peerdb
peerdb copied to clipboard
PeerDB-io
Spew full structure for all flow_errors
Another attempt as CI keeps getting canceled on #3607
Chasing DB errors is getting ridiculous lately, adding spew logging that looks like this:
(*utils.connectionError)({
message: (string) (len=25) "connection pool exhausted",
wrapped: (*connpostgres.queryExecutionError)({
query: (string) (len=33) "SELECT * FROM users WHERE id = $1",
wrapped: (*errors.errorString)({
s: (string) (len=15) "network timeout"
})
})
})
:x: 2 Tests Failed:
| Tests completed | Failed | Passed | Skipped |
|---|---|---|---|
| 1304 | 2 | 1302 | 129 |
View the full list of 4 :snowflake: flaky test(s)
github.com/PeerDB-io/peerdb/flow/e2e::TestPeerFlowE2ETestSuitePGFlake rate in main: 30.56% (Passed 25 times, Failed 11 times)
Stack Traces | 0s run time
=== RUN TestPeerFlowE2ETestSuitePG === PAUSE TestPeerFlowE2ETestSuitePG === CONT TestPeerFlowE2ETestSuitePG --- FAIL: TestPeerFlowE2ETestSuitePG (0.00s)
github.com/PeerDB-io/peerdb/flow/e2e::TestPeerFlowE2ETestSuitePG/Test_Soft_Delete_UD_Same_BatchFlake rate in main: 30.56% (Passed 25 times, Failed 11 times)
Stack Traces | 5.03s run time
=== RUN TestPeerFlowE2ETestSuitePG/Test_Soft_Delete_UD_Same_Batch === PAUSE TestPeerFlowE2ETestSuitePG/Test_Soft_Delete_UD_Same_Batch === CONT TestPeerFlowE2ETestSuitePG/Test_Soft_Delete_UD_Same_Batch postgres_test.go:634: Failed to connect temporal client: failed reaching server: context deadline exceeded postgres.go:92: begin tearing down postgres schema pg_6xpwac3g --- FAIL: TestPeerFlowE2ETestSuitePG/Test_Soft_Delete_UD_Same_Batch (5.03s)
github.com/PeerDB-io/peerdb/flow/e2e::TestPeerFlowE2ETestSuitePG_CHFlake rate in main: 30.56% (Passed 25 times, Failed 11 times)
Stack Traces | 0.01s run time
=== RUN TestPeerFlowE2ETestSuitePG_CH === PAUSE TestPeerFlowE2ETestSuitePG_CH === CONT TestPeerFlowE2ETestSuitePG_CH --- FAIL: TestPeerFlowE2ETestSuitePG_CH (0.01s)
github.com/PeerDB-io/peerdb/flow/e2e::TestPeerFlowE2ETestSuitePG_CH/Test_Normalize_Metadata_With_RetryFlake rate in main: 30.56% (Passed 25 times, Failed 11 times)
Stack Traces | 199s run time
=== RUN TestPeerFlowE2ETestSuitePG_CH/Test_Normalize_Metadata_With_Retry === PAUSE TestPeerFlowE2ETestSuitePG_CH/Test_Normalize_Metadata_With_Retry === CONT TestPeerFlowE2ETestSuitePG_CH/Test_Normalize_Metadata_With_Retry 2025/10/19 04:08:41 INFO Received AWS credentials from peer for connector: ci x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} 2025/10/19 04:08:41 INFO Received AWS credentials from peer for connector: clickhouse x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} 2025/10/19 04:08:41 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_qd3mh7zy.\"test_nullengine\" ORDER BY id" 2025/10/19 04:08:41 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_qd3mh7zy.\"test_nullengine\" ORDER BY id" 2025/10/19 04:08:41 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_1733190746579346795 CURSOR FOR SELECT id,\"key\" FROM e2e_test_pgch_qd3mh7zy.\"test_nullengine\" ORDER BY id" args=[] 2025/10/19 04:08:41 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_qd3mh7zy.\"test_nullengine\" ORDER BY id" channelLen=0 2025/10/19 04:08:41 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1733190746579346795 2025/10/19 04:08:41 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1733190746579346795 records=1 bytes=7 channelLen=0 2025/10/19 04:08:41 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_qd3mh7zy.\"test_nullengine\" ORDER BY id" rows=1 bytes=7 channelLen=0 2025/10/19 04:08:41 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1733190746579346795 2025/10/19 04:08:41 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1733190746579346795 records=0 bytes=0 channelLen=0 2025/10/19 04:08:41 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_qd3mh7zy.\"test_nullengine\" ORDER BY id" rows=0 bytes=0 channelLen=0 2025/10/19 04:08:41 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart 2025/10/19 04:08:41 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_qd3mh7zy.\"test_nullengine\" ORDER BY id" rows=1 bytes=7 channelLen=0 clickhouse_test.go:2018: WaitFor waiting on initial 2025-10-19 04:08:45.087899527 +0000 UTC m=+509.884851307 2025/10/19 04:08:45 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_bki422hj.\"test_normalize_metadata_with_retry_1\" ORDER BY id" 2025/10/19 04:08:45 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_bki422hj.\"test_normalize_metadata_with_retry_1\" ORDER BY id" 2025/10/19 04:08:45 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_1051495318061219633 CURSOR FOR SELECT id,\"key\" FROM e2e_test_pgch_bki422hj.\"test_normalize_metadata_with_retry_1\" ORDER BY id" args=[] 2025/10/19 04:08:45 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_bki422hj.\"test_normalize_metadata_with_retry_1\" ORDER BY id" channelLen=0 2025/10/19 04:08:45 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1051495318061219633 2025/10/19 04:08:45 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1051495318061219633 records=4 bytes=29 channelLen=3 2025/10/19 04:08:45 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_bki422hj.\"test_normalize_metadata_with_retry_1\" ORDER BY id" rows=4 bytes=29 channelLen=0 2025/10/19 04:08:45 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1051495318061219633 2025/10/19 04:08:45 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1051495318061219633 records=0 bytes=0 channelLen=0 2025/10/19 04:08:45 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,\"key\" FROM e2e_test_pgch_bki422hj.\"test_normalize_metadata_with_retry_1\" ORDER BY id" rows=0 bytes=0 channelLen=0 2025/10/19 04:08:45 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart 2025/10/19 04:08:45 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_bki422hj.\"test_normalize_metadata_with_retry_1\" ORDER BY id" rows=4 bytes=29 channelLen=0 clickhouse_test.go:2032: WaitFor waiting for first sync to complete 2025-10-19 04:08:45.101453501 +0000 UTC m=+509.898405281 2025/10/19 04:08:45 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" 2025/10/19 04:08:45 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" 2025/10/19 04:08:45 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_5716145562286191128 CURSOR FOR SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" args=[] 2025/10/19 04:08:45 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" channelLen=0 2025/10/19 04:08:45 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_5716145562286191128 2025/10/19 04:08:45 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_5716145562286191128 records=0 bytes=0 channelLen=0 2025/10/19 04:08:45 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" rows=0 bytes=0 channelLen=0 2025/10/19 04:08:45 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart 2025/10/19 04:08:45 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" rows=0 bytes=0 channelLen=0 clickhouse_test.go:2047: WaitFor waiting for raw table push to complete 2025-10-19 04:09:01.14018854 +0000 UTC m=+525.937140320 clickhouse_test.go:2060: WaitFor waiting for normalize error 2025-10-19 04:09:01.142789703 +0000 UTC m=+525.939741483 2025/10/19 04:09:01 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT COUNT(*) FROM peerdb_stats.flow_errors\n\t\tWHERE error_type='error' AND position('test_normalize_metadata_with_retry_pgch_bki422hj' in flow_name) > 0\n\t\tAND error_message ILIKE '%error while inserting into target clickhouse table%'" 2025/10/19 04:09:01 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT COUNT(*) FROM peerdb_stats.flow_errors\n\t\tWHERE error_type='error' AND position('test_normalize_metadata_with_retry_pgch_bki422hj' in flow_name) > 0\n\t\tAND error_message ILIKE '%error while inserting into target clickhouse table%'" 2025/10/19 04:09:01 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_12506536845105215288 CURSOR FOR \n\t\tSELECT COUNT(*) FROM peerdb_stats.flow_errors\n\t\tWHERE error_type='error' AND position('test_normalize_metadata_with_retry_pgch_bki422hj' in flow_name) > 0\n\t\tAND error_message ILIKE '%error while inserting into target clickhouse table%'" args=[] 2025/10/19 04:09:01 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT COUNT(*) FROM peerdb_stats.flow_errors\n\t\tWHERE error_type='error' AND position('test_normalize_metadata_with_retry_pgch_bki422hj' in flow_name) > 0\n\t\tAND error_message ILIKE '%error while inserting into target clickhouse table%'" channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12506536845105215288 2025/10/19 04:09:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12506536845105215288 records=1 bytes=8 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT COUNT(*) FROM peerdb_stats.flow_errors\n\t\tWHERE error_type='error' AND position('test_normalize_metadata_with_retry_pgch_bki422hj' in flow_name) > 0\n\t\tAND error_message ILIKE '%error while inserting into target clickhouse table%'" rows=1 bytes=8 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12506536845105215288 2025/10/19 04:09:01 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,v1,hv,sv FROM e2e_test_pgch_55r4jd0e.\"test_pgvector_text\" ORDER BY id" 2025/10/19 04:09:01 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,v1,hv,sv FROM e2e_test_pgch_55r4jd0e.\"test_pgvector_text\" ORDER BY id" 2025/10/19 04:09:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12506536845105215288 records=0 bytes=0 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT COUNT(*) FROM peerdb_stats.flow_errors\n\t\tWHERE error_type='error' AND position('test_normalize_metadata_with_retry_pgch_bki422hj' in flow_name) > 0\n\t\tAND error_message ILIKE '%error while inserting into target clickhouse table%'" rows=0 bytes=0 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart 2025/10/19 04:09:01 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT COUNT(*) FROM peerdb_stats.flow_errors\n\t\tWHERE error_type='error' AND position('test_normalize_metadata_with_retry_pgch_bki422hj' in flow_name) > 0\n\t\tAND error_message ILIKE '%error while inserting into target clickhouse table%'" rows=1 bytes=8 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_17336452017315100841 CURSOR FOR SELECT id,v1,hv,sv FROM e2e_test_pgch_55r4jd0e.\"test_pgvector_text\" ORDER BY id" args=[] 2025/10/19 04:09:01 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,v1,hv,sv FROM e2e_test_pgch_55r4jd0e.\"test_pgvector_text\" ORDER BY id" channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17336452017315100841 2025/10/19 04:09:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17336452017315100841 records=2 bytes=76 channelLen=1 2025/10/19 04:09:01 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,v1,hv,sv FROM e2e_test_pgch_55r4jd0e.\"test_pgvector_text\" ORDER BY id" rows=2 bytes=76 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17336452017315100841 2025/10/19 04:09:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17336452017315100841 records=0 bytes=0 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,v1,hv,sv FROM e2e_test_pgch_55r4jd0e.\"test_pgvector_text\" ORDER BY id" rows=0 bytes=0 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart 2025/10/19 04:09:01 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,v1,hv,sv FROM e2e_test_pgch_55r4jd0e.\"test_pgvector_text\" ORDER BY id" rows=2 bytes=76 channelLen=0 clickhouse_test.go:2073: WaitFor waiting for second sync to complete 2025-10-19 04:09:01.151153605 +0000 UTC m=+525.948105395 2025/10/19 04:09:01 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" 2025/10/19 04:09:01 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" 2025/10/19 04:09:01 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_1900183859705394720 CURSOR FOR SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" args=[] 2025/10/19 04:09:01 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1900183859705394720 2025/10/19 04:09:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1900183859705394720 records=1 bytes=8 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" rows=1 bytes=8 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1900183859705394720 2025/10/19 04:09:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_1900183859705394720 records=0 bytes=0 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" rows=0 bytes=0 channelLen=0 2025/10/19 04:09:01 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart 2025/10/19 04:09:01 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT sync_batch_id FROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" rows=1 bytes=8 channelLen=0 clickhouse_test.go:2087: WaitFor waiting for second raw table push to complete 2025-10-19 04:09:16.189970934 +0000 UTC m=+540.986922714 2025/10/19 04:09:16 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,json,jsonb FROM e2e_test_pgch_wdbq3nab.\"test_json\" ORDER BY id" 2025/10/19 04:09:16 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,json,jsonb FROM e2e_test_pgch_wdbq3nab.\"test_json\" ORDER BY id" 2025/10/19 04:09:16 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_11010014779545265797 CURSOR FOR SELECT id,json,jsonb FROM e2e_test_pgch_wdbq3nab.\"test_json\" ORDER BY id" args=[] 2025/10/19 04:09:16 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,json,jsonb FROM e2e_test_pgch_wdbq3nab.\"test_json\" ORDER BY id" channelLen=0 2025/10/19 04:09:16 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_11010014779545265797 2025/10/19 04:09:16 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_11010014779545265797 records=12 bytes=1510 channelLen=3 2025/10/19 04:09:16 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,json,jsonb FROM e2e_test_pgch_wdbq3nab.\"test_json\" ORDER BY id" rows=12 bytes=1510 channelLen=3 2025/10/19 04:09:16 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_11010014779545265797 2025/10/19 04:09:16 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_11010014779545265797 records=0 bytes=0 channelLen=0 2025/10/19 04:09:16 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,json,jsonb FROM e2e_test_pgch_wdbq3nab.\"test_json\" ORDER BY id" rows=0 bytes=0 channelLen=0 2025/10/19 04:09:16 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart 2025/10/19 04:09:16 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,json,jsonb FROM e2e_test_pgch_wdbq3nab.\"test_json\" ORDER BY id" rows=12 bytes=1510 channelLen=0 clickhouse_test.go:2099: WaitFor check normalize table metadata after normalize 2025-10-19 04:10:00.347371759 +0000 UTC m=+585.144323559 2025/10/19 04:10:00 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_1')::bigint, (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_2')::bigint\n\t\tFROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" 2025/10/19 04:10:00 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_1')::bigint, (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_2')::bigint\n\t\tFROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" 2025/10/19 04:10:00 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_14621525324631680107 CURSOR FOR \n\t\tSELECT (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_1')::bigint, (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_2')::bigint\n\t\tFROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" args=[] 2025/10/19 04:10:00 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_1')::bigint, (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_2')::bigint\n\t\tFROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" channelLen=0 2025/10/19 04:10:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_14621525324631680107 2025/10/19 04:10:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_14621525324631680107 records=1 bytes=8 channelLen=0 2025/10/19 04:10:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_1')::bigint, (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_2')::bigint\n\t\tFROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" rows=1 bytes=8 channelLen=0 2025/10/19 04:10:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_14621525324631680107 2025/10/19 04:10:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_14621525324631680107 records=0 bytes=0 channelLen=0 2025/10/19 04:10:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_1')::bigint, (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_2')::bigint\n\t\tFROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" rows=0 bytes=0 channelLen=0 2025/10/19 04:10:00 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart 2025/10/19 04:10:00 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="\n\t\tSELECT (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_1')::bigint, (table_batch_id_data->>'test_normalize_metadata_with_retry_dst_2')::bigint\n\t\tFROM metadata_last_sync_state WHERE job_name='test_normalize_metadata_with_retry_pgch_bki422hj'" rows=1 bytes=8 channelLen=0 clickhouse_test.go:2113: metadata_last_sync_state <nil> 1 clickhouse.go:114: begin tearing down postgres schema pgch_bki422hj clickhouse.go:114: Error Trace: .../flow/e2e/pg.go:149 .../flow/e2e/clickhouse.go:114 .../flow/e2eshared/e2eshared.go:38 .../hostedtoolcache/go/1.25.2.../src/testing/testing.go:1308 .../hostedtoolcache/go/1.25.2.../src/testing/testing.go:1572 .../hostedtoolcache/go/1.25.2.../src/testing/testing.go:1928 .../hostedtoolcache/go/1.25.2.../src/runtime/panic.go:783 .../hostedtoolcache/go/1.25.2.../src/runtime/iface.go:275 .../flow/e2e/clickhouse_test.go:2114 .../flow/e2e/test_utils.go:780 .../flow/e2e/clickhouse_test.go:2099 Error: failed to teardown postgres schema Test: TestPeerFlowE2ETestSuitePG_CH/Test_Normalize_Metadata_With_Retry Messages: pgch_bki422hj: failed to drop e2e_test schema: timeout: context already done: context deadline exceeded --- FAIL: TestPeerFlowE2ETestSuitePG_CH/Test_Normalize_Metadata_With_Retry (199.47s)
To view more test analytics, go to the Test Analytics Dashboard 📋 Got 3 mins? Take this short survey to help us improve Test Analytics.
![codecov[bot] avatar](https://avatars.githubusercontent.com/in/254?v=4 "Published by a pub.dev verified publisher"){kind=small}