peerdb icon indicating copy to clipboard operation
peerdb copied to clipboard
verified publisher icon PeerDB-io

Add more WAL metrics

Open ilidemi opened this issue 1 month ago • 2 comments

We need better visibility into the impacts of a deployment on large customers.

When we reconnect to a busy PG instance, there can be five phases:

  1. Scrubbing the WAL from restart_lsn to confirmed_flush_lsn to reconstruct the consumer state
  2. Catching us up on the updates
  3. Reading through updates outside our publication (not knowing if there are in-scope updates later on)
  4. Waiting on a pending transaction, where we don't receive anything but pg_stat_replication.sent_lsn didn't reach the current LSN yet
  5. Steady state after sent_lsn touches the current LSN

The part we're interested in is how long does it take to get to 4 (or 5 if there's no transaction). The primary way to determine this is to observe pg_stat_activity.wait_event_type to become Client and wait_event become WalSenderWaitForWAL for that backend - this happens when there's no WAL the sender can send. This is emitted as walsender_state gauge with value=1 and attributes changing.

Also adding drilldowns to help see the progress towards that and the slow spots:

  • Deltas between restart<->confirmed<->sent<->current LSN, illustrating phases and how far behind we are
  • pg_stat_replication_slots.spill_txns, spill_count, spill_bytes (PG16+), logical_decoding_work_mem setting (PG13+) to see if phase 1 is running out of memory and spilling to disk (which we can recommend to adjust)

As well as few QoL metrics about the slot and the backend state, and the pg_replication_slots.safe_wal_size (PG13+) to see if we're in any danger zone wrt losing the slot.

TBD: actually test this

edit: there is a miss here - when the data is coming and it's outside of publication, wait_event_type/wait_event would flip in a subsecond range, and polling every 1-5 minutes would only produce noise. we could theoretically track of whether we're catching up or not and run a separate lightweight query every second (with sleep() on a server side to save on network) but this is getting quite involved

ilidemi avatar Nov 12 '25 06:11 ilidemi

Q: anything preventing us from querying this every minute instead of 5? 5 is kinda close to the unhappy zone for the customers

ilidemi avatar Nov 12 '25 06:11 ilidemi

:x: 2 Tests Failed:

Tests completed Failed Passed Skipped
1288 2 1286 131
View the full list of 2 :snowflake: flaky test(s) 
github.com/PeerDB-io/peerdb/flow/e2e::TestApiPg

Flake rate in main: 17.89% (Passed 312 times, Failed 68 times)

Stack Traces | 0.01s run time 
=== RUN   TestApiPg
=== PAUSE TestApiPg
=== CONT  TestApiPg
--- FAIL: TestApiPg (0.01s)
2025/11/17 00:16:55 INFO Received AWS credentials from peer for connector: ci x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2025/11/17 00:16:55 INFO Received AWS credentials from peer for connector: clickhouse x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}

github.com/PeerDB-io/peerdb/flow/e2e::TestApiPg/TestQRep

Flake rate in main: 14.21% (Passed 326 times, Failed 54 times)

Stack Traces | 63.2s run time 
=== RUN   TestApiPg/TestQRep
=== PAUSE TestApiPg/TestQRep
=== CONT  TestApiPg/TestQRep
2025/11/17 00:15:00 INFO Received AWS credentials from peer for connector: ci x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2025/11/17 00:15:00 INFO Received AWS credentials from peer for connector: clickhouse x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2025/11/17 00:15:00 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes\" ORDER BY id"
2025/11/17 00:15:00 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes\" ORDER BY id"
2025/11/17 00:15:00 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_16706529530404978036 CURSOR FOR SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes\" ORDER BY id" args=[]
2025/11/17 00:15:00 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes\" ORDER BY id" channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_16706529530404978036
2025/11/17 00:15:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_16706529530404978036 records=4 bytes=48 channelLen=3
2025/11/17 00:15:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes\" ORDER BY id" rows=4 bytes=48 channelLen=3
2025/11/17 00:15:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_16706529530404978036
2025/11/17 00:15:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_16706529530404978036 records=0 bytes=0 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes\" ORDER BY id" rows=0 bytes=0 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2025/11/17 00:15:00 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes\" ORDER BY id" rows=4 bytes=48 channelLen=0
2025/11/17 00:15:00 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes_dst\" ORDER BY id"
2025/11/17 00:15:00 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes_dst\" ORDER BY id"
2025/11/17 00:15:00 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_15356675899324954548 CURSOR FOR SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes_dst\" ORDER BY id" args=[]
2025/11/17 00:15:00 INFO [pg_query_executor] fetching rows start x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes_dst\" ORDER BY id" channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_15356675899324954548
2025/11/17 00:15:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_15356675899324954548 records=3 bytes=36 channelLen=2
2025/11/17 00:15:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes_dst\" ORDER BY id" rows=3 bytes=36 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_15356675899324954548
2025/11/17 00:15:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_15356675899324954548 records=0 bytes=0 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes_dst\" ORDER BY id" rows=0 bytes=0 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2025/11/17 00:15:00 INFO [pg_query_executor] committed transaction for query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,c1 FROM e2e_test_pg_uqyrwjhv.\"test_simple_schema_changes_dst\" ORDER BY id" rows=3 bytes=36 channelLen=0
    api_test.go:1239: WaitFor qrep initial load 2025-11-17 00:15:00.38709522 +0000 UTC m=+131.245856835
