Spew full structure for all flow_errors #3615

ilidemi · 2025-10-17T05:17:36Z

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"
    })
  })
})

codecov · 2025-10-19T04:12:15Z

❌ 2 Tests Failed:

Tests completed	Failed	Passed	Skipped
1304	2	1302	129

View the full list of 4 ❄️ flaky test(s)

github.com/PeerDB-io/peerdb/flow/e2e::TestPeerFlowE2ETestSuitePG

Flake 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_Batch

Flake 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_CH

Flake 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_Retry

Flake 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.}

ilidemi added 5 commits October 16, 2025 22:16

Spew full structure for all flow_errors

e003047

what if long log

7e76703

what if more logs are lost

835764c

try max depth

d14c8d6

full error, less depth

ed75d83

ilidemi marked this pull request as draft October 19, 2025 03:47

ilidemi changed the title ~~Spew full structure for all flow_errors (att 2)~~ Spew full structure for all flow_errors Oct 19, 2025

what if no methods

60c869b

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Spew full structure for all flow_errors #3615

Spew full structure for all flow_errors #3615

Uh oh!

ilidemi commented Oct 17, 2025 •

edited

Loading

Uh oh!

codecov bot commented Oct 19, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Spew full structure for all flow_errors #3615

Are you sure you want to change the base?

Spew full structure for all flow_errors #3615

Uh oh!

Conversation

ilidemi commented Oct 17, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

codecov bot commented Oct 19, 2025

❌ 2 Tests Failed:

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

ilidemi commented Oct 17, 2025 •

edited

Loading