# Checking port 53739
# Found port 53739
Name: primary
Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_primary_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_primary_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_primary_data/archives
Connection string: port=53739 host=/tmp/qm7wv7pj30
Log file: /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/log/012_subtransactions_primary.log
[02:07:05.649](0.045s) # 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/012_subtransactions/data/t_012_subtransactions_primary_data/pgdata
# Running: /tmp/cirrus-ci-build/build/src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_primary_data/pgdata
### Starting node "primary"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_primary_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/log/012_subtransactions_primary.log -o --cluster-name=primary start
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 21298
# Taking pg_basebackup primary_backup from node "primary"
# Running: pg_basebackup -D /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_primary_data/backup/primary_backup -h /tmp/qm7wv7pj30 -p 53739 --checkpoint fast --no-sync
# Backup finished
# Checking port 53740
# Found port 53740
Name: standby
Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_standby_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_standby_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_standby_data/archives
Connection string: port=53740 host=/tmp/qm7wv7pj30
Log file: /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/log/012_subtransactions_standby.log
# Initializing node "standby" from backup "primary_backup" of node "primary"
### Enabling streaming replication for node "standby"
### Starting node "standby"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_standby_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/log/012_subtransactions_standby.log -o --cluster-name=standby start
waiting for server to start.... done
server started
# Postmaster PID for node "standby" is 21510
t
### Stopping node "primary" using mode fast
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_primary_data/pgdata -m fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "primary"
### Starting node "primary"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_primary_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/log/012_subtransactions_primary.log -o --cluster-name=primary start
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 21579
[02:07:08.043](2.394s) ok 1 - Check nextXid handling for prepared subtransactions

Waiting for replication conn standby's replay_lsn to pass 0/3025C88 on primary
done
[02:07:08.610](0.567s) ok 2 - Visible
### Stopping node "primary" using mode fast
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_primary_data/pgdata -m fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "primary"
### Promoting node "standby"
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_standby_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/log/012_subtransactions_standby.log promote
waiting for server to promote.... done
server promoted
[02:07:08.841](0.232s) ok 3 - Visible
### Enabling streaming replication for node "primary"
### Starting node "primary"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_primary_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/log/012_subtransactions_primary.log -o --cluster-name=primary start
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 21770
[02:07:08.992](0.150s) ok 4 - Visible

Waiting for replication conn primary's replay_lsn to pass 0/3033478 on standby
[02:10:40.155](211.163s) # poll_query_until timed out executing this query:
# SELECT '0/3033478' <= replay_lsn AND state = 'streaming'
#          FROM pg_catalog.pg_stat_replication
#          WHERE application_name IN ('primary', 'walreceiver')
# expecting this output:
# t
# last actual query output:
# 
# with stderr:
timed out waiting for catchup at /tmp/cirrus-ci-build/src/test/recovery/t/012_subtransactions.pl line 152.
# No postmaster PID for node "primary"
# Postmaster PID for node "standby" is 21510
### Stopping node "standby" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/012_subtransactions/data/t_012_subtransactions_standby_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "standby"
[02:10:40.260](0.105s) # Tests were run but no plan was declared and done_testing() was not seen.
[02:10:40.260](0.000s) # Looks like your test exited with 29 just after 4.