# Checking port 64470 # Found port 64470 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=64470 host=/tmp/Bi0UTrjIrM Log file: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/log/022_twophase_cascade_node_A.log [22:17:15.118](0.015s) # 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 46037 # Checking port 64471 # Found port 64471 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=64471 host=/tmp/Bi0UTrjIrM Log file: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/log/022_twophase_cascade_node_B.log [22:17:15.312](0.194s) # 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 46079 # Checking port 64472 # Found port 64472 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=64472 host=/tmp/Bi0UTrjIrM Log file: /tmp/cirrus-ci-build/src/test/subscription/tmp_check/log/022_twophase_cascade_node_C.log [22:17:15.502](0.190s) # 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 46110 #### Begin standard error psql::5: NOTICE: created replication slot "tap_sub_b" on publisher #### End standard error #### Begin standard error psql::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/1552C68 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/15552E8 on node_B done [22:17:16.160](0.658s) ok 1 - Cascade setup is complete Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1552DF0 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1555470 on node_B done [22:17:16.301](0.141s) ok 2 - transaction is prepared on subscriber B [22:17:16.320](0.019s) ok 3 - transaction is prepared on subscriber C Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1552E40 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1555470 on node_B done [22:17:16.456](0.136s) ok 4 - Row inserted via 2PC has committed on subscriber B [22:17:16.473](0.017s) ok 5 - Row inserted via 2PC has committed on subscriber C [22:17:16.493](0.020s) ok 6 - transaction is committed on subscriber B [22:17:16.514](0.021s) ok 7 - transaction is committed on subscriber C Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1552FC8 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/15554C8 on node_B done [22:17:16.657](0.143s) ok 8 - transaction is prepared on subscriber B [22:17:16.676](0.019s) ok 9 - transaction is prepared on subscriber C Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1553018 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/15556A8 on node_B done [22:17:16.806](0.130s) ok 10 - Row inserted via 2PC is not present on subscriber B [22:17:16.830](0.024s) ok 11 - Row inserted via 2PC is not present on subscriber C [22:17:16.848](0.018s) ok 12 - transaction is ended on subscriber B [22:17:16.868](0.020s) ok 13 - transaction is ended on subscriber C Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1553238 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/15556A8 on node_B done [22:17:16.998](0.130s) ok 14 - transaction is prepared on subscriber B [22:17:17.016](0.018s) ok 15 - transaction is prepared on subscriber C Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1553270 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1555830 on node_B done [22:17:17.164](0.148s) ok 16 - transaction is ended on subscriber B [22:17:17.183](0.019s) not ok 17 - transaction is ended on subscriber C [22:17:17.184](0.000s) [22:17:17.184](0.000s) # Failed test 'transaction is ended on subscriber C' # at t/022_twophase_cascade.pl line 249. [22:17:17.184](0.000s) # got: '1' # expected: '0' [22:17:17.202](0.019s) ok 18 - Rows committed are present on subscriber B [22:17:17.221](0.018s) not ok 19 - Rows committed are present on subscriber C [22:17:17.221](0.000s) [22:17:17.221](0.000s) # Failed test 'Rows committed are present on subscriber C' # at t/022_twophase_cascade.pl line 259. [22:17:17.221](0.000s) # got: '' # expected: '21' Waiting for replication conn tap_sub_B's replay_lsn to pass 0/16CD7C8 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1738688 on node_B done [22:17:18.034](0.813s) ok 20 - transaction is prepared on subscriber B [22:17:18.054](0.020s) ok 21 - transaction is prepared on subscriber C Waiting for replication conn tap_sub_B's replay_lsn to pass 0/16CD810 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/1738688 on node_B done [22:17:18.197](0.142s) ok 22 - Rows inserted by 2PC have committed on subscriber B, and extra columns have local defaults [22:17:18.215](0.018s) not ok 23 - Rows inserted by 2PC have committed on subscriber C, and extra columns have local defaults [22:17:18.215](0.000s) [22:17:18.215](0.000s) # Failed test 'Rows inserted by 2PC have committed on subscriber C, and extra columns have local defaults' # at t/022_twophase_cascade.pl line 341. [22:17:18.215](0.000s) # got: '2|2|2' # expected: '3334|3334|3334' [22:17:18.236](0.021s) ok 24 - transaction is committed on subscriber B [22:17:18.258](0.022s) ok 25 - transaction is committed on subscriber C Waiting for replication conn tap_sub_B's replay_lsn to pass 0/1873370 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/17A0000 on node_B done [22:17:18.747](0.489s) ok 26 - transaction is prepared on subscriber B [22:17:18.764](0.017s) ok 27 - transaction is prepared on subscriber C Waiting for replication conn tap_sub_B's replay_lsn to pass 0/18733A8 on node_A done Waiting for replication conn tap_sub_C's replay_lsn to pass 0/17A4130 on node_B done [22:17:18.891](0.127s) ok 28 - transaction is ended on subscriber B [22:17:18.908](0.017s) ok 29 - transaction is ended on subscriber C [22:17:18.925](0.017s) ok 30 - Rows committed are present on subscriber B [22:17:18.942](0.017s) ok 31 - Rows committed are present on subscriber B [22:17:18.959](0.017s) ok 32 - Rows committed are present on subscriber C [22:17:18.975](0.016s) ok 33 - Rows committed are present on subscriber C #### Begin standard error psql::1: NOTICE: dropped replication slot "tap_sub_c" on publisher #### End standard error [22:17:19.027](0.052s) ok 34 - check subscription was dropped on subscriber node C [22:17:19.044](0.016s) ok 35 - check subscription relation status was dropped on subscriber node C [22:17:19.062](0.018s) ok 36 - check replication origin was dropped on subscriber node C [22:17:19.084](0.022s) ok 37 - check replication slot was dropped on publisher node B #### Begin standard error psql::1: NOTICE: dropped replication slot "tap_sub_b" on publisher #### End standard error [22:17:19.140](0.056s) ok 38 - check subscription was dropped on subscriber node B [22:17:19.160](0.020s) ok 39 - check subscription relation status was dropped on subscriber node B [22:17:19.176](0.017s) ok 40 - check replication origin was dropped on subscriber node B [22:17:19.202](0.026s) 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" [22:17:19.516](0.314s) 1..41 [22:17:19.518](0.002s) # Looks like you failed 3 tests of 41.