2025/11/17 00:15:00 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id"
2025/11/17 00:15:00 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id"
2025/11/17 00:15:00 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_10104150020541179310 CURSOR FOR SELECT id,val FROM e2e_test_api_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id" args=[]
2025/11/17 00:15:00 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_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id" channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10104150020541179310
2025/11/17 00:15:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10104150020541179310 records=1 bytes=9 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id" rows=1 bytes=9 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10104150020541179310
2025/11/17 00:15:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10104150020541179310 records=0 bytes=0 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id" rows=0 bytes=0 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2025/11/17 00:15:00 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_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id" rows=1 bytes=9 channelLen=0
    api_test.go:1239: code: 60, message: Unknown table expression identifier 'qrepapi_api_i7v7tcj2' in scope SELECT id, val FROM qrepapi_api_i7v7tcj2 FINAL WHERE _peerdb_is_deleted = 0 ORDER BY 1 ASC SETTINGS use_query_cache = false
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id"
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id"
2025/11/17 00:15:00 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_12368057687730231359 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" args=[]
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12368057687730231359
2025/11/17 00:15:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12368057687730231359 records=8 bytes=168 channelLen=7
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" rows=8 bytes=168 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12368057687730231359
2025/11/17 00:15:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12368057687730231359 records=0 bytes=0 channelLen=0
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" rows=0 bytes=0 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" rows=8 bytes=168 channelLen=0
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id"
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id"
2025/11/17 00:15:00 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_17721935186335616461 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" args=[]
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17721935186335616461
2025/11/17 00:15:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17721935186335616461 records=3 bytes=63 channelLen=2
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" rows=3 bytes=63 channelLen=2
2025/11/17 00:15:00 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17721935186335616461
2025/11/17 00:15:00 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_17721935186335616461 records=0 bytes=0 channelLen=0
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" rows=0 bytes=0 channelLen=0
2025/11/17 00:15:00 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2025/11/17 00:15: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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" rows=3 bytes=63 channelLen=0
    api_test.go:1244: WaitFor insert post qrep initial load 2025-11-17 00:15:01.40613528 +0000 UTC m=+132.264896885
2025/11/17 00:15:01 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id"
2025/11/17 00:15:01 INFO Executing and processing query stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id"
2025/11/17 00:15:01 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_10814477044230201898 CURSOR FOR SELECT id,val FROM e2e_test_api_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id" args=[]
2025/11/17 00:15:01 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_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id" channelLen=0
2025/11/17 00:15:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10814477044230201898
2025/11/17 00:15:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10814477044230201898 records=2 bytes=19 channelLen=1
2025/11/17 00:15:01 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id" rows=2 bytes=19 channelLen=0
2025/11/17 00:15:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10814477044230201898
2025/11/17 00:15:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_10814477044230201898 records=0 bytes=0 channelLen=0
2025/11/17 00:15:01 INFO [pg_query_executor] fetched rows x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,val FROM e2e_test_api_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id" rows=0 bytes=0 channelLen=0
2025/11/17 00:15:01 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2025/11/17 00:15:01 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_i7v7tcj2.\"qrepapi_api_i7v7tcj2\" ORDER BY id" rows=2 bytes=19 channelLen=0
    api_test.go:1244: q.NumRecords: 2
    api_test.go:1244: other.NumRecords: 1
