# Checking port 22393
# Found port 22393
Name: publisher
Version: 19devel
Data directory: /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/pgdata
Backup directory: /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/backup
Archive directory: /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/archives
Connection string: port=22393 host=/tmp/aAN_4ud0p0
Log file: /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_publisher.log
[00:22:16.220](0.048s) # initializing database system by copying initdb template
# Running: cp -RPp /home/postgres/postgres/build/tmp_install/initdb-template /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/pgdata
# Running: /home/postgres/postgres/build/src/test/regress/pg_regress --config-auth /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/pgdata
### Starting node "publisher"
# Running: pg_ctl --wait --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/pgdata --log /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_publisher.log --options --cluster-name=publisher start
waiting for server to start.... done
server started
# Postmaster PID for node "publisher" is 25220
# Checking port 22394
# Found port 22394
Name: subscriber
Version: 19devel
Data directory: /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata
Backup directory: /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/backup
Archive directory: /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/archives
Connection string: port=22394 host=/tmp/aAN_4ud0p0
Log file: /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_subscriber.log
[00:22:16.978](0.758s) # initializing database system by copying initdb template
# Running: cp -RPp /home/postgres/postgres/build/tmp_install/initdb-template /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata
# Running: /home/postgres/postgres/build/src/test/regress/pg_regress --config-auth /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata
### Starting node "subscriber"
# Running: pg_ctl --wait --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata --log /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_subscriber.log --options --cluster-name=subscriber start
waiting for server to start.... done
server started
# Postmaster PID for node "subscriber" is 13363
#### Begin standard error
psql:<stdin>:5: NOTICE:  created replication slot "tap_sub" on publisher
#### End standard error
Waiting for all subscriptions in "subscriber" to synchronize data
Waiting for replication conn tap_sub's replay_lsn to pass 0/017BD4B0 on publisher
done
done
[00:22:20.015](3.037s) ok 1 - check initial data was copied to subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017BD8D8 on publisher
done
[00:22:20.440](0.425s) ok 2 - transaction is prepared on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017BD920 on publisher
done
[00:22:20.723](0.282s) ok 3 - Rows inserted by 2PC have committed on subscriber, and extra columns contain local defaults
[00:22:20.833](0.110s) ok 4 - transaction is committed on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017BDDF8 on publisher
done
[00:22:21.332](0.499s) ok 5 - transaction is prepared on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017BDE40 on publisher
done
[00:22:21.620](0.289s) ok 6 - Rows inserted by 2PC are rolled back, leaving only the original 2 rows
[00:22:21.670](0.049s) ok 7 - transaction is aborted on subscriber
### Stopping node "subscriber" using mode immediate
# Running: pg_ctl --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata --mode immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "subscriber"
### Stopping node "publisher" using mode immediate
# Running: pg_ctl --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/pgdata --mode immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "publisher"
### Starting node "publisher"
# Running: pg_ctl --wait --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/pgdata --log /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_publisher.log --options --cluster-name=publisher start
waiting for server to start.... done
server started
# Postmaster PID for node "publisher" is 59924
### Starting node "subscriber"
# Running: pg_ctl --wait --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata --log /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_subscriber.log --options --cluster-name=subscriber start
waiting for server to start.... done
server started
# Postmaster PID for node "subscriber" is 82009
Waiting for replication conn tap_sub's replay_lsn to pass 0/017C2A60 on publisher
done
[00:22:23.403](1.733s) ok 8 - Rows inserted by 2PC have committed on subscriber, and extra columns contain local defaults
Waiting for replication conn tap_sub's replay_lsn to pass 0/017C4B48 on publisher
done
[00:22:23.842](0.439s) ok 9 - transaction is prepared on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017C4C48 on publisher
done
[00:22:24.397](0.554s) ok 10 - check the outside insert was copied to subscriber
[00:22:24.489](0.093s) ok 11 - transaction is aborted on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017C50E0 on publisher
done
[00:22:24.893](0.404s) ok 12 - transaction is prepared on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017C51E0 on publisher
done
[00:22:25.425](0.531s) ok 13 - Rows inserted by 2PC (as well as outside insert) have committed on subscriber, and extra columns contain local defaults
[00:22:25.466](0.041s) ok 14 - transaction is committed on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017C52D0 on publisher
done
### Reloading node "subscriber"
# Running: pg_ctl --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata reload
server signaled
Waiting for replication conn tap_sub's replay_lsn to pass 0/017C56F8 on publisher
done
[00:22:26.466](1.000s) ok 15 - transaction is prepared on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017C5740 on publisher
done
[00:22:27.004](0.539s) ok 16 - Rows inserted by 2PC have committed on subscriber, and extra columns contain local defaults
[00:22:27.076](0.072s) ok 17 - transaction is committed on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017C5C18 on publisher
done
[00:22:27.369](0.293s) ok 18 - transaction is prepared on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017C5C60 on publisher
done
[00:22:27.629](0.260s) ok 19 - Rows inserted by 2PC are rolled back, leaving only the original 2 rows
[00:22:27.709](0.081s) ok 20 - transaction is aborted on subscriber
### Stopping node "subscriber" using mode immediate
# Running: pg_ctl --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata --mode immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "subscriber"
### Stopping node "publisher" using mode immediate
# Running: pg_ctl --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/pgdata --mode immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "publisher"
### Starting node "publisher"
# Running: pg_ctl --wait --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/pgdata --log /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_publisher.log --options --cluster-name=publisher start
waiting for server to start.... done
server started
# Postmaster PID for node "publisher" is 92131
### Starting node "subscriber"
# Running: pg_ctl --wait --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata --log /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_subscriber.log --options --cluster-name=subscriber start
waiting for server to start.... done
server started
# Postmaster PID for node "subscriber" is 9096
Waiting for replication conn tap_sub's replay_lsn to pass 0/017CA198 on publisher
done
[00:22:29.785](2.076s) ok 21 - Rows inserted by 2PC have committed on subscriber, and extra columns contain local defaults
Waiting for replication conn tap_sub's replay_lsn to pass 0/017CC978 on publisher
done
[00:22:30.482](0.697s) ok 22 - transaction is prepared on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017CCA78 on publisher
done
[00:22:30.967](0.485s) ok 23 - check the outside insert was copied to subscriber
[00:22:31.053](0.086s) ok 24 - transaction is aborted on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017CCF10 on publisher
done
[00:22:32.141](1.088s) ok 25 - transaction is prepared on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017CD010 on publisher
done
[00:22:32.888](0.747s) ok 26 - Rows inserted by 2PC (as well as outside insert) have committed on subscriber, and extra columns contain local defaults
[00:22:32.941](0.053s) ok 27 - transaction is committed on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017CD100 on publisher
done
### Reloading node "subscriber"
# Running: pg_ctl --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata reload
server signaled
Waiting for replication conn tap_sub's replay_lsn to pass 0/017CD238 on publisher
done
[00:22:34.841](1.900s) ok 28 - transaction is prepared on subscriber
Waiting for replication conn tap_sub's replay_lsn to pass 0/017CD270 on publisher
done
[00:22:35.260](0.419s) ok 29 - transaction is committed on subscriber
### Restarting node "subscriber"
# Running: pg_ctl --wait --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata --log /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_subscriber.log restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "subscriber" is 32727
[00:25:55.072](199.812s) # die: timed out waiting for file /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_subscriber.log contents to match: (?^:ERROR: .*logical replication parallel apply worker.*) at /home/postgres/postgres/src/test/subscription/t/023_twophase_stream.pl line 461.
[00:25:55.072](0.001s) 1..29
timed out waiting for file /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/log/023_twophase_stream_subscriber.log contents to match: (?^:ERROR: .*logical replication parallel apply worker.*) at /home/postgres/postgres/src/test/subscription/t/023_twophase_stream.pl line 461.
# Postmaster PID for node "publisher" is 92131
### Stopping node "publisher" using mode immediate
# Running: pg_ctl --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_publisher_data/pgdata --mode immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "publisher"
# Postmaster PID for node "subscriber" is 32727
### Stopping node "subscriber" using mode immediate
# Running: pg_ctl --pgdata /home/postgres/postgres/build/testrun/subscription/023_twophase_stream/data/t_023_twophase_stream_subscriber_data/pgdata --mode immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "subscriber"
[00:25:55.314](0.242s) # Looks like your test exited with 255 just after 29.