Skip to content

fix mysql stuck on syncer.Close()#4195

Merged
jgao54 merged 4 commits into
mainfrom
mysql-ssh-hang
Apr 22, 2026
Merged

fix mysql stuck on syncer.Close()#4195
jgao54 merged 4 commits into
mainfrom
mysql-ssh-hang

Conversation

@jgao54

@jgao54 jgao54 commented Apr 18, 2026

Copy link
Copy Markdown
Contributor

When mysql connector is set up with ssh tunnel, there is a possible deadlock observed where the syncer is never closed and PullRecords hangs indefinitely.


  | 2026-04-10 23:09:01.794180854 | INFO | [mysql] PullRecords finished streaming |
 
  | 2026-04-10 23:09:01.794210647 | INFO | syncer is closing... |  
 
  | 2026-04-10 23:09:01.794213666 | WARN | could not set read deadline |  
 
  | 2026-04-10 23:09:01.835046706 | INFO | written records to OCF |
 
  | 2026-04-10 23:09:01.868201938 | ERROR | kill connection |  
 
  | 2026-04-10 23:09:01.868229754 | INFO | kill last connection |  
 
  | 2026-04-10 23:10:01.834992414 | INFO | written records to OCF | 
 
  | 2026-04-10 23:11:01.835059135 | INFO | written records to OCF | 
 
  | 2026-04-10 23:12:01.835527845 | INFO | written records to OCF | 
 
  | 2026-04-10 23:13:01.834876775 | INFO | written records to OCF | 
 
  | 2026-04-10 23:14:01.835584592 | INFO | written records to OCF | 
...

Notice the could not set read deadline warning, and the kill connection error, both coming from mysql binlogSyncer:

  • the could not set read deadline is failing with error message "ssh: tcpChan: deadline not supported"
  • the kill connection is failing with error message ""error":"ERROR 1094 (HY000): Unknown thread id: 743468""

What happened here is the library we are using for processing mysql replication, go-msyql, has a bug that can manifest if it's using SSH tunnel and if the thread is already reaped by the MySQL server. This let the syncer.Close() to hang indefinitely waiting because go-mysql thinks the connection is still alive (and the ssh tunneling connection very much is) so it gets stuck on wg.Wait() inside BinlogSyncer.close()

This is a different case than #4067, because SSH tunnel itself is healthy.

// Let CDC streaming establish before blocking the tunnel.
time.Sleep(2 * time.Second)

// Black-hole the SSH transport so syncer.Close() hangs

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If SSH is healthy in this case, should toxi be declared on top of MySQL?

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

that would be more direct, in this case was trying to reuse existing code for simplicity given what we are testing here is kind of trivial which is the watchdog works. maybe it's not worth a whole e2e test at all and better to test something abstract.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

let me do that.

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not sure the abstraction is needed here, given how short it is, and it comes with two callbacks. The scenario we want to test is being able to finish the batch when MySQL connection is down, and if the infra doesn't allow it, the infra needs to be better.

Better infra at #4207

@codecov

codecov Bot commented Apr 18, 2026

Copy link
Copy Markdown

❌ 2 Tests Failed:

Tests completed Failed Passed Skipped
2218 2 2216 201
View the top 2 failed test(s) by shortest run time
github.com/PeerDB-io/peerdb/flow/e2e::TestApiPg
Stack Traces | 0.01s run time
=== RUN   TestApiPg
=== PAUSE TestApiPg
=== CONT  TestApiPg
--- FAIL: TestApiPg (0.01s)
github.com/PeerDB-io/peerdb/flow/e2e::TestApiPg/TestTableAdditionWithoutInitialLoad
Stack Traces | 6.16s run time
=== RUN   TestApiPg/TestTableAdditionWithoutInitialLoad
=== PAUSE TestApiPg/TestTableAdditionWithoutInitialLoad
=== CONT  TestApiPg/TestTableAdditionWithoutInitialLoad
2026/04/18 01:37:32 INFO Received AWS credentials from peer for connector: ci x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2026/04/18 01:37:32 INFO Received AWS credentials from peer for connector: clickhouse x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
    api_test.go:2278: WaitFor wait for initial load to finish 2026-04-18 01:37:37.080944842 +0000 UTC m=+418.567093974
