regress_log_031_recovery_conflict
text/plain
Filename: regress_log_031_recovery_conflict
Type: text/plain
Part: 2
# Checking port 52786
# Found port 52786
Name: primary
Data directory: /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_primary_data/pgdata
Backup directory: /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_primary_data/backup
Archive directory: /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_primary_data/archives
Connection string: port=52786 host=/tmp/Ew0sehtBKm
Log file: /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/log/031_recovery_conflict_primary.log
# Running: initdb -D /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_primary_data/pgdata -A trust -N
The files belonging to this database system will be owned by user "myon".
This user must also own the server process.
The database cluster will be initialized with this locale configuration:
provider: libc
LC_COLLATE: en_US.utf8
LC_CTYPE: en_US.utf8
LC_MESSAGES: C
LC_MONETARY: en_US.utf8
LC_NUMERIC: en_US.utf8
LC_TIME: en_US.utf8
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".
Data page checksums are disabled.
creating directory /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_primary_data/pgdata ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... Etc/UTC
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok
Sync to disk skipped.
The data directory might become corrupt if the operating system crashes.
Success. You can now start the database server using:
pg_ctl -D /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_primary_data/pgdata -l logfile start
# Running: /home/myon/postgresql/pg/postgresql/build/src/test/recovery/../../../src/test/regress/pg_regress --config-auth /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_primary_data/pgdata
### Starting node "primary"
# Running: pg_ctl -w -D /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_primary_data/pgdata -l /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/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 3132659
# Taking pg_basebackup my_backup from node "primary"
# Running: pg_basebackup -D /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_primary_data/backup/my_backup -h /tmp/Ew0sehtBKm -p 52786 --checkpoint fast --no-sync
# Backup finished
# Checking port 52787
# Found port 52787
Name: standby
Data directory: /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_standby_data/pgdata
Backup directory: /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_standby_data/backup
Archive directory: /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_standby_data/archives
Connection string: port=52787 host=/tmp/Ew0sehtBKm
Log file: /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/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 /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_standby_data/pgdata -l /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/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 3132749
Waiting for replication conn standby's replay_lsn to pass 0/342B100 on primary
done
Waiting for replication conn standby's replay_lsn to pass 0/342B1C0 on primary
done
[10:21:54.634](3.411s) # 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;
[10:21:54.734](0.101s) ok 1 - buffer pin conflict: cursor with conflicting pin established
Waiting for replication conn standby's replay_lsn to pass 0/3430000 on primary
done
[10:21:55.048](0.314s) ok 2 - buffer pin conflict: logfile contains terminated connection due to recovery conflict
[10:21:55.226](0.178s) ok 3 - buffer pin conflict: stats show conflict on standby
Waiting for replication conn standby's replay_lsn to pass 0/34339C8 on primary
done
[10:21:55.378](0.152s) # 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;
#
[10:21:55.382](0.005s) ok 4 - snapshot conflict: cursor with conflicting snapshot established
Waiting for replication conn standby's replay_lsn to pass 0/3434000 on primary
done
[10:21:56.136](0.753s) ok 5 - snapshot conflict: logfile contains terminated connection due to recovery conflict
[10:21:56.187](0.051s) ok 6 - snapshot conflict: stats show conflict on standby
[10:21:56.187](0.000s) # issuing query via background psql:
# BEGIN;
# LOCK TABLE test_recovery_conflict_table1 IN ACCESS SHARE MODE;
# SELECT 1;
#
[10:21:56.188](0.001s) ok 7 - lock conflict: conflicting lock acquired
Waiting for replication conn standby's replay_lsn to pass 0/3434630 on primary
done
[10:21:56.364](0.176s) ok 8 - lock conflict: logfile contains terminated connection due to recovery conflict
[10:21:56.415](0.051s) ok 9 - lock conflict: stats show conflict on standby
[10:21:56.416](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;
#
[10:21:56.423](0.008s) ok 10 - tablespace conflict: cursor with conflicting temp file established
Waiting for replication conn standby's replay_lsn to pass 0/34346D0 on primary
done
[10:21:56.774](0.350s) ok 11 - tablespace conflict: logfile contains terminated connection due to recovery conflict
[10:21:57.274](0.501s) ok 12 - tablespace conflict: stats show conflict on standby
### Restarting node "standby"
# Running: pg_ctl -w -D /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_standby_data/pgdata -l /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/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 3133177
Waiting for replication conn standby's replay_lsn to pass 0/3437418 on primary
done
[10:21:58.230](0.956s) ok 13 - startup deadlock: cursor holding conflicting pin, also waiting for lock, established
[10:21:58.259](0.029s) ok 14 - startup deadlock: lock acquisition is waiting
Waiting for replication conn standby's replay_lsn to pass 0/3437418 on primary
done
[10:21:58.410](0.151s) ok 15 - startup deadlock: logfile contains terminated connection due to recovery conflict
[10:21:58.463](0.053s) not ok 16 - startup deadlock: stats show conflict on standby
[10:21:58.463](0.000s)
[10:21:58.463](0.000s) # Failed test 'startup deadlock: stats show conflict on standby'
# at t/031_recovery_conflict.pl line 332.
[10:21:58.463](0.000s) # got: '0'
# expected: '1'
### Restarting node "standby"
# Running: pg_ctl -w -D /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/t_031_recovery_conflict_standby_data/pgdata -l /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/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 3133299
[10:22:00.298](1.835s) ok 17 - 5 recovery conflicts shown in pg_stat_database
Waiting for replication conn standby's replay_lsn to pass 0/343DBF0 on primary
done
[10:22:00.505](0.207s) ok 18 - database conflict: logfile contains terminated connection due to recovery conflict
### Stopping node "standby" using mode fast
# Running: pg_ctl -D /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/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 /home/myon/postgresql/pg/postgresql/build/src/test/recovery/tmp_check/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"
[10:22:00.724](0.219s) 1..18
[10:22:00.730](0.006s) # Looks like you failed 1 test of 18.