2025/11/17 00:15:01 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id"
2025/11/17 00:15:01 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id"
2025/11/17 00:15:01 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_12957010335837172849 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" args=[]
2025/11/17 00:15:01 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" channelLen=0
2025/11/17 00:15:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12957010335837172849
2025/11/17 00:15:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12957010335837172849 records=8 bytes=168 channelLen=7
2025/11/17 00:15:01 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" rows=8 bytes=168 channelLen=7
2025/11/17 00:15:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12957010335837172849
2025/11/17 00:15:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_12957010335837172849 records=0 bytes=0 channelLen=0
2025/11/17 00:15:01 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" rows=0 bytes=0 channelLen=0
2025/11/17 00:15:01 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2025/11/17 00:15:01 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" rows=8 bytes=168 channelLen=0
2025/11/17 00:15:01 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id"
2025/11/17 00:15:01 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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id"
2025/11/17 00:15:01 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_3763614576510736419 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" args=[]
2025/11/17 00:15:01 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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" channelLen=0
2025/11/17 00:15:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3763614576510736419
2025/11/17 00:15:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3763614576510736419 records=3 bytes=63 channelLen=2
2025/11/17 00:15:01 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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" rows=3 bytes=63 channelLen=2
2025/11/17 00:15:01 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3763614576510736419
2025/11/17 00:15:01 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_3763614576510736419 records=0 bytes=0 channelLen=0
2025/11/17 00:15:01 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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" rows=0 bytes=0 channelLen=0
2025/11/17 00:15:01 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2025/11/17 00:15:01 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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" rows=3 bytes=63 channelLen=0
    api_test.go:1244: q.NumRecords: 2
    api_test.go:1244: other.NumRecords: 1
2025/11/17 00:15:02 INFO Received AWS credentials from peer for connector: ci x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
2025/11/17 00:15:02 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id"
2025/11/17 00:15:02 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id"
2025/11/17 00:15:02 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_15390011349517442824 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" args=[]
2025/11/17 00:15:02 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" channelLen=0
2025/11/17 00:15:02 INFO Received AWS credentials from peer for connector: clickhouse x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN}
    api_test.go:1256: WaitFor finish 2025-11-17 00:15:03.433434202 +0000 UTC m=+134.292195817
2025/11/17 00:15:03 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id"
2025/11/17 00:15:03 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id"
2025/11/17 00:15:03 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_13067060322559198188 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" args=[]
2025/11/17 00:15:03 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" channelLen=0
2025/11/17 00:15:03 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13067060322559198188
2025/11/17 00:15:03 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13067060322559198188 records=8 bytes=168 channelLen=7
2025/11/17 00:15:03 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" rows=8 bytes=168 channelLen=0
2025/11/17 00:15:03 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13067060322559198188
2025/11/17 00:15:03 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_13067060322559198188 records=0 bytes=0 channelLen=0
2025/11/17 00:15:03 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" rows=0 bytes=0 channelLen=0
2025/11/17 00:15:03 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2025/11/17 00:15:03 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_pg_dfovejkt.\"test_inheritance_dynconf\" ORDER BY id" rows=8 bytes=168 channelLen=0
2025/11/17 00:15:03 INFO Executing and processing query x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart query="SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id"
2025/11/17 00:15:03 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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id"
2025/11/17 00:15:03 INFO [pg_query_executor] declared cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursorQuery="DECLARE peerdb_cursor_4602859401494687939 CURSOR FOR SELECT id,name,created_at FROM e2e_test_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" args=[]
2025/11/17 00:15:03 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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" channelLen=0
2025/11/17 00:15:03 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_4602859401494687939
2025/11/17 00:15:03 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_4602859401494687939 records=3 bytes=63 channelLen=2
2025/11/17 00:15:03 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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" rows=3 bytes=63 channelLen=0
2025/11/17 00:15:03 INFO [pg_query_executor] fetching from cursor x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_4602859401494687939
2025/11/17 00:15:03 INFO processed row stream x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart cursor=peerdb_cursor_4602859401494687939 records=0 bytes=0 channelLen=0
2025/11/17 00:15:03 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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" rows=0 bytes=0 channelLen=0
2025/11/17 00:15:03 INFO [pg_query_executor] committing transaction x-peerdb-additional-metadata={Operation:FLOW_OPERATION_UNKNOWN} partitionId=testpart
2025/11/17 00:15:03 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_pg_dfovejkt.\"test_inheritance_dynconf_dst\" ORDER BY id" rows=3 bytes=63 channelLen=0
    api_test.go:1256: UNEXPECTED TIMEOUT finish 2025-11-17 00:16:03.558833576 +0000 UTC m=+194.417595191
    api_test.go:44: begin tearing down postgres schema api_i7v7tcj2
--- FAIL: TestApiPg/TestQRep (63.24s)

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 Nov 12 '25 06:11 codecov[bot]