2026/04/18 01:37:37 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_v52qmfhn.\"original\" ORDER BY id"
2026/04/18 01:37:37 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_v52qmfhn.\"original\" ORDER BY id"
2026/04/18 01:37:37 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_3741182607888474081 CURSOR FOR SELECT id,val FROM e2e_test_api_v52qmfhn.\"original\" ORDER BY id" args=[]
2026/04/18 01:37:37 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_v52qmfhn.\"original\" ORDER BY id" channelLen=0
2026/04/18 01:37:37 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3741182607888474081
2026/04/18 01:37:37 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3741182607888474081 records=1 bytes=9 channelLen=0
2026/04/18 01:37:37 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_v52qmfhn.\"original\" ORDER BY id" rows=1 bytes=9 channelLen=0
2026/04/18 01:37:37 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3741182607888474081
2026/04/18 01:37:37 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3741182607888474081 records=0 bytes=0 channelLen=0
2026/04/18 01:37:37 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_v52qmfhn.\"original\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/18 01:37:37 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/18 01:37:37 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_v52qmfhn.\"original\" ORDER BY id" rows=1 bytes=9 channelLen=0
    api_test.go:2288: WaitFor wait for pause for add table 2026-04-18 01:37:37.101301388 +0000 UTC m=+418.587450510
2026/04/18 01:37:37 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_ehbwelc6.\"t1\" ORDER BY id"
2026/04/18 01:37:37 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_ehbwelc6.\"t1\" ORDER BY id"
2026/04/18 01:37:37 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_5614311967355466558 CURSOR FOR SELECT id,val FROM e2e_test_api_ehbwelc6.\"t1\" ORDER BY id" args=[]
2026/04/18 01:37:37 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_ehbwelc6.\"t1\" ORDER BY id" channelLen=0
2026/04/18 01:37:37 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_5614311967355466558
2026/04/18 01:37:37 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_5614311967355466558 records=2 bytes=19 channelLen=1
2026/04/18 01:37:37 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_ehbwelc6.\"t1\" ORDER BY id" rows=2 bytes=19 channelLen=1
2026/04/18 01:37:37 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_5614311967355466558
2026/04/18 01:37:37 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_5614311967355466558 records=0 bytes=0 channelLen=0
2026/04/18 01:37:37 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_ehbwelc6.\"t1\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/18 01:37:37 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/18 01:37:37 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_ehbwelc6.\"t1\" ORDER BY id" rows=2 bytes=19 channelLen=0
    api_test.go:2289: UNEXPECTED ERROR unable to establish connection with catalog: FATAL: terminating connection due to administrator command (SQLSTATE 57P01)
    api_test.go:48: begin tearing down postgres schema api_v52qmfhn
--- FAIL: TestApiPg/TestTableAdditionWithoutInitialLoad (6.16s)

To view more test analytics, go to the Test Analytics Dashboard
📋 Got 3 mins? Take this short survey to help us improve Test Analytics.

@github-actions

Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: TestMySQLCloseSyncerWithTimeout fails with "connection refused" on local port 42006 when setting up an SSH tunnel, a network/timing error consistent with a port conflict or race condition under high test parallelism (-p 32).
Confidence: 0.9

✅ Automatically retrying the workflow

View workflow run

@github-actions

Copy link
Copy Markdown
Contributor

❌ Test Failure

Analysis: New test TestMySQLCloseSyncerWithTimeout (added in this PR) consistently fails with connection refused on toxiproxy port 42006 across both matrix configurations, indicating a real bug in the test's SSH tunnel setup rather than a flaky environment issue.
Confidence: 0.85

⚠️ This appears to be a real bug - manual intervention needed

View workflow run

@jgao54 jgao54 marked this pull request as ready for review April 18, 2026 01:28
@github-actions

Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: TestCreateCDCFlowAttachIdempotentAfterContinueAsNew failed with a race-condition-style assertion ("1" is not greater than "1") — the async Temporal ContinueAsNew increment had not yet occurred when the check ran, in a test suite already running close to its 900s timeout.
Confidence: 0.88

✅ Automatically retrying the workflow

View workflow run

@github-actions

Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: The test failed due to PostgreSQL SQLSTATE 57P01 ("terminating connection due to administrator command"), an external infrastructure event that forcibly killed the catalog connection mid-test — not a code defect.
Confidence: 0.92

✅ Automatically retrying the workflow

View workflow run

Comment thread flow/connectors/mysql/cdc.go
Comment thread flow/connectors/mysql/cdc.go
@jgao54 jgao54 enabled auto-merge (squash) April 22, 2026 03:05
@jgao54 jgao54 merged commit 3a036db into main Apr 22, 2026
14 checks passed
@jgao54 jgao54 deleted the mysql-ssh-hang branch April 22, 2026 03:21
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants