Skip to content

Fix MySQL CDC hang when SSH tunnel dies#4067

Merged
ilidemi merged 9 commits intomainfrom
customer-mysql-cdc-keepalive
Apr 15, 2026
Merged

Fix MySQL CDC hang when SSH tunnel dies#4067
ilidemi merged 9 commits intomainfrom
customer-mysql-cdc-keepalive

Conversation

@ilidemi
Copy link
Copy Markdown
Contributor

@ilidemi ilidemi commented Mar 18, 2026

When SSH connection dies during CDC, the keepalive machinery notices but BinlogSyncer is not aware. To make it aware, close SSH connection besides just the MySQL query connection. Add tests for hangs in mystream.GetEvent() and syncer.Close() (both observed in production). Verified that without the fix both tests fail.

@codecov
Copy link
Copy Markdown

codecov bot commented Mar 18, 2026

❌ 2 Tests Failed:

Tests completed Failed Passed Skipped
2201 2 2199 202
View the top 3 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)
2026/04/15 05:30:18 INFO Received AWS credentials from peer for connector: ci x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2026/04/15 05:30:18 INFO Received AWS credentials from peer for connector: clickhouse x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2026/04/15 05:30:18 INFO fetched schema x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} table=e2e_test_mychcl_acybcdbx.test_nullengine
github.com/PeerDB-io/peerdb/flow/e2e::TestApiPg/TestDoubleClickCancelTableAddition
Stack Traces | 7.22s run time
=== RUN   TestApiPg/TestDoubleClickCancelTableAddition
=== PAUSE TestApiPg/TestDoubleClickCancelTableAddition
=== CONT  TestApiPg/TestDoubleClickCancelTableAddition
2026/04/15 05:13:27 INFO Received AWS credentials from peer for connector: ci x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2026/04/15 05:13:27 INFO Received AWS credentials from peer for connector: clickhouse x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2026/04/15 05:13:27 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_gnyctilf.\"status_test\" ORDER BY id"
2026/04/15 05:13:27 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_gnyctilf.\"status_test\" ORDER BY id"
2026/04/15 05:13:27 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_13505577483592159370 CURSOR FOR SELECT id,val FROM e2e_test_api_gnyctilf.\"status_test\" ORDER BY id" args=[]
2026/04/15 05:13:27 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_gnyctilf.\"status_test\" ORDER BY id" channelLen=0
2026/04/15 05:13:27 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13505577483592159370
2026/04/15 05:13:27 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13505577483592159370 records=1 bytes=9 channelLen=0
2026/04/15 05:13:27 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_gnyctilf.\"status_test\" ORDER BY id" rows=1 bytes=9 channelLen=0
2026/04/15 05:13:27 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13505577483592159370
2026/04/15 05:13:27 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13505577483592159370 records=0 bytes=0 channelLen=0
2026/04/15 05:13:27 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_gnyctilf.\"status_test\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 05:13:27 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 05:13:27 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_gnyctilf.\"status_test\" ORDER BY id" rows=1 bytes=9 channelLen=0
    cancel_table_addition_test.go:1368: WaitFor wait for initial load to finish 2026-04-15 05:13:32.026520923 +0000 UTC m=+648.378478494
2026/04/15 05:13:32 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_f172oqrx.\"t1\" ORDER BY id"
2026/04/15 05:13:32 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_f172oqrx.\"t1\" ORDER BY id"
2026/04/15 05:13:32 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_9281946710710861407 CURSOR FOR SELECT id,val FROM e2e_test_api_f172oqrx.\"t1\" ORDER BY id" args=[]
2026/04/15 05:13:32 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_f172oqrx.\"t1\" ORDER BY id" channelLen=0
2026/04/15 05:13:32 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_9281946710710861407
2026/04/15 05:13:32 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_9281946710710861407 records=1 bytes=9 channelLen=0
2026/04/15 05:13:32 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_f172oqrx.\"t1\" ORDER BY id" rows=1 bytes=9 channelLen=0
2026/04/15 05:13:32 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_9281946710710861407
2026/04/15 05:13:32 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_9281946710710861407 records=0 bytes=0 channelLen=0
2026/04/15 05:13:32 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_f172oqrx.\"t1\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 05:13:32 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 05:13:32 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_f172oqrx.\"t1\" ORDER BY id" rows=1 bytes=9 channelLen=0
    cancel_table_addition_test.go:1379: WaitFor wait for pause 2026-04-15 05:13:32.046302179 +0000 UTC m=+648.398259750
