031_recovery_conflict_standby.log
text/plain
Filename: 031_recovery_conflict_standby.log
Type: text/plain
Part: 1
2023-08-07 10:21:54.157 UTC [3132749] LOG: starting PostgreSQL 17devel (Debian 17~~devel-1) on s390x-ibm-linux-gnu, compiled by gcc (Debian 13.2.0-1) 13.2.0, 64-bit 2023-08-07 10:21:54.157 UTC [3132749] LOG: listening on Unix socket "/tmp/Ew0sehtBKm/.s.PGSQL.52787" 2023-08-07 10:21:54.160 UTC [3132752] LOG: database system was interrupted; last known up at 2023-08-07 10:21:53 UTC 2023-08-07 10:21:54.160 UTC [3132752] LOG: entering standby mode 2023-08-07 10:21:54.161 UTC [3132752] LOG: redo starts at 0/2000028 2023-08-07 10:21:54.161 UTC [3132752] WARNING: unexpected directory entry "16384" found in pg_tblspc/ 2023-08-07 10:21:54.161 UTC [3132752] DETAIL: All directory entries in pg_tblspc/ should be symbolic links. 2023-08-07 10:21:54.161 UTC [3132752] HINT: Remove those directories, or set allow_in_place_tablespaces to ON transiently to let recovery complete. 2023-08-07 10:21:54.161 UTC [3132752] LOG: consistent recovery state reached at 0/2000100 2023-08-07 10:21:54.161 UTC [3132749] LOG: database system is ready to accept read-only connections 2023-08-07 10:21:54.349 UTC [3132753] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2023-08-07 10:21:54.635 UTC [3132815] 031_recovery_conflict.pl LOG: statement: BEGIN; 2023-08-07 10:21:54.720 UTC [3132815] 031_recovery_conflict.pl LOG: statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT b FROM test_recovery_conflict_table1; 2023-08-07 10:21:54.721 UTC [3132815] 031_recovery_conflict.pl LOG: statement: FETCH FORWARD FROM test_recovery_conflict_cursor; 2023-08-07 10:21:54.733 UTC [3132815] 031_recovery_conflict.pl LOG: statement: ; 2023-08-07 10:21:54.941 UTC [3132752] LOG: recovery still waiting after 10.021 ms: recovery conflict on buffer pin 2023-08-07 10:21:54.941 UTC [3132752] CONTEXT: WAL redo at 0/342B1C0 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-07 10:21:55.000 UTC [3132815] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery 2023-08-07 10:21:55.000 UTC [3132815] 031_recovery_conflict.pl DETAIL: User was holding shared buffer pin for too long. 2023-08-07 10:21:55.000 UTC [3132815] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command. 2023-08-07 10:21:55.000 UTC [3132752] LOG: recovery finished waiting after 69.577 ms: recovery conflict on buffer pin 2023-08-07 10:21:55.000 UTC [3132752] CONTEXT: WAL redo at 0/342B1C0 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-07 10:21:55.222 UTC [3132913] 031_recovery_conflict.pl LOG: statement: SELECT confl_bufferpin FROM pg_stat_database_conflicts WHERE datname='test_db'; 2023-08-07 10:21:55.379 UTC [3132910] 031_recovery_conflict.pl LOG: statement: BEGIN; 2023-08-07 10:21:55.379 UTC [3132910] 031_recovery_conflict.pl LOG: statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT b FROM test_recovery_conflict_table1; 2023-08-07 10:21:55.380 UTC [3132910] 031_recovery_conflict.pl LOG: statement: FETCH FORWARD FROM test_recovery_conflict_cursor; 2023-08-07 10:21:55.381 UTC [3132910] 031_recovery_conflict.pl LOG: statement: ; 2023-08-07 10:21:55.460 UTC [3132752] LOG: recovery still waiting after 15.223 ms: recovery conflict on snapshot 2023-08-07 10:21:55.460 UTC [3132752] DETAIL: Conflicting process: 3132910. 2023-08-07 10:21:55.460 UTC [3132752] CONTEXT: WAL redo at 0/3433F00 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-07 10:21:55.508 UTC [3132910] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery 2023-08-07 10:21:55.508 UTC [3132910] 031_recovery_conflict.pl DETAIL: User query might have needed to see row versions that must be removed. 2023-08-07 10:21:55.508 UTC [3132910] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command. 2023-08-07 10:21:55.513 UTC [3132752] LOG: recovery finished waiting after 68.437 ms: recovery conflict on snapshot 2023-08-07 10:21:55.513 UTC [3132752] CONTEXT: WAL redo at 0/3433F00 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-07 10:21:56.182 UTC [3133010] 031_recovery_conflict.pl LOG: statement: SELECT confl_snapshot FROM pg_stat_database_conflicts WHERE datname='test_db'; 2023-08-07 10:21:56.187 UTC [3133007] 031_recovery_conflict.pl LOG: statement: BEGIN; 2023-08-07 10:21:56.187 UTC [3133007] 031_recovery_conflict.pl LOG: statement: LOCK TABLE test_recovery_conflict_table1 IN ACCESS SHARE MODE; 2023-08-07 10:21:56.187 UTC [3133007] 031_recovery_conflict.pl LOG: statement: SELECT 1; 2023-08-07 10:21:56.188 UTC [3133007] 031_recovery_conflict.pl LOG: statement: ; 2023-08-07 10:21:56.215 UTC [3132752] LOG: recovery still waiting after 10.705 ms: recovery conflict on lock 2023-08-07 10:21:56.215 UTC [3132752] DETAIL: Conflicting process: 3133007. 2023-08-07 10:21:56.215 UTC [3132752] CONTEXT: WAL redo at 0/34340F8 for Standby/LOCK: xid 739 db 16385 rel 16386 2023-08-07 10:21:56.262 UTC [3133007] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery 2023-08-07 10:21:56.262 UTC [3133007] 031_recovery_conflict.pl DETAIL: User was holding a relation lock for too long. 2023-08-07 10:21:56.262 UTC [3133007] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command. 2023-08-07 10:21:56.270 UTC [3132752] LOG: recovery finished waiting after 65.579 ms: recovery conflict on lock 2023-08-07 10:21:56.270 UTC [3132752] CONTEXT: WAL redo at 0/34340F8 for Standby/LOCK: xid 739 db 16385 rel 16386 2023-08-07 10:21:56.410 UTC [3133047] 031_recovery_conflict.pl LOG: statement: SELECT confl_lock FROM pg_stat_database_conflicts WHERE datname='test_db'; 2023-08-07 10:21:56.418 UTC [3133041] 031_recovery_conflict.pl LOG: statement: BEGIN; 2023-08-07 10:21:56.418 UTC [3133041] 031_recovery_conflict.pl LOG: statement: SET work_mem = '64kB'; 2023-08-07 10:21:56.418 UTC [3133041] 031_recovery_conflict.pl LOG: statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT count(*) FROM generate_series(1,6000); 2023-08-07 10:21:56.418 UTC [3133041] 031_recovery_conflict.pl LOG: statement: FETCH FORWARD FROM test_recovery_conflict_cursor; 2023-08-07 10:21:56.419 UTC [3133041] 031_recovery_conflict.pl LOG: statement: ; 2023-08-07 10:21:56.440 UTC [3132752] LOG: could not remove directory "pg_tblspc/16384/PG_17_202307261/pgsql_tmp": Directory not empty 2023-08-07 10:21:56.440 UTC [3132752] CONTEXT: WAL redo at 0/3434668 for Tablespace/DROP: 16384 2023-08-07 10:21:56.440 UTC [3132752] LOG: could not remove directory "pg_tblspc/16384/PG_17_202307261": Directory not empty 2023-08-07 10:21:56.440 UTC [3132752] CONTEXT: WAL redo at 0/3434668 for Tablespace/DROP: 16384 2023-08-07 10:21:56.455 UTC [3132752] LOG: recovery still waiting after 15.222 ms: recovery conflict on tablespace 2023-08-07 10:21:56.455 UTC [3132752] DETAIL: Conflicting process: 3133041. 2023-08-07 10:21:56.455 UTC [3132752] CONTEXT: WAL redo at 0/3434668 for Tablespace/DROP: 16384 2023-08-07 10:21:56.561 UTC [3133041] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery 2023-08-07 10:21:56.561 UTC [3133041] 031_recovery_conflict.pl DETAIL: User was or might have been using tablespace that must be dropped. 2023-08-07 10:21:56.561 UTC [3133041] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command. 2023-08-07 10:21:56.561 UTC [3133041] 031_recovery_conflict.pl LOG: temporary file: path "pg_tblspc/16384/PG_17_202307261/pgsql_tmp/pgsql_tmp3133041.0", size 84000 2023-08-07 10:21:56.566 UTC [3132752] LOG: recovery finished waiting after 125.361 ms: recovery conflict on tablespace 2023-08-07 10:21:56.566 UTC [3132752] CONTEXT: WAL redo at 0/3434668 for Tablespace/DROP: 16384 2023-08-07 10:21:57.074 UTC [3133136] 031_recovery_conflict.pl LOG: statement: SELECT confl_tablespace FROM pg_stat_database_conflicts WHERE datname='test_db'; 2023-08-07 10:21:57.279 UTC [3132749] LOG: received fast shutdown request 2023-08-07 10:21:57.279 UTC [3132749] LOG: aborting any active transactions 2023-08-07 10:21:57.279 UTC [3133128] 031_recovery_conflict.pl FATAL: terminating connection due to administrator command 2023-08-07 10:21:57.284 UTC [3132753] FATAL: terminating walreceiver process due to administrator command 2023-08-07 10:21:57.370 UTC [3132750] LOG: shutting down 2023-08-07 10:21:57.489 UTC [3132749] LOG: database system is shut down 2023-08-07 10:21:57.595 UTC [3133177] LOG: starting PostgreSQL 17devel (Debian 17~~devel-1) on s390x-ibm-linux-gnu, compiled by gcc (Debian 13.2.0-1) 13.2.0, 64-bit 2023-08-07 10:21:57.595 UTC [3133177] LOG: listening on Unix socket "/tmp/Ew0sehtBKm/.s.PGSQL.52787" 2023-08-07 10:21:57.604 UTC [3133180] LOG: database system was shut down in recovery at 2023-08-07 10:21:57 UTC 2023-08-07 10:21:57.604 UTC [3133180] LOG: entering standby mode 2023-08-07 10:21:57.605 UTC [3133180] LOG: redo starts at 0/2000028 2023-08-07 10:21:57.803 UTC [3133180] LOG: could not stat file "pg_tblspc/16384": No such file or directory 2023-08-07 10:21:57.803 UTC [3133180] CONTEXT: WAL redo at 0/3434668 for Tablespace/DROP: 16384 2023-08-07 10:21:57.803 UTC [3133180] LOG: consistent recovery state reached at 0/34346D0 2023-08-07 10:21:57.803 UTC [3133180] LOG: invalid record length at 0/34346D0: expected at least 24, got 0 2023-08-07 10:21:57.803 UTC [3133177] LOG: database system is ready to accept read-only connections 2023-08-07 10:21:57.809 UTC [3133188] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2023-08-07 10:21:58.225 UTC [3133215] 031_recovery_conflict.pl LOG: statement: BEGIN; 2023-08-07 10:21:58.225 UTC [3133215] 031_recovery_conflict.pl LOG: statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT a FROM test_recovery_conflict_table1; 2023-08-07 10:21:58.226 UTC [3133215] 031_recovery_conflict.pl LOG: statement: FETCH FORWARD FROM test_recovery_conflict_cursor; 2023-08-07 10:21:58.231 UTC [3133215] 031_recovery_conflict.pl LOG: statement: SELECT * FROM test_recovery_conflict_table2; 2023-08-07 10:21:58.252 UTC [3133247] 031_recovery_conflict.pl LOG: statement: SELECT 'waiting' FROM pg_locks WHERE locktype = 'relation' AND NOT granted; 2023-08-07 10:21:58.314 UTC [3133180] LOG: recovery still waiting after 10.016 ms: recovery conflict on buffer pin 2023-08-07 10:21:58.314 UTC [3133180] CONTEXT: WAL redo at 0/3437418 for Heap2/PRUNE: snapshotConflictHorizon: 0, nredirected: 0, ndead: 100, nunused: 0, redirected: [], dead: [2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101], unused: []; blkref #0: rel 1663/16385/16392, blk 0 2023-08-07 10:21:58.324 UTC [3133215] 031_recovery_conflict.pl ERROR: canceling statement due to conflict with recovery at character 15 2023-08-07 10:21:58.324 UTC [3133215] 031_recovery_conflict.pl DETAIL: User transaction caused buffer deadlock with recovery. 2023-08-07 10:21:58.324 UTC [3133215] 031_recovery_conflict.pl STATEMENT: SELECT * FROM test_recovery_conflict_table2; 2023-08-07 10:21:58.324 UTC [3133180] LOG: recovery finished waiting after 20.102 ms: recovery conflict on buffer pin 2023-08-07 10:21:58.324 UTC [3133180] CONTEXT: WAL redo at 0/3437418 for Heap2/PRUNE: snapshotConflictHorizon: 0, nredirected: 0, ndead: 100, nunused: 0, redirected: [], dead: [2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101], unused: []; blkref #0: rel 1663/16385/16392, blk 0 2023-08-07 10:21:58.455 UTC [3133284] 031_recovery_conflict.pl LOG: statement: SELECT confl_deadlock FROM pg_stat_database_conflicts WHERE datname='test_db'; 2023-08-07 10:21:58.502 UTC [3133177] LOG: received fast shutdown request 2023-08-07 10:21:58.502 UTC [3133177] LOG: aborting any active transactions 2023-08-07 10:21:58.504 UTC [3133188] FATAL: terminating walreceiver process due to administrator command 2023-08-07 10:21:58.507 UTC [3133282] 031_recovery_conflict.pl FATAL: terminating connection due to administrator command 2023-08-07 10:21:58.536 UTC [3133215] 031_recovery_conflict.pl FATAL: terminating connection due to administrator command 2023-08-07 10:21:58.536 UTC [3133215] 031_recovery_conflict.pl LOG: could not send data to client: Broken pipe 2023-08-07 10:21:58.543 UTC [3133178] LOG: shutting down 2023-08-07 10:21:58.545 UTC [3133177] LOG: database system is shut down 2023-08-07 10:21:58.618 UTC [3133299] LOG: starting PostgreSQL 17devel (Debian 17~~devel-1) on s390x-ibm-linux-gnu, compiled by gcc (Debian 13.2.0-1) 13.2.0, 64-bit 2023-08-07 10:21:58.618 UTC [3133299] LOG: listening on Unix socket "/tmp/Ew0sehtBKm/.s.PGSQL.52787" 2023-08-07 10:21:59.894 UTC [3133495] LOG: database system was shut down in recovery at 2023-08-07 10:21:58 UTC 2023-08-07 10:21:59.894 UTC [3133495] LOG: entering standby mode 2023-08-07 10:22:00.050 UTC [3133495] LOG: redo starts at 0/2000028 2023-08-07 10:22:00.066 UTC [3133495] LOG: could not stat file "pg_tblspc/16384": No such file or directory 2023-08-07 10:22:00.066 UTC [3133495] CONTEXT: WAL redo at 0/3434668 for Tablespace/DROP: 16384 2023-08-07 10:22:00.066 UTC [3133495] LOG: consistent recovery state reached at 0/343D850 2023-08-07 10:22:00.066 UTC [3133495] LOG: invalid record length at 0/343D850: expected at least 24, got 0 2023-08-07 10:22:00.068 UTC [3133299] LOG: database system is ready to accept read-only connections 2023-08-07 10:22:00.263 UTC [3133520] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2023-08-07 10:22:00.295 UTC [3133543] 031_recovery_conflict.pl LOG: statement: SELECT conflicts FROM pg_stat_database WHERE datname='test_db'; 2023-08-07 10:22:00.453 UTC [3133533] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery 2023-08-07 10:22:00.453 UTC [3133533] 031_recovery_conflict.pl DETAIL: User was connected to a database that must be dropped. 2023-08-07 10:22:00.453 UTC [3133533] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command. 2023-08-07 10:22:00.516 UTC [3133299] LOG: received fast shutdown request 2023-08-07 10:22:00.516 UTC [3133299] LOG: aborting any active transactions 2023-08-07 10:22:00.519 UTC [3133520] FATAL: terminating walreceiver process due to administrator command 2023-08-07 10:22:00.521 UTC [3133493] LOG: shutting down 2023-08-07 10:22:00.521 UTC [3133493] LOG: restartpoint starting: shutdown immediate 2023-08-07 10:22:00.521 UTC [3133493] LOG: restartpoint complete: wrote 4 buffers (3.1%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=20726 kB, estimate=20726 kB; lsn=0/343D970, redo lsn=0/343D938 2023-08-07 10:22:00.521 UTC [3133493] LOG: recovery restart point at 0/343D938 2023-08-07 10:22:00.521 UTC [3133493] DETAIL: Last completed transaction was at log time 2023-08-07 10:22:00.450184+00. 2023-08-07 10:22:00.523 UTC [3133299] LOG: database system is shut down