# Checking port 58477
# Found port 58477
Name: node_A
Data directory: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_A_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_A_data/backup
Archive directory: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_A_data/archives
Connection string: port=58477 host=/tmp/fmqn_pMS69
Log file: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/log/022_twophase_cascade_node_A.log
[10:48:03.239](0.014s) # initializing database system by copying initdb template
# Running: cp -RPp /tmp/cirrus-ci-build/tmp_install/initdb-template /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_A_data/pgdata
# Running: /tmp/cirrus-ci-build/src/test/subscription/../../../src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_A_data/pgdata
### Starting node "node_A"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_A_data/pgdata -l /tmp/cirrus-ci-build/src/test/subscription/tmp_check/log/022_twophase_cascade_node_A.log -o --cluster-name=node_A start
waiting for server to start.... done
server started
# Postmaster PID for node "node_A" is 42592
# Checking port 58478
# Found port 58478
Name: node_B
Data directory: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_B_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_B_data/backup
Archive directory: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_B_data/archives
Connection string: port=58478 host=/tmp/fmqn_pMS69
Log file: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/log/022_twophase_cascade_node_B.log
[10:48:03.423](0.185s) # initializing database system by copying initdb template
# Running: cp -RPp /tmp/cirrus-ci-build/tmp_install/initdb-template /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_B_data/pgdata
# Running: /tmp/cirrus-ci-build/src/test/subscription/../../../src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_B_data/pgdata
### Starting node "node_B"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_B_data/pgdata -l /tmp/cirrus-ci-build/src/test/subscription/tmp_check/log/022_twophase_cascade_node_B.log -o --cluster-name=node_B start
waiting for server to start.... done
server started
# Postmaster PID for node "node_B" is 42624
# Checking port 58479
# Found port 58479
Name: node_C
Data directory: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_C_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_C_data/backup
Archive directory: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_C_data/archives
Connection string: port=58479 host=/tmp/fmqn_pMS69
Log file: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/log/022_twophase_cascade_node_C.log
[10:48:03.607](0.183s) # initializing database system by copying initdb template
# Running: cp -RPp /tmp/cirrus-ci-build/tmp_install/initdb-template /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_C_data/pgdata
# Running: /tmp/cirrus-ci-build/src/test/subscription/../../../src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_C_data/pgdata
### Starting node "node_C"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_C_data/pgdata -l /tmp/cirrus-ci-build/src/test/subscription/tmp_check/log/022_twophase_cascade_node_C.log -o --cluster-name=node_C start
waiting for server to start.... done
server started
# Postmaster PID for node "node_C" is 42661
#### Begin standard error
psql:<stdin>:5: NOTICE:  created replication slot "tap_sub_b" on publisher
#### End standard error
#### Begin standard error
psql:<stdin>:5: NOTICE:  created replication slot "tap_sub_c" on publisher
#### End standard error
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1554EF8 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1557588 on node_B
done
[10:48:04.254](0.647s) ok 1 - Cascade setup is complete
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1555080 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1557710 on node_B
done
[10:48:04.369](0.115s) ok 2 - transaction is prepared on subscriber B
[10:48:04.385](0.017s) ok 3 - transaction is prepared on subscriber C
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/15550D0 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1557710 on node_B
done
[10:48:04.501](0.115s) ok 4 - Row inserted via 2PC has committed on subscriber B
[10:48:04.515](0.014s) not ok 5 - Row inserted via 2PC has committed on subscriber C
[10:48:04.516](0.000s) 
[10:48:04.516](0.000s) #   Failed test 'Row inserted via 2PC has committed on subscriber C'
#   at t/022_twophase_cascade.pl line 156.
[10:48:04.516](0.000s) #          got: '0'
#     expected: '1'
[10:48:04.531](0.015s) ok 6 - transaction is committed on subscriber B
[10:48:04.546](0.015s) ok 7 - transaction is committed on subscriber C
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1555258 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1557768 on node_B
done
[10:48:04.659](0.113s) ok 8 - transaction is prepared on subscriber B
[10:48:04.680](0.020s) not ok 9 - transaction is prepared on subscriber C
[10:48:04.680](0.000s) 
[10:48:04.680](0.000s) #   Failed test 'transaction is prepared on subscriber C'
#   at t/022_twophase_cascade.pl line 187.
[10:48:04.680](0.000s) #          got: '0'
#     expected: '1'
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/15552A8 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1557948 on node_B
done
[10:48:04.788](0.108s) ok 10 - Row inserted via 2PC is not present on subscriber B
[10:48:04.803](0.015s) ok 11 - Row inserted via 2PC is not present on subscriber C
[10:48:04.820](0.017s) ok 12 - transaction is ended on subscriber B
[10:48:04.840](0.020s) ok 13 - transaction is ended on subscriber C
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/15554C8 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1557948 on node_B
done
[10:48:04.960](0.120s) ok 14 - transaction is prepared on subscriber B
[10:48:04.977](0.018s) ok 15 - transaction is prepared on subscriber C
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1555500 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1557AD0 on node_B
done
[10:48:05.092](0.115s) ok 16 - transaction is ended on subscriber B
[10:48:05.108](0.016s) not ok 17 - transaction is ended on subscriber C
[10:48:05.108](0.000s) 
[10:48:05.108](0.000s) #   Failed test 'transaction is ended on subscriber C'
#   at t/022_twophase_cascade.pl line 249.
[10:48:05.108](0.000s) #          got: '1'
#     expected: '0'
[10:48:05.123](0.014s) ok 18 - Rows committed are present on subscriber B
[10:48:05.137](0.014s) ok 19 - Rows committed are present on subscriber C
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/16CFA58 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/173A928 on node_B
done
[10:48:06.180](1.043s) ok 20 - transaction is prepared on subscriber B
[10:48:06.206](0.026s) ok 21 - transaction is prepared on subscriber C
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/16CFAA0 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/173A928 on node_B
done
[10:48:06.332](0.126s) ok 22 - Rows inserted by 2PC have committed on subscriber B, and extra columns have local defaults
[10:48:06.351](0.019s) ok 23 - Rows inserted by 2PC have committed on subscriber C, and extra columns have local defaults
[10:48:06.369](0.018s) ok 24 - transaction is committed on subscriber B
[10:48:06.394](0.025s) ok 25 - transaction is committed on subscriber C
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1875608 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/17A0000 on node_B
done
[10:48:07.098](0.703s) ok 26 - transaction is prepared on subscriber B
[10:48:07.134](0.036s) ok 27 - transaction is prepared on subscriber C
Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1875640 on node_A
done
Waiting for replication conn tap_sub_C's replay_lsn to pass 0/17A64D8 on node_B
done
[10:48:07.306](0.172s) ok 28 - transaction is ended on subscriber B
[10:48:07.324](0.018s) not ok 29 - transaction is ended on subscriber C
[10:48:07.324](0.000s) 
[10:48:07.324](0.000s) #   Failed test 'transaction is ended on subscriber C'
#   at t/022_twophase_cascade.pl line 404.
[10:48:07.324](0.000s) #          got: '1'
#     expected: '0'
[10:48:07.341](0.017s) ok 30 - Rows committed are present on subscriber B
[10:48:07.358](0.017s) ok 31 - Rows committed are present on subscriber B
[10:48:07.375](0.017s) ok 32 - Rows committed are present on subscriber C
[10:48:07.392](0.017s) ok 33 - Rows committed are present on subscriber C
#### Begin standard error
psql:<stdin>:1: NOTICE:  dropped replication slot "tap_sub_c" on publisher
#### End standard error
[10:48:07.445](0.053s) ok 34 - check subscription was dropped on subscriber node C
[10:48:07.461](0.016s) ok 35 - check subscription relation status was dropped on subscriber node C
[10:48:07.477](0.016s) ok 36 - check replication origin was dropped on subscriber node C
[10:48:07.498](0.021s) ok 37 - check replication slot was dropped on publisher node B
#### Begin standard error
psql:<stdin>:1: NOTICE:  dropped replication slot "tap_sub_b" on publisher
#### End standard error
[10:48:07.547](0.049s) ok 38 - check subscription was dropped on subscriber node B
[10:48:07.563](0.016s) ok 39 - check subscription relation status was dropped on subscriber node B
[10:48:07.577](0.014s) ok 40 - check replication origin was dropped on subscriber node B
[10:48:07.594](0.017s) ok 41 - check replication slot was dropped on publisher node A
### Stopping node "node_C" using mode fast
# Running: pg_ctl -D /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_C_data/pgdata -m fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "node_C"
### Stopping node "node_B" using mode fast
# Running: pg_ctl -D /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_B_data/pgdata -m fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "node_B"
### Stopping node "node_A" using mode fast
# Running: pg_ctl -D /tmp/cirrus-ci-build/src/test/subscription/tmp_check/t_022_twophase_cascade_node_A_data/pgdata -m fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "node_A"
[10:48:07.906](0.312s) 1..41
[10:48:07.907](0.002s) # Looks like you failed 4 tests of 41.