2026/04/15 05:13:32 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_mzyifluh.\"table1\" ORDER BY id"
2026/04/15 05:13:32 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_mzyifluh.\"table1\" ORDER BY id"
2026/04/15 05:13:32 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_11783922799475411940 CURSOR FOR SELECT id,val FROM e2e_test_api_mzyifluh.\"table1\" ORDER BY id" args=[]
2026/04/15 05:13:32 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_mzyifluh.\"table1\" ORDER BY id" channelLen=0
2026/04/15 05:13:32 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_11783922799475411940
2026/04/15 05:13:32 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_11783922799475411940 records=2 bytes=19 channelLen=1
2026/04/15 05:13:32 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_mzyifluh.\"table1\" ORDER BY id" rows=2 bytes=19 channelLen=1
2026/04/15 05:13:32 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_11783922799475411940
2026/04/15 05:13:32 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_11783922799475411940 records=0 bytes=0 channelLen=0
2026/04/15 05:13:32 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_mzyifluh.\"table1\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 05:13:32 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 05:13:32 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_mzyifluh.\"table1\" ORDER BY id" rows=2 bytes=19 channelLen=0
    cancel_table_addition_test.go:1433: WaitFor wait for snapshot status 2026-04-15 05:13:34.069503857 +0000 UTC m=+650.421461428
2026/04/15 05:13:34 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_mzyifluh.\"table1\" ORDER BY id"
2026/04/15 05:13:34 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_mzyifluh.\"table1\" ORDER BY id"
2026/04/15 05:13:34 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_12553240109738711939 CURSOR FOR SELECT id,val FROM e2e_test_api_mzyifluh.\"table1\" ORDER BY id" args=[]
2026/04/15 05:13:34 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_mzyifluh.\"table1\" ORDER BY id" channelLen=0
2026/04/15 05:13:34 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12553240109738711939
2026/04/15 05:13:34 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12553240109738711939 records=2 bytes=19 channelLen=1
2026/04/15 05:13:34 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_mzyifluh.\"table1\" ORDER BY id" rows=2 bytes=19 channelLen=1
2026/04/15 05:13:34 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12553240109738711939
2026/04/15 05:13:34 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12553240109738711939 records=0 bytes=0 channelLen=0
2026/04/15 05:13:34 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_mzyifluh.\"table1\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 05:13:34 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 05:13:34 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_mzyifluh.\"table1\" ORDER BY id" rows=2 bytes=19 channelLen=0
    cancel_table_addition_test.go:1434: UNEXPECTED ERROR unable to establish connection with catalog: FATAL: terminating connection due to administrator command (SQLSTATE 57P01)
    cancel_table_addition_test.go:1310: begin tearing down postgres schema double_cancel_api_f172oqrx
    api_test.go:48: begin tearing down postgres schema api_f172oqrx
