Skip to content

Commit e490cee

Browse files
authored
dbi 604 handle replication slot creation getting stuck (#4439)
* Handle status terminating during resync-drop-flow. * Add user facing logs for waiting replication slot creation warning. * Streaming replication protocol doesn't support timeouts, so best we can do is user warning
1 parent 8514199 commit e490cee

9 files changed

Lines changed: 196 additions & 11 deletions

File tree

flow/activities/snapshot_activity.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -72,7 +72,7 @@ func (a *SnapshotActivity) SetupReplication(
7272
}
7373

7474
logger.Info("waiting for slot to be created...")
75-
slotInfo, err := conn.SetupReplication(ctx, config)
75+
slotInfo, err := conn.SetupReplication(ctx, a.CatalogPool, config)
7676

7777
if err != nil {
7878
connClose(ctx)

flow/connectors/bigquery/qrep_object_pull.go

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -507,6 +507,9 @@ func (c *BigQueryConnector) PullFlowCleanup(context.Context, string) error {
507507
return nil
508508
}
509509

510-
func (c *BigQueryConnector) SetupReplication(context.Context, *protos.SetupReplicationInput) (model.SetupReplicationResult, error) {
510+
func (c *BigQueryConnector) SetupReplication(
511+
context.Context, shared.CatalogPool,
512+
*protos.SetupReplicationInput,
513+
) (model.SetupReplicationResult, error) {
511514
return model.SetupReplicationResult{}, nil
512515
}

flow/connectors/core.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -110,7 +110,7 @@ type CDCPullConnectorCore interface {
110110
FinishExport(any) error
111111

112112
// Setup replication in prep for initial copy
113-
SetupReplication(context.Context, *protos.SetupReplicationInput) (model.SetupReplicationResult, error)
113+
SetupReplication(context.Context, shared.CatalogPool, *protos.SetupReplicationInput) (model.SetupReplicationResult, error)
114114

115115
// Methods related to retrieving and pushing records for this connector as a source and destination.
116116
SetupReplConn(context.Context, map[string]string) error

flow/connectors/mongo/cdc.go

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -97,7 +97,11 @@ func (c *MongoConnector) GetTableSchema(
9797
return result, nil
9898
}
9999

100-
func (c *MongoConnector) SetupReplication(ctx context.Context, input *protos.SetupReplicationInput) (model.SetupReplicationResult, error) {
100+
func (c *MongoConnector) SetupReplication(
101+
ctx context.Context,
102+
catalogPool shared.CatalogPool,
103+
input *protos.SetupReplicationInput,
104+
) (model.SetupReplicationResult, error) {
101105
changeStreamOpts := options.ChangeStream().
102106
SetComment("PeerDB changeStream").
103107
SetFullDocument(options.UpdateLookup)

flow/connectors/mysql/cdc.go

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -205,6 +205,7 @@ func (c *MySqlConnector) FinishExport(any) error {
205205

206206
func (c *MySqlConnector) SetupReplication(
207207
ctx context.Context,
208+
catalogPool shared.CatalogPool,
208209
req *protos.SetupReplicationInput,
209210
) (model.SetupReplicationResult, error) {
210211
var gtidModeOn bool

flow/connectors/postgres/postgres_source.go

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -758,6 +758,7 @@ func (c *PostgresConnector) FinishExport(tx any) error {
758758
// SetupReplication sets up replication for the source connector
759759
func (c *PostgresConnector) SetupReplication(
760760
ctx context.Context,
761+
catalogPool shared.CatalogPool,
761762
req *protos.SetupReplicationInput,
762763
) (model.SetupReplicationResult, error) {
763764
if !shared.IsValidReplicationName(req.FlowJobName) {
@@ -793,6 +794,27 @@ func (c *PostgresConnector) SetupReplication(
793794
Exclude: make(map[string]struct{}, 0),
794795
}
795796
}
797+
798+
// Add a user-facing warning if replication slot creation is taking a long time,
799+
// which is often caused by an open transaction blocking the creation.
800+
slotCreateStart := time.Now()
801+
stopSlotCreateWarning := common.Interval(ctx, 1*time.Minute, func() {
802+
elapsed := time.Since(slotCreateStart)
803+
if elapsed >= 1*time.Minute {
804+
msg := fmt.Sprintf(
805+
"Replication slot creation is taking very long (%s), possibly blocked by an open transaction."+
806+
" Run the following on the source to identify blockers:"+
807+
" SELECT pid, usename, application_name, state, now() - xact_start AS duration, query"+
808+
" FROM pg_stat_activity WHERE xact_start IS NOT NULL AND pid != pg_backend_pid() ORDER BY xact_start;",
809+
elapsed.Round(time.Second),
810+
)
811+
if err := alerting.InsertFlowLog(ctx, catalogPool, req.FlowJobName, msg, alerting.FlowErrorTypeWarn); err != nil {
812+
c.logger.Error("failed to insert slot creation warning", slog.Any("error", err))
813+
}
814+
}
815+
})
816+
defer stopSlotCreateWarning()
817+
796818
// Create the replication slot and publication
797819
return c.createSlotAndPublication(ctx, exists, slotName, publicationName, tableNameMapping,
798820
req.DoInitialSnapshot, skipSnapshotExport, req.Env)

flow/e2e/drop_flow_test.go

Lines changed: 101 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,101 @@
1+
package e2e
2+
3+
import (
4+
"fmt"
5+
"time"
6+
7+
"github.com/jackc/pgx/v5"
8+
"github.com/stretchr/testify/require"
9+
10+
"github.com/PeerDB-io/peerdb/flow/generated/protos"
11+
"github.com/PeerDB-io/peerdb/flow/internal"
12+
)
13+
14+
// TestTerminateDuringResyncDropFlow creates a pipe, resyncs it, then sends a TERMINATING
15+
// signal while the DropFlowWorkflow is blocked dropping the replication slot. An idle
16+
// open transaction on the source keeps the slot active (pg_drop_replication_slot blocks
17+
// while the slot's xmin cannot advance). Once the TERMINATING signal is queued, the
18+
// transaction is committed so the drop activity can finish — but the DropFlowWorkflow's
19+
// signal goroutine has already set TerminateSignal, so it does NOT ContinueAsNew back
20+
// to CDCFlowWorkflow and the pipe is fully torn down.
21+
func (s APITestSuite) TestTerminateDuringResyncDropFlow() {
22+
if _, ok := s.source.(*PostgresSource); !ok {
23+
s.t.Skip("only testing with PostgreSQL source")
24+
}
25+
26+
// Open a separate raw PG connection and start a transaction that will block
27+
// pg_drop_replication_slot during the resync drop flow.
28+
pgCfg := internal.GetAncillaryPostgresConfigFromEnv()
29+
blockConn, err := pgx.Connect(s.t.Context(), internal.GetPGConnectionString(pgCfg, ""))
30+
require.NoError(s.t, err)
31+
defer blockConn.Close(s.t.Context())
32+
33+
blockTx, err := blockConn.Begin(s.t.Context())
34+
require.NoError(s.t, err)
35+
// Acquire a transaction ID; keeping this transaction open prevents the replication
36+
// slot's xmin from advancing, causing pg_drop_replication_slot to block.
37+
var xid uint32
38+
require.NoError(s.t, blockTx.QueryRow(s.t.Context(), "SELECT txid_current()").Scan(&xid))
39+
s.t.Logf("blocking transaction XID: %d", xid)
40+
41+
tableName := "terminate_resync"
42+
require.NoError(s.t, s.source.Exec(s.t.Context(),
43+
fmt.Sprintf("CREATE TABLE %s(id int primary key, val text)", AttachSchema(s, tableName))))
44+
require.NoError(s.t, s.source.Exec(s.t.Context(),
45+
fmt.Sprintf("INSERT INTO %s(id, val) values (1,'first')", AttachSchema(s, tableName))))
46+
47+
connectionGen := FlowConnectionGenerationConfig{
48+
FlowJobName: "terminate_resync_" + s.suffix,
49+
TableNameMapping: map[string]string{AttachSchema(s, tableName): tableName},
50+
Destination: s.ch.Peer().Name,
51+
}
52+
flowConnConfig := connectionGen.GenerateFlowConnectionConfigs(s)
53+
flowConnConfig.DoInitialSnapshot = true
54+
55+
response, err := s.CreateCDCFlow(s.t.Context(), &protos.CreateCDCFlowRequest{ConnectionConfigs: flowConnConfig})
56+
require.NoError(s.t, err)
57+
require.NotNil(s.t, response)
58+
59+
tc := NewTemporalClient(s.t)
60+
env, err := GetPeerflow(s.t.Context(), s.catalog, tc, flowConnConfig.FlowJobName)
61+
require.NoError(s.t, err)
62+
63+
// Wait for STATUS_SNAPSHOT without using SetupCDCFlowStatusQuery, which would
64+
// t.Fatal after 60s if the flow stays in STATUS_SNAPSHOT. We query the catalog
65+
// directly so "not found yet" errors are silently skipped.
66+
EnvWaitFor(s.t, env, 3*time.Minute, "wait for initial snapshot to start", func() bool {
67+
status, err := internal.GetWorkflowStatus(s.t.Context(), s.catalog, env.GetID())
68+
return err == nil && status == protos.FlowStatus_STATUS_SNAPSHOT
69+
})
70+
71+
// Trigger resync: CDC flow ContinueAsNew → DropFlowWorkflow(Resync=true).
72+
// The drop flow will block on pg_drop_replication_slot because of the open transaction.
73+
_, err = s.FlowStateChange(s.t.Context(), &protos.FlowStateChangeRequest{
74+
FlowJobName: flowConnConfig.FlowJobName,
75+
RequestedFlowState: protos.FlowStatus_STATUS_RESYNC,
76+
})
77+
require.NoError(s.t, err)
78+
79+
// Wait until DropFlowWorkflow has started (catalog status = RESYNC).
80+
// Use direct catalog query so transient "not found" errors during ContinueAsNew
81+
// handoff are silently skipped rather than failing the test.
82+
EnvWaitFor(s.t, env, 3*time.Minute, "wait for resync drop flow to start", func() bool {
83+
status, err := internal.GetWorkflowStatus(s.t.Context(), s.catalog, env.GetID())
84+
return err == nil && status == protos.FlowStatus_STATUS_RESYNC
85+
})
86+
87+
// While the drop flow is blocked on the slot drop, send TERMINATING.
88+
// The signal goroutine inside DropFlowWorkflow catches this and sets
89+
// activeSignal = TerminateSignal, preventing ContinueAsNew after drop completes.
90+
_, err = s.FlowStateChange(s.t.Context(), &protos.FlowStateChangeRequest{
91+
FlowJobName: flowConnConfig.FlowJobName,
92+
RequestedFlowState: protos.FlowStatus_STATUS_TERMINATING,
93+
})
94+
// Release the blocker — the drop activity can now finish.
95+
require.NoError(s.t, blockTx.Rollback(s.t.Context()))
96+
97+
require.NoError(s.t, err)
98+
99+
// The flow must be fully removed from the catalog, not restarted as a new CDC run.
100+
s.waitForFlowDropped(env, flowConnConfig.FlowJobName)
101+
}

flow/e2e/postgres_qrep_test.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -154,7 +154,7 @@ func (s PeerFlowE2ETestSuitePG) TestSimpleSlotCreation() {
154154
}
155155

156156
s.t.Log("waiting for slot creation to complete: " + flowJobName)
157-
slotInfo, err := s.conn.SetupReplication(s.t.Context(), setupReplicationInput)
157+
slotInfo, err := s.conn.SetupReplication(s.t.Context(), shared.CatalogPool{}, setupReplicationInput)
158158
require.NoError(s.t, err)
159159

160160
s.t.Logf("slot creation complete: %v", slotInfo)

flow/workflows/drop_flow.go

Lines changed: 60 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -112,7 +112,7 @@ func executeCDCDropActivities(ctx workflow.Context, input *protos.DropFlowInput)
112112
if canceled {
113113
if input.Resync {
114114
if err := errors.Join(ctx.Err(), sourceError, destinationError); err != nil {
115-
logger.Warn("resync failed drop, proceeding with cdc flow", slog.Any("error", err))
115+
logger.Warn("resync failed drop, proceeding with cleanup", slog.Any("error", err))
116116
}
117117
break
118118
}
@@ -124,25 +124,64 @@ func executeCDCDropActivities(ctx workflow.Context, input *protos.DropFlowInput)
124124
}
125125

126126
func DropFlowWorkflow(ctx workflow.Context, input *protos.DropFlowInput) error {
127+
activeSignal := model.NoopSignal
128+
if input.Resync {
129+
activeSignal = model.ResyncSignal
130+
} else {
131+
activeSignal = model.TerminateSignal
132+
}
133+
127134
if err := workflow.SetQueryHandler(ctx, shared.CDCFlowStateQuery, func() (cdc_state.CDCFlowWorkflowState, error) {
128135
state := cdc_state.CDCFlowWorkflowState{DropFlowInput: input}
129136
if input.Resync {
130137
state.CurrentFlowStatus = protos.FlowStatus_STATUS_RESYNC
131-
state.ActiveSignal = model.ResyncSignal
138+
state.ActiveSignal = activeSignal
132139
} else {
133140
state.CurrentFlowStatus = protos.FlowStatus_STATUS_TERMINATING
134-
state.ActiveSignal = model.TerminateSignal
141+
state.ActiveSignal = activeSignal
135142
}
136143
return state, nil
137144
}); err != nil {
138145
return fmt.Errorf("failed to set `%s` query handler: %w", shared.CDCFlowStateQuery, err)
139146
}
140147

148+
logger := workflow.GetLogger(ctx)
149+
150+
finalDrop := false
151+
if input.Resync {
152+
flowSignalChan := model.FlowSignal.GetSignalChannel(ctx)
153+
flowSignalStateChangeChan := model.FlowSignalStateChange.GetSignalChannel(ctx)
154+
workflow.Go(ctx, func(gCtx workflow.Context) {
155+
sigSelector := workflow.NewNamedSelector(gCtx, input.FlowJobName+"-drop-signals")
156+
sigSelector.AddReceive(gCtx.Done(), func(_ workflow.ReceiveChannel, _ bool) {})
157+
158+
flowSignalChan.AddToSelector(sigSelector, func(val model.CDCFlowSignal, _ bool) {
159+
prev := activeSignal
160+
activeSignal = model.FlowSignalHandler(activeSignal, val, logger)
161+
if prev != model.TerminateSignal && activeSignal == model.TerminateSignal {
162+
finalDrop = true
163+
}
164+
})
165+
166+
flowSignalStateChangeChan.AddToSelector(sigSelector, func(req *protos.FlowStateChangeRequest, _ bool) {
167+
if req.RequestedFlowState == protos.FlowStatus_STATUS_TERMINATING {
168+
activeSignal = model.TerminateSignal
169+
input.DropFlowStats = req.DropMirrorStats
170+
input.SkipDestinationDrop = req.SkipDestinationDrop
171+
finalDrop = true
172+
}
173+
})
174+
175+
for gCtx.Err() == nil {
176+
sigSelector.Select(gCtx)
177+
}
178+
})
179+
}
180+
141181
status := protos.FlowStatus_STATUS_TERMINATING
142182
if input.Resync {
143183
status = protos.FlowStatus_STATUS_RESYNC
144184
}
145-
logger := workflow.GetLogger(ctx)
146185
cdc_state.SyncStatusToCatalogWithFlowName(ctx, logger, status, input.FlowJobName)
147186

148187
ctx = workflow.WithValue(ctx, shared.FlowNameKey, input.FlowJobName)
@@ -205,7 +244,7 @@ func DropFlowWorkflow(ctx workflow.Context, input *protos.DropFlowInput) error {
205244

206245
req := model.RemoveFlowDetailsFromCatalogRequest{
207246
FlowName: input.FlowJobName,
208-
Resync: input.Resync,
247+
Resync: input.Resync && activeSignal != model.TerminateSignal,
209248
}
210249
if err := workflow.ExecuteActivity(
211250
removeFlowEntriesCtx, flowable.RemoveFlowDetailsFromCatalog, &req,
@@ -214,7 +253,22 @@ func DropFlowWorkflow(ctx workflow.Context, input *protos.DropFlowInput) error {
214253
return err
215254
}
216255

217-
if input.Resync {
256+
// If a terminate signal arrived during RemoveFlowDetailsFromCatalog while it ran
257+
// in resync mode, the catalog row was left as RESYNC — do a final cleanup now.
258+
if finalDrop && req.Resync {
259+
finalReq := model.RemoveFlowDetailsFromCatalogRequest{
260+
FlowName: input.FlowJobName,
261+
Resync: false,
262+
}
263+
if err := workflow.ExecuteActivity(
264+
removeFlowEntriesCtx, flowable.RemoveFlowDetailsFromCatalog, &finalReq,
265+
).Get(ctx, nil); err != nil {
266+
workflow.GetLogger(ctx).Error("failed to remove flow details from catalog (final drop)", slog.Any("error", err))
267+
return err
268+
}
269+
}
270+
271+
if input.Resync && activeSignal != model.TerminateSignal {
218272
return workflow.NewContinueAsNewError(ctx, CDCFlowWorkflow, input.FlowConnectionConfigs, nil)
219273
}
220274

0 commit comments

Comments
 (0)