031_recovery_conflict_standby.log

2023-08-04 12:20:36.887 UTC [1920020] LOG:  starting PostgreSQL 17devel (Ubuntu 17~~devel-1) on s390x-ibm-linux-gnu, compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit
2023-08-04 12:20:36.887 UTC [1920020] LOG:  listening on Unix socket "/tmp/GoFBiPMX9Y/.s.PGSQL.55091"
2023-08-04 12:20:36.891 UTC [1920023] LOG:  database system was interrupted; last known up at 2023-08-04 12:20:36 UTC
2023-08-04 12:20:36.891 UTC [1920023] LOG:  entering standby mode
2023-08-04 12:20:36.891 UTC [1920023] LOG:  redo starts at 0/2000028
2023-08-04 12:20:36.891 UTC [1920023] WARNING:  unexpected directory entry "16384" found in pg_tblspc/
2023-08-04 12:20:36.891 UTC [1920023] DETAIL:  All directory entries in pg_tblspc/ should be symbolic links.
2023-08-04 12:20:36.891 UTC [1920023] HINT:  Remove those directories, or set allow_in_place_tablespaces to ON transiently to let recovery complete.
2023-08-04 12:20:36.891 UTC [1920023] LOG:  consistent recovery state reached at 0/2000100
2023-08-04 12:20:36.892 UTC [1920020] LOG:  database system is ready to accept read-only connections
2023-08-04 12:20:36.936 UTC [1920024] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2023-08-04 12:20:37.350 UTC [1920035] 031_recovery_conflict.pl LOG:  statement: BEGIN;
2023-08-04 12:20:37.350 UTC [1920035] 031_recovery_conflict.pl LOG:  statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT b FROM test_recovery_conflict_table1;
2023-08-04 12:20:37.354 UTC [1920035] 031_recovery_conflict.pl LOG:  statement: FETCH FORWARD FROM test_recovery_conflict_cursor;
2023-08-04 12:20:37.355 UTC [1920035] 031_recovery_conflict.pl LOG:  statement: ;
2023-08-04 12:20:37.385 UTC [1920023] LOG:  recovery still waiting after 13.382 ms: recovery conflict on buffer pin
2023-08-04 12:20:37.385 UTC [1920023] CONTEXT:  WAL redo at 0/3429C50 for Heap2/PRUNE: snapshotConflictHorizon: 0, nredirected: 0, ndead: 1, nunused: 0, redirected: [], dead: [21], unused: []; blkref #0: rel 1663/16385/16386, blk 0
2023-08-04 12:20:37.426 UTC [1920035] 031_recovery_conflict.pl FATAL:  terminating connection due to conflict with recovery
2023-08-04 12:20:37.426 UTC [1920035] 031_recovery_conflict.pl DETAIL:  User was holding shared buffer pin for too long.
2023-08-04 12:20:37.426 UTC [1920035] 031_recovery_conflict.pl HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2023-08-04 12:20:37.428 UTC [1920023] LOG:  recovery finished waiting after 56.327 ms: recovery conflict on buffer pin
2023-08-04 12:20:37.428 UTC [1920023] CONTEXT:  WAL redo at 0/3429C50 for Heap2/PRUNE: snapshotConflictHorizon: 0, nredirected: 0, ndead: 1, nunused: 0, redirected: [], dead: [21], unused: []; blkref #0: rel 1663/16385/16386, blk 0
2023-08-04 12:20:37.601 UTC [1920055] 031_recovery_conflict.pl LOG:  statement: SELECT confl_bufferpin FROM pg_stat_database_conflicts WHERE datname='test_db';
2023-08-04 12:20:37.684 UTC [1920053] 031_recovery_conflict.pl LOG:  statement: BEGIN;
2023-08-04 12:20:37.693 UTC [1920053] 031_recovery_conflict.pl LOG:  statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT b FROM test_recovery_conflict_table1;
2023-08-04 12:20:37.695 UTC [1920053] 031_recovery_conflict.pl LOG:  statement: FETCH FORWARD FROM test_recovery_conflict_cursor;
2023-08-04 12:20:37.700 UTC [1920053] 031_recovery_conflict.pl LOG:  statement: ;
2023-08-04 12:20:37.788 UTC [1920023] LOG:  recovery still waiting after 19.486 ms: recovery conflict on snapshot
2023-08-04 12:20:37.788 UTC [1920023] DETAIL:  Conflicting process: 1920053.
2023-08-04 12:20:37.788 UTC [1920023] CONTEXT:  WAL redo at 0/34329A8 for Heap2/PRUNE: snapshotConflictHorizon: 738, nredirected: 18, ndead: 0, nunused: 0, redirected: [23->41, 24->42, 25->43, 26->44, 27->45, 28->46, 29->47, 30->48, 31->49, 32->50, 33->51, 34->52, 35->53, 36->54, 37->55, 38->56, 39->57, 40->58], dead: [], unused: []; blkref #0: rel 1663/16385/16386, blk 0
2023-08-04 12:20:37.839 UTC [1920053] 031_recovery_conflict.pl FATAL:  terminating connection due to conflict with recovery
2023-08-04 12:20:37.839 UTC [1920053] 031_recovery_conflict.pl DETAIL:  User query might have needed to see row versions that must be removed.
2023-08-04 12:20:37.839 UTC [1920053] 031_recovery_conflict.pl HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2023-08-04 12:20:37.844 UTC [1920023] LOG:  recovery finished waiting after 75.763 ms: recovery conflict on snapshot
2023-08-04 12:20:37.844 UTC [1920023] CONTEXT:  WAL redo at 0/34329A8 for Heap2/PRUNE: snapshotConflictHorizon: 738, nredirected: 18, ndead: 0, nunused: 0, redirected: [23->41, 24->42, 25->43, 26->44, 27->45, 28->46, 29->47, 30->48, 31->49, 32->50, 33->51, 34->52, 35->53, 36->54, 37->55, 38->56, 39->57, 40->58], dead: [], unused: []; blkref #0: rel 1663/16385/16386, blk 0
2023-08-04 12:20:37.959 UTC [1920075] 031_recovery_conflict.pl LOG:  statement: SELECT confl_snapshot FROM pg_stat_database_conflicts WHERE datname='test_db';
2023-08-04 12:20:37.969 UTC [1920073] 031_recovery_conflict.pl LOG:  statement: BEGIN;
2023-08-04 12:20:37.970 UTC [1920073] 031_recovery_conflict.pl LOG:  statement: LOCK TABLE test_recovery_conflict_table1 IN ACCESS SHARE MODE;
2023-08-04 12:20:37.970 UTC [1920073] 031_recovery_conflict.pl LOG:  statement: SELECT 1;
2023-08-04 12:20:37.970 UTC [1920073] 031_recovery_conflict.pl LOG:  statement: ;
2023-08-04 12:20:38.061 UTC [1920023] LOG:  recovery still waiting after 69.530 ms: recovery conflict on lock
2023-08-04 12:20:38.061 UTC [1920023] DETAIL:  Conflicting process: 1920073.
2023-08-04 12:20:38.061 UTC [1920023] CONTEXT:  WAL redo at 0/3432B88 for Standby/LOCK: xid 739 db 16385 rel 16386 
2023-08-04 12:20:38.061 UTC [1920073] 031_recovery_conflict.pl FATAL:  terminating connection due to conflict with recovery
2023-08-04 12:20:38.061 UTC [1920073] 031_recovery_conflict.pl DETAIL:  User transaction caused buffer deadlock with recovery.
2023-08-04 12:20:38.061 UTC [1920073] 031_recovery_conflict.pl HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2023-08-04 12:20:38.111 UTC [1920023] LOG:  recovery finished waiting after 119.873 ms: recovery conflict on lock
2023-08-04 12:20:38.111 UTC [1920023] CONTEXT:  WAL redo at 0/3432B88 for Standby/LOCK: xid 739 db 16385 rel 16386 
2023-08-04 12:23:41.120 UTC [1920024] FATAL:  could not receive data from WAL stream: server closed the connection unexpectedly
		This probably means the server terminated abnormally
		before or while processing the request.
2023-08-04 12:23:41.122 UTC [1920023] LOG:  invalid record length at 0/3480320: expected at least 24, got 0
2023-08-04 12:23:41.129 UTC [1920090] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/GoFBiPMX9Y/.s.PGSQL.55090" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2023-08-04 12:23:41.132 UTC [1920023] LOG:  waiting for WAL to become available at 0/3480338
2023-08-04 12:23:41.226 UTC [1920020] LOG:  received immediate shutdown request
2023-08-04 12:23:41.232 UTC [1920020] LOG:  database system is shut down