--- FAIL: TestApiPg/TestDoubleClickCancelTableAddition (7.22s)
github.com/PeerDB-io/peerdb/flow/e2e::TestApiPg/TestCancelTableAdditionRemoveAddRemove
Stack Traces | 24.2s run time
=== RUN   TestApiPg/TestCancelTableAdditionRemoveAddRemove
=== PAUSE TestApiPg/TestCancelTableAdditionRemoveAddRemove
=== CONT  TestApiPg/TestCancelTableAdditionRemoveAddRemove
2026/04/15 04:43:00 INFO Received AWS credentials from peer for connector: ci x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2026/04/15 04:43:00 INFO Received AWS credentials from peer for connector: clickhouse x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2026/04/15 04:43:00 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id"
2026/04/15 04:43:00 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id"
2026/04/15 04:43:00 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_17898745623484676073 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id" args=[]
2026/04/15 04:43:00 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id" channelLen=0
2026/04/15 04:43:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17898745623484676073
2026/04/15 04:43:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17898745623484676073 records=8 bytes=168 channelLen=7
2026/04/15 04:43:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id" rows=8 bytes=168 channelLen=7
2026/04/15 04:43:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17898745623484676073
2026/04/15 04:43:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17898745623484676073 records=0 bytes=0 channelLen=0
2026/04/15 04:43:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 04:43:00 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 04:43:00 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id" rows=8 bytes=168 channelLen=0
2026/04/15 04:43:00 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,key,value,created_at,extra FROM e2e_test_pgchg_10owm8ou.\"test_partition_reorder\" ORDER BY id"
2026/04/15 04:43:00 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,key,value,created_at,extra FROM e2e_test_pgchg_10owm8ou.\"test_partition_reorder\" ORDER BY id"
2026/04/15 04:43:00 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_17965996068650993242 CURSOR FOR SELECT id,key,value,created_at,extra FROM e2e_test_pgchg_10owm8ou.\"test_partition_reorder\" ORDER BY id" args=[]
2026/04/15 04:43:00 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,key,value,created_at,extra FROM e2e_test_pgchg_10owm8ou.\"test_partition_reorder\" ORDER BY id" channelLen=0
2026/04/15 04:43:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17965996068650993242
2026/04/15 04:43:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17965996068650993242 records=11 bytes=195 channelLen=10
2026/04/15 04:43:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,key,value,created_at,extra FROM e2e_test_pgchg_10owm8ou.\"test_partition_reorder\" ORDER BY id" rows=11 bytes=195 channelLen=10
2026/04/15 04:43:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17965996068650993242
2026/04/15 04:43:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17965996068650993242 records=0 bytes=0 channelLen=0
2026/04/15 04:43:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,key,value,created_at,extra FROM e2e_test_pgchg_10owm8ou.\"test_partition_reorder\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 04:43:00 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 04:43:00 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,key,value,created_at,extra FROM e2e_test_pgchg_10owm8ou.\"test_partition_reorder\" ORDER BY id" rows=11 bytes=195 channelLen=0
    cancel_table_addition_test.go:637: WaitFor wait for initial load to finish 2026-04-15 04:43:06.617260083 +0000 UTC m=+63.622271776
    cancel_table_addition_test.go:641: WaitFor t1 2026-04-15 04:43:06.617650352 +0000 UTC m=+63.622662046
2026/04/15 04:43:06 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_vbcudxhj.\"t1\" ORDER BY id"
2026/04/15 04:43:06 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_vbcudxhj.\"t1\" ORDER BY id"
2026/04/15 04:43:06 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_12653979747615255224 CURSOR FOR SELECT id,val FROM e2e_test_api_vbcudxhj.\"t1\" ORDER BY id" args=[]
2026/04/15 04:43:06 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_vbcudxhj.\"t1\" ORDER BY id" channelLen=0
2026/04/15 04:43:06 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12653979747615255224
2026/04/15 04:43:06 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12653979747615255224 records=1 bytes=9 channelLen=0
2026/04/15 04:43:06 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_vbcudxhj.\"t1\" ORDER BY id" rows=1 bytes=9 channelLen=0
2026/04/15 04:43:06 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12653979747615255224
2026/04/15 04:43:06 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12653979747615255224 records=0 bytes=0 channelLen=0
2026/04/15 04:43:06 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_vbcudxhj.\"t1\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 04:43:06 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 04:43:06 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_vbcudxhj.\"t1\" ORDER BY id" rows=1 bytes=9 channelLen=0
    cancel_table_addition_test.go:642: WaitFor t2 2026-04-15 04:43:06.629021851 +0000 UTC m=+63.634033545
