# Checking port 62306
# Found port 62306
Name: primary
Data directory: /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_primary_data/pgdata
Backup directory: /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_primary_data/backup
Archive directory: /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_primary_data/archives
Connection string: port=62306 host=/var/folders/n8/pp_chp6x3jlfy1n94r6hdjv40000gn/T/sDWI5QcrwP
Log file: /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/log/031_recovery_conflict_primary.log
[00:03:52.988](0.108s) # initializing database system by copying initdb template
# Running: cp -RPp /Users/admin/pgsql/build/tmp_install/initdb-template /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_primary_data/pgdata
# Running: /Users/admin/pgsql/build/src/test/regress/pg_regress --config-auth /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_primary_data/pgdata
### Starting node "primary"
# Running: pg_ctl -w -D /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_primary_data/pgdata -l /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/log/031_recovery_conflict_primary.log -o --cluster-name=primary start
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 16403
# Taking pg_basebackup my_backup from node "primary"
# Running: pg_basebackup -D /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_primary_data/backup/my_backup -h /var/folders/n8/pp_chp6x3jlfy1n94r6hdjv40000gn/T/sDWI5QcrwP -p 62306 --checkpoint fast --no-sync
# Backup finished
# Checking port 62307
# Found port 62307
Name: standby
Data directory: /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_standby_data/pgdata
Backup directory: /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_standby_data/backup
Archive directory: /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_standby_data/archives
Connection string: port=62307 host=/var/folders/n8/pp_chp6x3jlfy1n94r6hdjv40000gn/T/sDWI5QcrwP
Log file: /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/log/031_recovery_conflict_standby.log
# Initializing node "standby" from backup "my_backup" of node "primary"
### Enabling streaming replication for node "standby"
### Starting node "standby"
# Running: pg_ctl -w -D /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_standby_data/pgdata -l /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/log/031_recovery_conflict_standby.log -o --cluster-name=standby start
waiting for server to start.... done
server started
# Postmaster PID for node "standby" is 16612
Waiting for replication conn standby's replay_lsn to pass 0/343EED8 on primary
done
Waiting for replication conn standby's replay_lsn to pass 0/343EF98 on primary
done
[00:03:55.459](2.471s) # issuing query via background psql: 
#     BEGIN;
#     DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT b FROM test_recovery_conflict_table1;
#     FETCH FORWARD FROM test_recovery_conflict_cursor;
[00:03:55.460](0.001s) ok 1 - buffer pin conflict: cursor with conflicting pin established
Waiting for replication conn standby's replay_lsn to pass 0/343EF98 on primary
done
[00:03:55.849](0.389s) ok 2 - buffer pin conflict: logfile contains terminated connection due to recovery conflict
[00:03:55.886](0.037s) ok 3 - buffer pin conflict: stats show conflict on standby
Waiting for replication conn standby's replay_lsn to pass 0/34477D8 on primary
done
[00:03:56.014](0.127s) # issuing query via background psql: 
#         BEGIN;
#         DECLARE test_recovery_conflict_cursor CURSOR FOR SELECT b FROM test_recovery_conflict_table1;
#         FETCH FORWARD FROM test_recovery_conflict_cursor;
#         
[00:03:56.015](0.001s) ok 4 - snapshot conflict: cursor with conflicting snapshot established
Waiting for replication conn standby's replay_lsn to pass 0/3447D10 on primary
done
[00:03:56.206](0.192s) ok 5 - snapshot conflict: logfile contains terminated connection due to recovery conflict
[00:03:56.249](0.043s) ok 6 - snapshot conflict: stats show conflict on standby
[00:03:56.249](0.000s) # issuing query via background psql: 
#         BEGIN;
#         LOCK TABLE test_recovery_conflict_table1 IN ACCESS SHARE MODE;
#         SELECT 1;
#         
[00:03:56.250](0.001s) ok 7 - lock conflict: conflicting lock acquired
Waiting for replication conn standby's replay_lsn to pass 0/34484B8 on primary
done
[00:03:56.591](0.341s) ok 8 - lock conflict: logfile contains terminated connection due to recovery conflict
[00:03:56.629](0.038s) ok 9 - lock conflict: stats show conflict on standby
[00:03:56.629](0.000s) # issuing query via background psql: 
#         BEGIN;
#         SET work_mem = '64kB';
#         DECLARE test_recovery_conflict_cursor CURSOR FOR
#           SELECT count(*) FROM generate_series(1,6000);
#         FETCH FORWARD FROM test_recovery_conflict_cursor;
#         
[00:03:56.630](0.002s) ok 10 - tablespace conflict: cursor with conflicting temp file established
Waiting for replication conn standby's replay_lsn to pass 0/3448558 on primary
done
[00:03:56.783](0.153s) ok 11 - tablespace conflict: logfile contains terminated connection due to recovery conflict
[00:03:56.813](0.030s) not ok 12 - tablespace conflict: stats show conflict on standby
[00:03:56.813](0.000s) #   Failed test 'tablespace conflict: stats show conflict on standby'
#   at /Users/admin/pgsql/src/test/recovery/t/031_recovery_conflict.pl line 332.
[00:03:56.813](0.000s) #          got: '0'
#     expected: '1'
### Restarting node "standby"
# Running: pg_ctl -w -D /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_standby_data/pgdata -l /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/log/031_recovery_conflict_standby.log restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "standby" is 16865
Waiting for replication conn standby's replay_lsn to pass 0/344B2A8 on primary
done
[00:03:57.153](0.339s) ok 13 - startup deadlock: cursor holding conflicting pin, also waiting for lock, established
[00:03:57.173](0.021s) ok 14 - startup deadlock: lock acquisition is waiting
Waiting for replication conn standby's replay_lsn to pass 0/3450000 on primary
done
[00:03:57.352](0.179s) ok 15 - startup deadlock: logfile contains terminated connection due to recovery conflict
[00:03:57.392](0.039s) ok 16 - startup deadlock: stats show conflict on standby
### Restarting node "standby"
# Running: pg_ctl -w -D /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_standby_data/pgdata -l /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/log/031_recovery_conflict_standby.log restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "standby" is 16978
[00:03:58.174](0.783s) ok 17 - 5 recovery conflicts shown in pg_stat_database
Waiting for replication conn standby's replay_lsn to pass 0/3451A10 on primary
done
[00:03:58.387](0.213s) ok 18 - database conflict: logfile contains terminated connection due to recovery conflict
### Stopping node "standby" using mode fast
# Running: pg_ctl -D /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_standby_data/pgdata -m fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "standby"
### Stopping node "primary" using mode fast
# Running: pg_ctl -D /Users/admin/pgsql/build/testrun/recovery/031_recovery_conflict/data/t_031_recovery_conflict_primary_data/pgdata -m fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "primary"
[00:03:58.607](0.219s) 1..18
[00:03:58.608](0.001s) # Looks like you failed 1 test of 18.