# Checking port 58430
# Found port 58430
Name: primary1_FILE_COPY
Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_FILE_COPY_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_FILE_COPY_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_FILE_COPY_data/archives
Connection string: port=58430 host=/tmp/ORrAtFY9C1
Log file: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_primary1_FILE_COPY.log
[14:37:59.383](0.019s) # initializing database system by copying initdb template
# Running: cp -RPp /tmp/cirrus-ci-build/build/tmp_install/initdb-template /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_FILE_COPY_data/pgdata
# Running: /tmp/cirrus-ci-build/build/src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_FILE_COPY_data/pgdata
### Starting node "primary1_FILE_COPY"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_FILE_COPY_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_primary1_FILE_COPY.log -o --cluster-name=primary1_FILE_COPY start
waiting for server to start.... done
server started
# Postmaster PID for node "primary1_FILE_COPY" is 30813
(slot,0/1521830)
# Taking pg_basebackup my_backup from node "primary1_FILE_COPY"
# Running: pg_basebackup -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_FILE_COPY_data/backup/my_backup -h /tmp/ORrAtFY9C1 -p 58430 --checkpoint fast --no-sync
# Backup finished
# Checking port 58431
# Found port 58431
Name: standby2_FILE_COPY
Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_FILE_COPY_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_FILE_COPY_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_FILE_COPY_data/archives
Connection string: port=58431 host=/tmp/ORrAtFY9C1
Log file: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_standby2_FILE_COPY.log
# Initializing node "standby2_FILE_COPY" from backup "my_backup" of node "primary1_FILE_COPY"
### Enabling streaming replication for node "standby2_FILE_COPY"
### Starting node "standby2_FILE_COPY"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_FILE_COPY_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_standby2_FILE_COPY.log -o --cluster-name=standby2_FILE_COPY start
waiting for server to start.... done
server started
# Postmaster PID for node "standby2_FILE_COPY" is 31026
Waiting for replication conn standby2_FILE_COPY's write_lsn to pass 0/3000000 on primary1_FILE_COPY
done
Waiting for replication conn standby2_FILE_COPY's write_lsn to pass 0/3024DC8 on primary1_FILE_COPY
done
### Stopping node "standby2_FILE_COPY" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_FILE_COPY_data/pgdata -m immediate stop
waiting for server to shut down... done
server stopped
# No postmaster PID for node "standby2_FILE_COPY"
### Starting node "standby2_FILE_COPY"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_FILE_COPY_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_standby2_FILE_COPY.log -o --cluster-name=standby2_FILE_COPY start
waiting for server to start........................................................................................................................... stopped waiting
pg_ctl: server did not start in time
# pg_ctl start failed; logfile:
2024-03-22 14:38:00.802 UTC [31026][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-linux, compiled by gcc-10.2.1, 64-bit
2024-03-22 14:38:00.802 UTC [31026][postmaster] LOG:  listening on Unix socket "/tmp/ORrAtFY9C1/.s.PGSQL.58431"
2024-03-22 14:38:00.827 UTC [31039][startup] LOG:  database system was interrupted; last known up at 2024-03-22 14:37:59 UTC
2024-03-22 14:38:00.828 UTC [31039][startup] LOG:  starting backup recovery with redo LSN 0/2000028, checkpoint LSN 0/2000080, on timeline ID 1
2024-03-22 14:38:00.828 UTC [31039][startup] LOG:  entering standby mode
2024-03-22 14:38:00.828 UTC [31039][startup] LOG:  redo starts at 0/2000028
2024-03-22 14:38:00.828 UTC [31039][startup] LOG:  completed backup recovery with redo LSN 0/2000028 and end LSN 0/2000120
2024-03-22 14:38:00.828 UTC [31039][startup] WARNING:  unexpected directory entry "16386" found in pg_tblspc/
2024-03-22 14:38:00.828 UTC [31039][startup] DETAIL:  All directory entries in pg_tblspc/ should be symbolic links.
2024-03-22 14:38:00.828 UTC [31039][startup] HINT:  Remove those directories, or set allow_in_place_tablespaces to ON transiently to let recovery complete.
2024-03-22 14:38:00.828 UTC [31039][startup] WARNING:  unexpected directory entry "16385" found in pg_tblspc/
2024-03-22 14:38:00.828 UTC [31039][startup] DETAIL:  All directory entries in pg_tblspc/ should be symbolic links.
2024-03-22 14:38:00.828 UTC [31039][startup] HINT:  Remove those directories, or set allow_in_place_tablespaces to ON transiently to let recovery complete.
2024-03-22 14:38:00.828 UTC [31039][startup] WARNING:  unexpected directory entry "16384" found in pg_tblspc/
2024-03-22 14:38:00.828 UTC [31039][startup] DETAIL:  All directory entries in pg_tblspc/ should be symbolic links.
2024-03-22 14:38:00.828 UTC [31039][startup] HINT:  Remove those directories, or set allow_in_place_tablespaces to ON transiently to let recovery complete.
2024-03-22 14:38:00.828 UTC [31039][startup] WARNING:  unexpected directory entry "16387" found in pg_tblspc/
2024-03-22 14:38:00.828 UTC [31039][startup] DETAIL:  All directory entries in pg_tblspc/ should be symbolic links.
2024-03-22 14:38:00.828 UTC [31039][startup] HINT:  Remove those directories, or set allow_in_place_tablespaces to ON transiently to let recovery complete.
2024-03-22 14:38:00.828 UTC [31039][startup] LOG:  consistent recovery state reached at 0/2000120
2024-03-22 14:38:00.831 UTC [31026][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-22 14:38:00.853 UTC [31044][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-22 14:38:01.912 UTC [31237][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 14:38:01.913 UTC [31237][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_FILE_COPY_data/pgdata/pg_hba.conf:117)
2024-03-22 14:38:01.913 UTC [31237][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=033_replay_tsp_drops.pl
2024-03-22 14:38:01.918 UTC [31237][client backend] [033_replay_tsp_drops.pl][0/2:0] LOG:  statement: ALTER SYSTEM SET log_min_messages TO debug1;
2024-03-22 14:38:01.980 UTC [31237][client backend] [033_replay_tsp_drops.pl][:0] LOG:  disconnection: session time: 0:00:00.069 user=postgres database=postgres host=[local]
2024-03-22 14:38:02.005 UTC [31026][postmaster] LOG:  received immediate shutdown request
2024-03-22 14:38:02.006 UTC [31026][postmaster] LOG:  database system is shut down
2024-03-22 14:38:02.047 UTC [31265][postmaster] DEBUG:  registering background worker "logical replication launcher"
2024-03-22 14:38:02.047 UTC [31265][postmaster] DEBUG:  mmap(6291456) with MAP_HUGETLB failed, huge pages disabled: Cannot allocate memory
2024-03-22 14:38:02.048 UTC [31265][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-linux, compiled by gcc-10.2.1, 64-bit
2024-03-22 14:38:02.048 UTC [31265][postmaster] LOG:  listening on Unix socket "/tmp/ORrAtFY9C1/.s.PGSQL.58431"
2024-03-22 14:38:02.075 UTC [31270][startup] LOG:  database system was interrupted while in recovery at log time 2024-03-22 14:37:59 UTC
2024-03-22 14:38:02.075 UTC [31270][startup] HINT:  If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
2024-03-22 14:38:02.075 UTC [31270][startup] DEBUG:  checkpoint record is at 0/2000080
2024-03-22 14:38:02.075 UTC [31270][startup] LOG:  entering standby mode
2024-03-22 14:38:02.075 UTC [31270][startup] DEBUG:  redo record is at 0/2000028; shutdown false
2024-03-22 14:38:02.075 UTC [31270][startup] DEBUG:  next transaction ID: 743; next OID: 24576
2024-03-22 14:38:02.075 UTC [31270][startup] DEBUG:  next MultiXactId: 1; next MultiXactOffset: 0
2024-03-22 14:38:02.075 UTC [31270][startup] DEBUG:  oldest unfrozen transaction ID: 730, in database 1
2024-03-22 14:38:02.075 UTC [31270][startup] DEBUG:  oldest MultiXactId: 1, in database 1
2024-03-22 14:38:02.075 UTC [31270][startup] DEBUG:  commit timestamp Xid oldest/newest: 0/0
2024-03-22 14:38:02.075 UTC [31270][startup] DEBUG:  transaction ID wrap limit is 2147484377, limited by database with OID 1
2024-03-22 14:38:02.075 UTC [31270][startup] DEBUG:  MultiXactId wrap limit is 2147483648, limited by database with OID 1
2024-03-22 14:38:02.076 UTC [31270][startup] DEBUG:  starting up replication slots
2024-03-22 14:38:02.076 UTC [31270][startup] DEBUG:  xmin required by slots: data 0, catalog 0
2024-03-22 14:38:02.076 UTC [31270][startup] DEBUG:  resetting unlogged relations: cleanup 1 init 0
2024-03-22 14:38:02.078 UTC [31270][startup] DEBUG:  initializing for hot standby
2024-03-22 14:38:02.078 UTC [31270][startup] LOG:  redo starts at 0/2000028
2024-03-22 14:38:02.081 UTC [31270][startup] DEBUG:  recovery snapshots are now enabled
2024-03-22 14:38:02.081 UTC [31270][startup] CONTEXT:  WAL redo at 0/2000048 for Standby/RUNNING_XACTS: nextXid 743 latestCompletedXid 742 oldestRunningXid 743
2024-03-22 14:38:02.081 UTC [31270][startup] DEBUG:  saw end-of-backup record for backup starting at 0/2000028, waiting for 0/0
2024-03-22 14:38:02.081 UTC [31270][startup] CONTEXT:  WAL redo at 0/20000F8 for XLOG/BACKUP_END: 0/2000028
2024-03-22 14:38:02.081 UTC [31270][startup] DEBUG:  waiting for all backends to process ProcSignalBarrier generation 1
2024-03-22 14:38:02.081 UTC [31270][startup] CONTEXT:  WAL redo at 0/3000660 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16384/16389
2024-03-22 14:38:02.081 UTC [31270][startup] DEBUG:  finished waiting for all backends to process ProcSignalBarrier generation 1
2024-03-22 14:38:02.081 UTC [31270][startup] CONTEXT:  WAL redo at 0/3000660 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16384/16389
2024-03-22 14:38:02.097 UTC [31270][startup] DEBUG:  waiting for all backends to process ProcSignalBarrier generation 2
2024-03-22 14:38:02.097 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:07.101 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:07.101 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:12.101 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:12.101 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:17.105 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:17.105 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:22.105 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:22.105 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:27.109 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:27.109 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:32.115 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:32.115 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:37.117 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:37.117 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:42.117 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:42.117 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:47.121 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:47.121 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:52.121 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:52.121 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:38:57.125 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:38:57.125 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:02.125 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:02.125 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:07.129 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:07.129 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:12.129 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:12.129 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:17.134 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:17.134 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:22.134 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:22.134 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:27.137 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:27.137 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:32.137 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:32.137 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:37.141 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:37.141 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:42.142 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:42.142 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:47.145 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:47.145 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:52.146 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:52.146 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:39:57.151 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:39:57.151 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
2024-03-22 14:40:02.152 UTC [31270][startup] LOG:  still waiting for backend with PID 31269 to accept ProcSignalBarrier
2024-03-22 14:40:02.152 UTC [31270][startup] CONTEXT:  WAL redo at 0/3019F00 for Database/CREATE_FILE_COPY: copy dir 1663/1 to 16385/16393
# Postmaster PID for node "standby2_FILE_COPY" is 31265
[14:40:02.295](122.912s) not ok 1 - standby node started for FILE_COPY
[14:40:02.295](0.000s) #   Failed test 'standby node started for FILE_COPY'
#   at /tmp/cirrus-ci-build/src/test/recovery/t/033_replay_tsp_drops.pl line 73.
[14:40:02.295](0.000s) #          got: '0'
#     expected: '1'
### Stopping node "standby2_FILE_COPY" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_FILE_COPY_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "standby2_FILE_COPY"
# Checking port 58432
# Found port 58432
Name: primary1_WAL_LOG
Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_WAL_LOG_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_WAL_LOG_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_WAL_LOG_data/archives
Connection string: port=58432 host=/tmp/ORrAtFY9C1
Log file: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_primary1_WAL_LOG.log
[14:40:02.401](0.106s) # initializing database system by copying initdb template
# Running: cp -RPp /tmp/cirrus-ci-build/build/tmp_install/initdb-template /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_WAL_LOG_data/pgdata
# Running: /tmp/cirrus-ci-build/build/src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_WAL_LOG_data/pgdata
### Starting node "primary1_WAL_LOG"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_WAL_LOG_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_primary1_WAL_LOG.log -o --cluster-name=primary1_WAL_LOG start
waiting for server to start.... done
server started
# Postmaster PID for node "primary1_WAL_LOG" is 57896
(slot,0/1521830)
# Taking pg_basebackup my_backup from node "primary1_WAL_LOG"
# Running: pg_basebackup -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_WAL_LOG_data/backup/my_backup -h /tmp/ORrAtFY9C1 -p 58432 --checkpoint fast --no-sync
# Backup finished
# Checking port 58433
# Found port 58433
Name: standby2_WAL_LOG
Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_WAL_LOG_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_WAL_LOG_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_WAL_LOG_data/archives
Connection string: port=58433 host=/tmp/ORrAtFY9C1
Log file: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_standby2_WAL_LOG.log
# Initializing node "standby2_WAL_LOG" from backup "my_backup" of node "primary1_WAL_LOG"
### Enabling streaming replication for node "standby2_WAL_LOG"
### Starting node "standby2_WAL_LOG"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_WAL_LOG_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_standby2_WAL_LOG.log -o --cluster-name=standby2_WAL_LOG start
waiting for server to start.... done
server started
# Postmaster PID for node "standby2_WAL_LOG" is 57913
Waiting for replication conn standby2_WAL_LOG's write_lsn to pass 0/3000000 on primary1_WAL_LOG
done
Waiting for replication conn standby2_WAL_LOG's write_lsn to pass 0/412A820 on primary1_WAL_LOG
done
### Stopping node "standby2_WAL_LOG" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_WAL_LOG_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "standby2_WAL_LOG"
### Starting node "standby2_WAL_LOG"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_WAL_LOG_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_standby2_WAL_LOG.log -o --cluster-name=standby2_WAL_LOG start
waiting for server to start.... done
server started
# Postmaster PID for node "standby2_WAL_LOG" is 57939
[14:40:03.363](0.961s) ok 2 - standby node started for WAL_LOG
### Stopping node "standby2_WAL_LOG" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby2_WAL_LOG_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "standby2_WAL_LOG"
# Checking port 58434
# Found port 58434
Name: primary2
Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary2_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary2_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary2_data/archives
Connection string: port=58434 host=/tmp/ORrAtFY9C1
Log file: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_primary2.log
[14:40:03.469](0.107s) # initializing database system by copying initdb template
# Running: cp -RPp /tmp/cirrus-ci-build/build/tmp_install/initdb-template /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary2_data/pgdata
# Running: /tmp/cirrus-ci-build/build/src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary2_data/pgdata
### Starting node "primary2"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary2_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_primary2.log -o --cluster-name=primary2 start
waiting for server to start.... done
server started
# Postmaster PID for node "primary2" is 57952
# Taking pg_basebackup my_backup from node "primary2"
# Running: pg_basebackup -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary2_data/backup/my_backup -h /tmp/ORrAtFY9C1 -p 58434 --checkpoint fast --no-sync
# Backup finished
# Checking port 58435
# Found port 58435
Name: standby3
Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby3_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby3_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby3_data/archives
Connection string: port=58435 host=/tmp/ORrAtFY9C1
Log file: /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_standby3.log
# Initializing node "standby3" from backup "my_backup" of node "primary2"
### Enabling streaming replication for node "standby3"
### Starting node "standby3"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby3_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/log/033_replay_tsp_drops_standby3.log -o --cluster-name=standby3 start
waiting for server to start.... done
server started
# Postmaster PID for node "standby3" is 57971
[14:40:04.046](0.576s) ok 3 - invalid directory creation is detected
[14:40:04.046](0.000s) 1..3
### Stopping node "primary1_FILE_COPY" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_FILE_COPY_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "primary1_FILE_COPY"
### Stopping node "primary1_WAL_LOG" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary1_WAL_LOG_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "primary1_WAL_LOG"
### Stopping node "primary2" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_primary2_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "primary2"
### Stopping node "standby3" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/033_replay_tsp_drops/data/t_033_replay_tsp_drops_standby3_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "standby3"
[14:40:04.460](0.414s) # Looks like you failed 1 test of 3.