2026/04/15 04:43:06 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_vbcudxhj.\"t2\" ORDER BY id"
2026/04/15 04:43:06 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_vbcudxhj.\"t2\" ORDER BY id"
2026/04/15 04:43:06 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_3226323452682277019 CURSOR FOR SELECT id,val FROM e2e_test_api_vbcudxhj.\"t2\" ORDER BY id" args=[]
2026/04/15 04:43:06 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_vbcudxhj.\"t2\" ORDER BY id" channelLen=0
2026/04/15 04:43:06 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3226323452682277019
2026/04/15 04:43:06 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3226323452682277019 records=1 bytes=9 channelLen=0
2026/04/15 04:43:06 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_vbcudxhj.\"t2\" ORDER BY id" rows=1 bytes=9 channelLen=0
2026/04/15 04:43:06 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3226323452682277019
2026/04/15 04:43:06 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3226323452682277019 records=0 bytes=0 channelLen=0
2026/04/15 04:43:06 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_vbcudxhj.\"t2\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 04:43:06 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 04:43:06 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_vbcudxhj.\"t2\" ORDER BY id" rows=1 bytes=9 channelLen=0
    cancel_table_addition_test.go:82: WaitFor wait for pause for remove e2e_test_api_vbcudxhj.t2 2026-04-15 04:43:06.6372637 +0000 UTC m=+63.642275394
2026/04/15 04:43:06 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id"
2026/04/15 04:43:06 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id"
2026/04/15 04:43:07 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_13895384077997264239 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id" args=[]
2026/04/15 04:43:07 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id" channelLen=0
2026/04/15 04:43:07 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13895384077997264239
2026/04/15 04:43:07 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13895384077997264239 records=13 bytes=293 channelLen=12
2026/04/15 04:43:07 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id" rows=13 bytes=293 channelLen=12
2026/04/15 04:43:07 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13895384077997264239
2026/04/15 04:43:07 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13895384077997264239 records=0 bytes=0 channelLen=0
2026/04/15 04:43:07 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 04:43:07 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 04:43:07 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id" rows=13 bytes=293 channelLen=0
    cancel_table_addition_test.go:100: WaitFor wait for table removal of source_table_identifier:"e2e_test_api_vbcudxhj.t2"  destination_table_identifier:"t2" to finish 2026-04-15 04:43:08.644339178 +0000 UTC m=+65.649350872
2026/04/15 04:43:09 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id"
2026/04/15 04:43:09 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id"
2026/04/15 04:43:09 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_14518929139452474091 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id" args=[]
2026/04/15 04:43:09 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id" channelLen=0
2026/04/15 04:43:09 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_14518929139452474091
2026/04/15 04:43:09 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_14518929139452474091 records=13 bytes=293 channelLen=12
2026/04/15 04:43:09 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id" rows=13 bytes=293 channelLen=12
2026/04/15 04:43:09 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_14518929139452474091
2026/04/15 04:43:09 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_14518929139452474091 records=0 bytes=0 channelLen=0
2026/04/15 04:43:09 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 04:43:09 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 04:43:09 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_zbf0mxkn.\"test_partition_noroot\" ORDER BY id" rows=13 bytes=293 channelLen=0
    cancel_table_addition_test.go:127: WaitFor wait for pause for add e2e_test_api_vbcudxhj.t2 2026-04-15 04:43:09.650486373 +0000 UTC m=+66.655498067
2026/04/15 04:43:09 INFO queued schema delta update x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} flowName=test_cancel_error_on_pg_zero_oids_api_mdjmeb4m tableName=t1
    cancel_table_addition_test.go:128: 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_vbcudxhj
