031_recovery_conflict_standby.log
text/plain
Filename: 031_recovery_conflict_standby.log
Type: text/plain
Part: 1
2023-08-06 17:20:51.002 UTC [1274900] 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-06 17:20:51.002 UTC [1274900] LOG: listening on Unix socket "/tmp/N8KG4BCXAf/.s.PGSQL.53739" 2023-08-06 17:20:51.503 UTC [1274938] LOG: database system was interrupted; last known up at 2023-08-06 17:20:35 UTC 2023-08-06 17:20:51.503 UTC [1274938] LOG: entering standby mode 2023-08-06 17:20:51.792 UTC [1274938] LOG: redo starts at 0/2000028 2023-08-06 17:20:51.793 UTC [1274938] WARNING: unexpected directory entry "16384" found in pg_tblspc/ 2023-08-06 17:20:51.793 UTC [1274938] DETAIL: All directory entries in pg_tblspc/ should be symbolic links. 2023-08-06 17:20:51.793 UTC [1274938] HINT: Remove those directories, or set allow_in_place_tablespaces to ON transiently to let recovery complete. 2023-08-06 17:20:51.793 UTC [1274938] LOG: consistent recovery state reached at 0/2000100 2023-08-06 17:20:51.797 UTC [1274900] LOG: database system is ready to accept read-only connections 2023-08-06 17:20:52.558 UTC [1274942] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2023-08-06 17:21:06.994 UTC [1275199] 031_recovery_conflict.pl LOG: statement: BEGIN; 2023-08-06 17:21:06.994 UTC [1275199] 031_recovery_conflict.pl LOG: statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT b FROM test_recovery_conflict_table1; 2023-08-06 17:21:07.025 UTC [1275199] 031_recovery_conflict.pl LOG: statement: FETCH FORWARD FROM test_recovery_conflict_cursor; 2023-08-06 17:21:07.030 UTC [1275199] 031_recovery_conflict.pl LOG: statement: ; 2023-08-06 17:21:07.165 UTC [1274938] LOG: recovery still waiting after 13.616 ms: recovery conflict on buffer pin 2023-08-06 17:21:07.165 UTC [1274938] CONTEXT: WAL redo at 0/3429C88 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-06 17:21:07.209 UTC [1275199] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery 2023-08-06 17:21:07.209 UTC [1275199] 031_recovery_conflict.pl DETAIL: User was holding shared buffer pin for too long. 2023-08-06 17:21:07.209 UTC [1275199] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command. 2023-08-06 17:21:07.211 UTC [1274938] LOG: recovery finished waiting after 59.737 ms: recovery conflict on buffer pin 2023-08-06 17:21:07.211 UTC [1274938] CONTEXT: WAL redo at 0/3429C88 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-06 17:21:08.456 UTC [1275250] 031_recovery_conflict.pl LOG: statement: SELECT confl_bufferpin FROM pg_stat_database_conflicts WHERE datname='test_db'; 2023-08-06 17:21:09.237 UTC [1275248] 031_recovery_conflict.pl LOG: statement: BEGIN; 2023-08-06 17:21:09.243 UTC [1275248] 031_recovery_conflict.pl LOG: statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT b FROM test_recovery_conflict_table1; 2023-08-06 17:21:09.249 UTC [1275248] 031_recovery_conflict.pl LOG: statement: FETCH FORWARD FROM test_recovery_conflict_cursor; 2023-08-06 17:21:09.249 UTC [1275248] 031_recovery_conflict.pl LOG: statement: ; 2023-08-06 17:21:10.024 UTC [1274938] LOG: recovery still waiting after 11.501 ms: recovery conflict on snapshot 2023-08-06 17:21:10.024 UTC [1274938] DETAIL: Conflicting process: 1275248. 2023-08-06 17:21:10.024 UTC [1274938] CONTEXT: WAL redo at 0/3432A18 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-06 17:21:10.093 UTC [1275248] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery 2023-08-06 17:21:10.093 UTC [1275248] 031_recovery_conflict.pl DETAIL: User query might have needed to see row versions that must be removed. 2023-08-06 17:21:10.093 UTC [1275248] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command. 2023-08-06 17:21:10.098 UTC [1274938] LOG: recovery finished waiting after 86.119 ms: recovery conflict on snapshot 2023-08-06 17:21:10.098 UTC [1274938] CONTEXT: WAL redo at 0/3432A18 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-06 17:21:10.238 UTC [1275290] 031_recovery_conflict.pl LOG: statement: SELECT confl_snapshot FROM pg_stat_database_conflicts WHERE datname='test_db'; 2023-08-06 17:21:10.250 UTC [1275288] 031_recovery_conflict.pl LOG: statement: BEGIN; 2023-08-06 17:21:10.255 UTC [1275288] 031_recovery_conflict.pl LOG: statement: LOCK TABLE test_recovery_conflict_table1 IN ACCESS SHARE MODE; 2023-08-06 17:21:10.260 UTC [1275288] 031_recovery_conflict.pl LOG: statement: SELECT 1; 2023-08-06 17:21:10.263 UTC [1275288] 031_recovery_conflict.pl LOG: statement: ; 2023-08-06 17:21:10.586 UTC [1274938] LOG: recovery still waiting after 11.288 ms: recovery conflict on lock 2023-08-06 17:21:10.586 UTC [1274938] DETAIL: Conflicting process: 1275288. 2023-08-06 17:21:10.586 UTC [1274938] CONTEXT: WAL redo at 0/3432BF8 for Standby/LOCK: xid 739 db 16385 rel 16386 2023-08-06 17:21:10.625 UTC [1275288] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery 2023-08-06 17:21:10.625 UTC [1275288] 031_recovery_conflict.pl DETAIL: User was holding a relation lock for too long. 2023-08-06 17:21:10.625 UTC [1275288] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command. 2023-08-06 17:21:10.661 UTC [1274938] LOG: recovery finished waiting after 85.925 ms: recovery conflict on lock 2023-08-06 17:21:10.661 UTC [1274938] CONTEXT: WAL redo at 0/3432BF8 for Standby/LOCK: xid 739 db 16385 rel 16386 2023-08-06 17:21:11.058 UTC [1275322] 031_recovery_conflict.pl LOG: statement: SELECT confl_lock FROM pg_stat_database_conflicts WHERE datname='test_db'; 2023-08-06 17:21:11.149 UTC [1275319] 031_recovery_conflict.pl LOG: statement: BEGIN; 2023-08-06 17:21:11.152 UTC [1275319] 031_recovery_conflict.pl LOG: statement: SET work_mem = '64kB'; 2023-08-06 17:21:11.155 UTC [1275319] 031_recovery_conflict.pl LOG: statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT count(*) FROM generate_series(1,6000); 2023-08-06 17:21:11.199 UTC [1275319] 031_recovery_conflict.pl LOG: statement: FETCH FORWARD FROM test_recovery_conflict_cursor; 2023-08-06 17:21:11.232 UTC [1275319] 031_recovery_conflict.pl LOG: statement: ; 2023-08-06 17:21:11.532 UTC [1274938] LOG: could not remove directory "pg_tblspc/16384/PG_17_202307261/pgsql_tmp": Directory not empty 2023-08-06 17:21:11.532 UTC [1274938] CONTEXT: WAL redo at 0/3433168 for Tablespace/DROP: 16384 2023-08-06 17:21:11.535 UTC [1274938] LOG: could not remove directory "pg_tblspc/16384/PG_17_202307261": Directory not empty 2023-08-06 17:21:11.535 UTC [1274938] CONTEXT: WAL redo at 0/3433168 for Tablespace/DROP: 16384 2023-08-06 17:21:11.546 UTC [1274938] LOG: recovery still waiting after 10.877 ms: recovery conflict on tablespace 2023-08-06 17:21:11.546 UTC [1274938] DETAIL: Conflicting process: 1275319. 2023-08-06 17:21:11.546 UTC [1274938] CONTEXT: WAL redo at 0/3433168 for Tablespace/DROP: 16384 2023-08-06 17:21:11.588 UTC [1275319] 031_recovery_conflict.pl FATAL: terminating connection due to conflict with recovery 2023-08-06 17:21:11.588 UTC [1275319] 031_recovery_conflict.pl DETAIL: User was or might have been using tablespace that must be dropped. 2023-08-06 17:21:11.588 UTC [1275319] 031_recovery_conflict.pl HINT: In a moment you should be able to reconnect to the database and repeat your command. 2023-08-06 17:21:11.614 UTC [1275319] 031_recovery_conflict.pl LOG: temporary file: path "pg_tblspc/16384/PG_17_202307261/pgsql_tmp/pgsql_tmp1275319.0", size 84000 2023-08-06 17:21:11.615 UTC [1274938] LOG: recovery finished waiting after 79.143 ms: recovery conflict on tablespace 2023-08-06 17:21:11.615 UTC [1274938] CONTEXT: WAL redo at 0/3433168 for Tablespace/DROP: 16384 2023-08-06 17:21:11.798 UTC [1275362] 031_recovery_conflict.pl LOG: statement: SELECT confl_tablespace FROM pg_stat_database_conflicts WHERE datname='test_db'; 2023-08-06 17:21:12.060 UTC [1274900] LOG: received fast shutdown request 2023-08-06 17:21:12.060 UTC [1274900] LOG: aborting any active transactions 2023-08-06 17:21:12.060 UTC [1274942] FATAL: terminating walreceiver process due to administrator command 2023-08-06 17:21:12.064 UTC [1275360] 031_recovery_conflict.pl FATAL: terminating connection due to administrator command 2023-08-06 17:21:12.106 UTC [1274936] LOG: shutting down 2023-08-06 17:21:12.131 UTC [1274900] LOG: database system is shut down 2023-08-06 17:21:14.807 UTC [1275376] 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-06 17:21:14.807 UTC [1275376] LOG: listening on Unix socket "/tmp/N8KG4BCXAf/.s.PGSQL.53739" 2023-08-06 17:21:15.133 UTC [1275421] LOG: database system was shut down in recovery at 2023-08-06 17:21:12 UTC 2023-08-06 17:21:15.133 UTC [1275421] LOG: entering standby mode 2023-08-06 17:21:15.333 UTC [1275421] LOG: redo starts at 0/2000028 2023-08-06 17:21:15.992 UTC [1275421] LOG: could not stat file "pg_tblspc/16384": No such file or directory 2023-08-06 17:21:15.992 UTC [1275421] CONTEXT: WAL redo at 0/3433168 for Tablespace/DROP: 16384 2023-08-06 17:21:15.992 UTC [1275421] LOG: consistent recovery state reached at 0/34331D0 2023-08-06 17:21:16.007 UTC [1275421] LOG: invalid record length at 0/34331D0: expected at least 24, got 0 2023-08-06 17:21:16.007 UTC [1275376] LOG: database system is ready to accept read-only connections 2023-08-06 17:21:16.100 UTC [1275429] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2023-08-06 17:21:19.206 UTC [1275437] 031_recovery_conflict.pl LOG: statement: BEGIN; 2023-08-06 17:21:19.206 UTC [1275437] 031_recovery_conflict.pl LOG: statement: DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT a FROM test_recovery_conflict_table1; 2023-08-06 17:21:19.337 UTC [1275437] 031_recovery_conflict.pl LOG: statement: FETCH FORWARD FROM test_recovery_conflict_cursor; 2023-08-06 17:21:19.345 UTC [1275437] 031_recovery_conflict.pl LOG: statement: SELECT * FROM test_recovery_conflict_table2; 2023-08-06 17:21:20.067 UTC [1275482] 031_recovery_conflict.pl LOG: statement: SELECT 'waiting' FROM pg_locks WHERE locktype = 'relation' AND NOT granted; 2023-08-06 17:21:21.357 UTC [1275437] 031_recovery_conflict.pl ERROR: canceling statement due to conflict with recovery at character 15 2023-08-06 17:21:21.357 UTC [1275437] 031_recovery_conflict.pl DETAIL: User transaction caused buffer deadlock with recovery. 2023-08-06 17:21:21.357 UTC [1275437] 031_recovery_conflict.pl STATEMENT: SELECT * FROM test_recovery_conflict_table2; 2023-08-06 17:21:21.664 UTC [1275511] 031_recovery_conflict.pl LOG: statement: SELECT confl_deadlock FROM pg_stat_database_conflicts WHERE datname='test_db'; 2023-08-06 17:21:21.843 UTC [1275376] LOG: received fast shutdown request 2023-08-06 17:21:21.843 UTC [1275376] LOG: aborting any active transactions 2023-08-06 17:21:21.847 UTC [1275429] FATAL: terminating walreceiver process due to administrator command 2023-08-06 17:21:21.851 UTC [1275509] 031_recovery_conflict.pl FATAL: terminating connection due to administrator command 2023-08-06 17:21:21.855 UTC [1275419] LOG: shutting down 2023-08-06 17:21:21.857 UTC [1275376] LOG: database system is shut down 2023-08-06 17:21:21.907 UTC [1275517] 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-06 17:21:21.907 UTC [1275517] LOG: listening on Unix socket "/tmp/N8KG4BCXAf/.s.PGSQL.53739" 2023-08-06 17:21:21.910 UTC [1275520] LOG: database system was shut down in recovery at 2023-08-06 17:21:21 UTC 2023-08-06 17:21:21.910 UTC [1275520] LOG: entering standby mode 2023-08-06 17:21:21.911 UTC [1275520] LOG: redo starts at 0/2000028 2023-08-06 17:21:22.193 UTC [1275520] LOG: could not stat file "pg_tblspc/16384": No such file or directory 2023-08-06 17:21:22.193 UTC [1275520] CONTEXT: WAL redo at 0/3433168 for Tablespace/DROP: 16384 2023-08-06 17:21:22.193 UTC [1275520] LOG: consistent recovery state reached at 0/343C368 2023-08-06 17:21:22.193 UTC [1275520] LOG: invalid record length at 0/343C368: expected at least 24, got 0 2023-08-06 17:21:22.198 UTC [1275517] LOG: database system is ready to accept read-only connections 2023-08-06 17:21:22.578 UTC [1275544] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2023-08-06 17:21:22.824 UTC [1275558] 031_recovery_conflict.pl LOG: statement: SELECT conflicts FROM pg_stat_database WHERE datname='test_db'; 2023-08-06 17:21:24.078 UTC [1275555] 031_recovery_conflict.pl FATAL: unrecognized conflict mode: 7 2023-08-06 17:24:31.466 UTC [1275544] 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-06 17:24:31.532 UTC [1275517] LOG: received immediate shutdown request 2023-08-06 17:24:31.608 UTC [1275517] LOG: database system is shut down