2026/04/15 04:43:18 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id"
2026/04/15 04:43:18 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id"
2026/04/15 04:43:18 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_7108006854694374696 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id" args=[]
2026/04/15 04:43:18 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id" channelLen=0
2026/04/15 04:43:18 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_7108006854694374696
2026/04/15 04:43:18 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_7108006854694374696 records=8 bytes=168 channelLen=7
2026/04/15 04:43:18 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id" rows=8 bytes=168 channelLen=7
2026/04/15 04:43:18 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_7108006854694374696
2026/04/15 04:43:18 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_7108006854694374696 records=0 bytes=0 channelLen=0
2026/04/15 04:43:18 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 04:43:18 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 04:43:18 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pgchg_0n28enuy.\"test_inheritance_dynconf\" ORDER BY id" rows=8 bytes=168 channelLen=0
--- FAIL: TestApiPg/TestCancelTableAdditionRemoveAddRemove (24.19s)
github.com/PeerDB-io/peerdb/flow/e2e::TestApiPg/TestQRep
Stack Traces | 63.3s run time
=== RUN   TestApiPg/TestQRep
=== PAUSE TestApiPg/TestQRep
=== CONT  TestApiPg/TestQRep
2026/04/15 05:28:28 ERROR Failed to get catalog connection pool x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} error="unable to establish connection with catalog: FATAL: terminating connection due to administrator command (SQLSTATE 57P01)"
2026/04/15 05:28:28 ERROR Failed to parse bool x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} key=PEERDB_APPLICATION_NAME_PER_MIRROR_NAME error="failed to get catalog connection pool: unable to establish connection with catalog: FATAL: terminating connection due to administrator command (SQLSTATE 57P01)"
2026/04/15 05:28:28 ERROR Failed to get flow name from application name x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} error="failed to parse PEERDB_APPLICATION_NAME_PER_MIRROR_NAME as bool: failed to get catalog connection pool: unable to establish connection with catalog: FATAL: terminating connection due to administrator command (SQLSTATE 57P01)"
2026/04/15 05:28:28 INFO Received AWS credentials from peer for connector: ci x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2026/04/15 05:28:28 INFO Received AWS credentials from peer for connector: clickhouse x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
    api_test.go:2155: WaitFor qrep initial load 2026-04-15 05:28:28.67574547 +0000 UTC m=+466.845875113
2026/04/15 05:28:28 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id"
2026/04/15 05:28:28 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id"
2026/04/15 05:28:28 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_10487116848847890044 CURSOR FOR SELECT id,val FROM e2e_test_api_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id" args=[]
2026/04/15 05:28:28 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_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id" channelLen=0
2026/04/15 05:28:28 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10487116848847890044
2026/04/15 05:28:28 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10487116848847890044 records=1 bytes=9 channelLen=0
2026/04/15 05:28:28 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id" rows=1 bytes=9 channelLen=0
2026/04/15 05:28:28 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10487116848847890044
2026/04/15 05:28:28 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10487116848847890044 records=0 bytes=0 channelLen=0
2026/04/15 05:28:28 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 05:28:28 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 05:28:28 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_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id" rows=1 bytes=9 channelLen=0
    api_test.go:2155: q.NumRecords: 1
    api_test.go:2155: other.NumRecords: 0
    api_test.go:2160: WaitFor insert post qrep initial load 2026-04-15 05:28:29.696578189 +0000 UTC m=+467.866707832
2026/04/15 05:28:29 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id"
2026/04/15 05:28:29 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id"
2026/04/15 05:28:29 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_8549906725005653647 CURSOR FOR SELECT id,val FROM e2e_test_api_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id" args=[]
2026/04/15 05:28:29 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_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id" channelLen=0
2026/04/15 05:28:29 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_8549906725005653647
2026/04/15 05:28:29 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_8549906725005653647 records=2 bytes=19 channelLen=1
2026/04/15 05:28:29 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id" rows=2 bytes=19 channelLen=1
2026/04/15 05:28:29 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_8549906725005653647
2026/04/15 05:28:29 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_8549906725005653647 records=0 bytes=0 channelLen=0
2026/04/15 05:28:29 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 05:28:29 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 05:28:29 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_xoshqhqv.\"qrepapi_api_xoshqhqv\" ORDER BY id" rows=2 bytes=19 channelLen=0
    api_test.go:2160: q.NumRecords: 2
    api_test.go:2160: other.NumRecords: 1
2026/04/15 05:28:30 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id"
2026/04/15 05:28:30 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id"
2026/04/15 05:28:30 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_18079940840446288248 CURSOR FOR SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" args=[]
2026/04/15 05:28:30 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" channelLen=0
2026/04/15 05:28:30 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_18079940840446288248
2026/04/15 05:28:30 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_18079940840446288248 records=3 bytes=26 channelLen=2
2026/04/15 05:28:30 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" rows=3 bytes=26 channelLen=2
2026/04/15 05:28:30 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_18079940840446288248
2026/04/15 05:28:30 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_18079940840446288248 records=0 bytes=0 channelLen=0
2026/04/15 05:28:30 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 05:28:30 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 05:28:30 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" rows=3 bytes=26 channelLen=0
    api_test.go:2160: q.NumRecords: 2
    api_test.go:2160: other.NumRecords: 1
2026/04/15 05:28:31 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id"
2026/04/15 05:28:31 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id"
2026/04/15 05:28:31 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_10705625463778821892 CURSOR FOR SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" args=[]
2026/04/15 05:28:31 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" channelLen=0
2026/04/15 05:28:31 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10705625463778821892
2026/04/15 05:28:31 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10705625463778821892 records=3 bytes=26 channelLen=2
2026/04/15 05:28:31 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" rows=3 bytes=26 channelLen=2
2026/04/15 05:28:31 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10705625463778821892
2026/04/15 05:28:31 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10705625463778821892 records=0 bytes=0 channelLen=0
2026/04/15 05:28:31 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 05:28:31 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 05:28:31 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" rows=3 bytes=26 channelLen=0
    api_test.go:2179: WaitFor finish 2026-04-15 05:28:31.719688669 +0000 UTC m=+469.889818302
2026/04/15 05:28:32 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id"
2026/04/15 05:28:32 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id"
2026/04/15 05:28:32 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_8850716316024745832 CURSOR FOR SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" args=[]
2026/04/15 05:28:32 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" channelLen=0
2026/04/15 05:28:32 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_8850716316024745832
2026/04/15 05:28:32 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_8850716316024745832 records=3 bytes=26 channelLen=2
2026/04/15 05:28:32 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" rows=3 bytes=26 channelLen=2
2026/04/15 05:28:32 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_8850716316024745832
2026/04/15 05:28:32 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_8850716316024745832 records=0 bytes=0 channelLen=0
2026/04/15 05:28:32 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" rows=0 bytes=0 channelLen=0
2026/04/15 05:28:32 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2026/04/15 05:28:32 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_xxyo3dxh.\"test_nullengine\" ORDER BY id" rows=3 bytes=26 channelLen=0
    api_test.go:2179: UNEXPECTED TIMEOUT finish 2026-04-15 05:29:31.848825918 +0000 UTC m=+530.018955561
    api_test.go:48: begin tearing down postgres schema api_xoshqhqv
--- FAIL: TestApiPg/TestQRep (63.32s)

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: The test failed due to "context deadline exceeded" when connecting to the Temporal server — a transient infrastructure/network timeout, not a code logic failure.
Confidence: 0.95

✅ Automatically retrying the workflow

View workflow run

@github-actions
Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: Multiple Snowflake e2e tests failed with "UNEXPECTED STATUS TIMEOUT STATUS_SETUP", indicating transient connectivity/availability issues with the external Snowflake service during flow initialization, unrelated to the partitioned table column-ordering code change.
Confidence: 0.92

✅ Automatically retrying the workflow

View workflow run

@github-actions
Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: The e2e test TestGenericBQ/Test_Inheritance_Table_With_Dynamic_Setting timed out during the STATUS_SNAPSHOT phase, which is a classic flaky failure caused by timing-sensitive infrastructure (Temporal/snapshot workflow) rather than a code regression.
Confidence: 0.92

✅ Automatically retrying the workflow

View workflow run

@ilidemi
Copy link
Copy Markdown
Contributor Author

ilidemi commented Mar 25, 2026

Current status:

  1. The issue we were looking at in production doesn't seem to be SSH issue
  2. The tests show that it should be an additive improvement reliability wise
  3. There was some weirdness in logs with keepalive errors completely disappearing that we'd need another repro to witness this code working, so will keep as draft until then

@ilidemi
Copy link
Copy Markdown
Contributor Author

ilidemi commented Apr 10, 2026

Double checked logs in a local e2e test, looks as expected. Should be good to go

@ilidemi ilidemi marked this pull request as ready for review April 10, 2026 03:17
@ilidemi ilidemi requested a review from jgao54 April 10, 2026 03:17
@github-actions
Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: The e2e test suite hit the 900-second timeout deadline (FAIL github.com/PeerDB-io/peerdb/flow/e2e 900.680s), indicating a flaky timeout rather than a deterministic test assertion failure.
Confidence: 0.9

✅ Automatically retrying the workflow

View workflow run

@github-actions
Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: All three failures are timing/resource-related (setup timeouts, teardown failures, wait-for-load timeouts) with no logic assertion errors, occurring across unrelated matrix jobs on the same commit — classic CI flakiness.
Confidence: 0.9

✅ Automatically retrying the workflow

View workflow run

@github-actions
Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: The test e2e TestApiPg/TestResyncCompleted failed due to a transient PostgreSQL connection drop (SQLSTATE 57P01: admin_shutdown — catalog connection terminated by administrator command), which is an infrastructure/environment issue unrelated to the test logic.
Confidence: 0.95

✅ Automatically retrying the workflow

View workflow run

// the keepalive fires, something else closed the connection (driver timeout, etc.)
select {
case <-keepaliveChan:
t.Log("SSH keepalive detected failure")
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.

It looks like the prod keeepaliveInterval is set to 15s, is my understanding correct that this would take that much time to detect failure? if so, it may be worth setting a shorter interval for test.

I noticed that with the introduction of these two tests, mysql tests now takes 120s (was 60s previously)

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.

Added t.Parallel() which brought it to 30. Overriding the keepalive interval got hairier than I'd prefer with the current code structure, and 30 is in line with other suites.

Comment thread flow/connectors/mysql/ssh_keepalive_test.go
@ilidemi ilidemi enabled auto-merge (squash) April 15, 2026 04:39
@github-actions
Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: TestCancelTableAdditionRemoveAddRemove failed due to a catalog connection being terminated (SQLSTATE 57P01/admin_shutdown), likely caused by the concurrently-running TestCancelErrorOnPgZeroOids test calling pg_terminate_backend() as part of its error-scenario testing while both tests share the same PostgreSQL catalog under -p 32 parallelism.
Confidence: 0.88

✅ Automatically retrying the workflow

View workflow run

@github-actions
Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: TestApiPg/TestDoubleClickCancelTableAddition failed due to a PostgreSQL catalog connection being terminated by an admin command (SQLSTATE 57P01) mid-test — a transient infrastructure event, not a code bug.
Confidence: 0.93

✅ Automatically retrying the workflow

View workflow run

@github-actions
Copy link
Copy Markdown
Contributor

🔄 Flaky Test Detected

Analysis: e2e TestApiPg/TestQRep timed out after the catalog PostgreSQL connection was killed mid-test with SQLSTATE 57P01 (admin_shutdown), a transient infrastructure failure caused by resource contention from 32 parallel tests.
Confidence: 0.92

✅ Automatically retrying the workflow

View workflow run

@ilidemi ilidemi merged commit 3ecdad2 into main Apr 15, 2026
25 of 28 checks passed
@ilidemi ilidemi deleted the customer-mysql-cdc-keepalive branch April 15, 2026 05:50
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