On Tue, Mar 02, 2021 at 09:47:18PM -0800, Andres Freund wrote: > I can't reproduce that here - could either (or both) of you send > > src/test/recovery/tmp_check/log/regress_log_021_row_visibility > src/test/recovery/tmp_check/log/021_row_visibility_standby.log > src/test/recovery/tmp_check/log/021_row_visibility_primary.log > > of a failed run? And maybe how you're invoking it?
I have not checked this stuff in details, but here you go. I have simply invoked that with vcregress taptest src/test/recovery/, speeding up the process by removing temporarily all the other scripts. -- Michael
2021-03-02 17:20:31.759 PST [3428] LOG: starting PostgreSQL 14devel, compiled
by Visual C++ build 1900, 64-bit
2021-03-02 17:20:31.761 PST [3428] LOG: listening on IPv4 address "127.0.0.1",
port 57417
2021-03-02 17:20:31.778 PST [4180] LOG: database system was shut down at
2021-03-02 17:20:31 PST
2021-03-02 17:20:31.789 PST [3428] LOG: database system is ready to accept
connections
2021-03-02 17:20:31.923 PST [2532] 021_row_visibility.pl LOG: statement:
CREATE TABLE public.test_visibility (data text not null)
2021-03-02 17:20:32.024 PST [6012] 021_row_visibility.pl LOG: received
replication command: SHOW data_directory_mode
2021-03-02 17:20:32.024 PST [6012] 021_row_visibility.pl STATEMENT: SHOW
data_directory_mode
2021-03-02 17:20:32.025 PST [6012] 021_row_visibility.pl LOG: received
replication command: SHOW wal_segment_size
2021-03-02 17:20:32.025 PST [6012] 021_row_visibility.pl STATEMENT: SHOW
wal_segment_size
2021-03-02 17:20:32.025 PST [6012] 021_row_visibility.pl LOG: received
replication command: IDENTIFY_SYSTEM
2021-03-02 17:20:32.025 PST [6012] 021_row_visibility.pl STATEMENT:
IDENTIFY_SYSTEM
2021-03-02 17:20:32.025 PST [6012] 021_row_visibility.pl LOG: received
replication command: BASE_BACKUP LABEL 'pg_basebackup base backup' PROGRESS
FAST NOWAIT MANIFEST 'yes'
2021-03-02 17:20:32.025 PST [6012] 021_row_visibility.pl STATEMENT:
BASE_BACKUP LABEL 'pg_basebackup base backup' PROGRESS FAST NOWAIT MANIFEST
'yes'
2021-03-02 17:20:32.539 PST [4992] 021_row_visibility.pl LOG: received
replication command: SHOW data_directory_mode
2021-03-02 17:20:32.539 PST [4992] 021_row_visibility.pl STATEMENT: SHOW
data_directory_mode
2021-03-02 17:20:32.539 PST [4992] 021_row_visibility.pl LOG: received
replication command: CREATE_REPLICATION_SLOT "pg_basebackup_4992" TEMPORARY
PHYSICAL RESERVE_WAL
2021-03-02 17:20:32.539 PST [4992] 021_row_visibility.pl STATEMENT:
CREATE_REPLICATION_SLOT "pg_basebackup_4992" TEMPORARY PHYSICAL RESERVE_WAL
2021-03-02 17:20:32.542 PST [4992] 021_row_visibility.pl LOG: received
replication command: IDENTIFY_SYSTEM
2021-03-02 17:20:32.542 PST [4992] 021_row_visibility.pl STATEMENT:
IDENTIFY_SYSTEM
2021-03-02 17:20:32.543 PST [4992] 021_row_visibility.pl LOG: received
replication command: START_REPLICATION SLOT "pg_basebackup_4992" 0/2000000
TIMELINE 1
2021-03-02 17:20:32.543 PST [4992] 021_row_visibility.pl STATEMENT:
START_REPLICATION SLOT "pg_basebackup_4992" 0/2000000 TIMELINE 1
2021-03-02 17:20:43.208 PST [2984] standby LOG: received replication command:
IDENTIFY_SYSTEM
2021-03-02 17:20:43.208 PST [2984] standby STATEMENT: IDENTIFY_SYSTEM
2021-03-02 17:20:43.208 PST [2984] standby LOG: received replication command:
START_REPLICATION 0/3000000 TIMELINE 1
2021-03-02 17:20:43.208 PST [2984] standby STATEMENT: START_REPLICATION
0/3000000 TIMELINE 1
2021-03-02 17:20:43.627 PST [4516] 021_row_visibility.pl LOG: statement:
INSERT INTO test_visibility VALUES ('first insert')
2021-03-02 17:20:43.804 PST [5280] 021_row_visibility.pl LOG: statement:
SELECT pg_current_wal_insert_lsn()
2021-03-02 17:20:43.918 PST [3412] 021_row_visibility.pl LOG: statement:
SELECT '0/3002640' <= replay_lsn AND state = 'streaming' FROM
pg_catalog.pg_stat_replication WHERE application_name = 'standby';
2021-03-02 17:20:43.940 PST [3948] 021_row_visibility.pl LOG: statement: BEGIN;
2021-03-02 17:20:43.940 PST [3948] 021_row_visibility.pl LOG: statement:
UPDATE test_visibility SET data = 'first update' RETURNING data;
2021-03-02 17:20:44.020 PST [6028] 021_row_visibility.pl LOG: statement:
SELECT txid_current();
2021-03-02 17:20:44.062 PST [4900] 021_row_visibility.pl LOG: statement:
SELECT pg_current_wal_insert_lsn()
2021-03-02 17:20:44.093 PST [5336] 021_row_visibility.pl LOG: statement:
SELECT '0/30026B8' <= replay_lsn AND state = 'streaming' FROM
pg_catalog.pg_stat_replication WHERE application_name = 'standby';
2021-03-02 17:20:44.127 PST [3948] 021_row_visibility.pl LOG: statement:
COMMIT;
2021-03-02 17:20:44.155 PST [5060] 021_row_visibility.pl LOG: statement:
SELECT pg_current_wal_insert_lsn()
2021-03-02 17:20:44.220 PST [5256] 021_row_visibility.pl LOG: statement:
SELECT '0/30026E0' <= replay_lsn AND state = 'streaming' FROM
pg_catalog.pg_stat_replication WHERE application_name = 'standby';
2021-03-02 17:20:44.255 PST [3948] 021_row_visibility.pl LOG: statement:
DELETE from test_visibility;
2021-03-02 17:20:44.256 PST [3948] 021_row_visibility.pl LOG: statement: BEGIN;
2021-03-02 17:20:44.256 PST [3948] 021_row_visibility.pl LOG: statement:
INSERT INTO test_visibility VALUES('inserted in prepared will_commit');
2021-03-02 17:20:44.257 PST [3948] 021_row_visibility.pl LOG: statement:
PREPARE TRANSACTION 'will_commit';
2021-03-02 17:20:44.257 PST [3948] 021_row_visibility.pl LOG: statement: BEGIN;
2021-03-02 17:20:44.258 PST [3948] 021_row_visibility.pl LOG: statement:
INSERT INTO test_visibility VALUES('inserted in prepared will_abort');
2021-03-02 17:20:44.258 PST [3948] 021_row_visibility.pl LOG: statement:
PREPARE TRANSACTION 'will_abort';
2021-03-02 17:20:44.299 PST [4168] 021_row_visibility.pl LOG: statement:
SELECT pg_current_wal_insert_lsn()
2021-03-02 17:20:44.350 PST [5756] 021_row_visibility.pl LOG: statement:
SELECT '0/30029E0' <= replay_lsn AND state = 'streaming' FROM
pg_catalog.pg_stat_replication WHERE application_name = 'standby';
2021-03-02 17:20:44.418 PST [4248] 021_row_visibility.pl LOG: statement:
COMMIT PREPARED 'will_commit';
2021-03-02 17:20:44.476 PST [3916] 021_row_visibility.pl LOG: statement:
ROLLBACK PREPARED 'will_abort';
2021-03-02 17:20:44.543 PST [4580] 021_row_visibility.pl LOG: statement:
SELECT pg_current_wal_insert_lsn()
2021-03-02 17:20:44.618 PST [5512] 021_row_visibility.pl LOG: statement:
SELECT '0/3002A40' <= replay_lsn AND state = 'streaming' FROM
pg_catalog.pg_stat_replication WHERE application_name = 'standby';
2021-03-02 17:20:44.723 PST [2984] standby ERROR: canceling statement due to
user request
2021-03-02 17:20:44.723 PST [2984] standby STATEMENT: START_REPLICATION
0/3000000 TIMELINE 1
2021-03-02 17:20:44.723 PST [2508] ERROR: canceling statement due to user
request
2021-03-02 17:20:44.723 PST [4052] ERROR: canceling statement due to user
request
2021-03-02 17:20:44.724 PST [3428] LOG: received fast shutdown request
2021-03-02 17:20:44.731 PST [3428] LOG: aborting any active transactions
2021-03-02 17:20:44.731 PST [3948] 021_row_visibility.pl FATAL: terminating
connection due to administrator command
2021-03-02 17:20:44.740 PST [3428] LOG: background worker "logical replication
launcher" (PID 2508) exited with exit code 1
2021-03-02 17:20:44.752 PST [2112] LOG: shutting down
2021-03-02 17:20:44.775 PST [3428] LOG: database system is shut down
2021-03-02 17:20:43.146 PST [3144] LOG: starting PostgreSQL 14devel, compiled by Visual C++ build 1900, 64-bit 2021-03-02 17:20:43.147 PST [3144] LOG: listening on IPv4 address "127.0.0.1", port 57418 2021-03-02 17:20:43.163 PST [860] LOG: database system was interrupted; last known up at 2021-03-02 17:20:32 PST 2021-03-02 17:20:43.163 PST [860] LOG: entering standby mode 2021-03-02 17:20:43.169 PST [860] LOG: redo starts at 0/2000028 2021-03-02 17:20:43.170 PST [860] LOG: consistent recovery state reached at 0/2000100 2021-03-02 17:20:43.172 PST [3144] LOG: database system is ready to accept read only connections 2021-03-02 17:20:43.209 PST [5780] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2021-03-02 17:20:43.568 PST [5292] 021_row_visibility.pl LOG: statement: SELECT * FROM test_visibility ORDER BY data; 2021-03-02 17:20:43.939 PST [5292] 021_row_visibility.pl LOG: statement: SELECT * FROM test_visibility ORDER BY data; 2021-03-02 17:20:44.126 PST [5292] 021_row_visibility.pl LOG: statement: SELECT * FROM test_visibility ORDER BY data; 2021-03-02 17:20:44.254 PST [5292] 021_row_visibility.pl LOG: statement: SELECT * FROM test_visibility ORDER BY data; 2021-03-02 17:20:44.378 PST [5292] 021_row_visibility.pl LOG: statement: SELECT * FROM test_visibility ORDER BY data; 2021-03-02 17:20:44.704 PST [5292] 021_row_visibility.pl LOG: statement: SELECT * FROM test_visibility ORDER BY data; 2021-03-02 17:20:44.722 PST [3144] LOG: received fast shutdown request 2021-03-02 17:20:44.725 PST [5780] FATAL: could not receive data from WAL stream: ERROR: canceling statement due to user request 2021-03-02 17:20:44.730 PST [3144] LOG: aborting any active transactions 2021-03-02 17:20:44.730 PST [5292] 021_row_visibility.pl FATAL: terminating connection due to administrator command 2021-03-02 17:20:44.732 PST [860] LOG: invalid record length at 0/3002A40: wanted 24, got 0 2021-03-02 17:20:44.756 PST [5432] LOG: shutting down 2021-03-02 17:20:44.764 PST [3144] LOG: database system is shut down
# Checking port 57417
# Found port 57417
Name: primary
Data directory:
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_primary_data/pgdata
Backup directory:
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_primary_data/backup
Archive directory:
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_primary_data/archives
Connection string: port=57417 host=127.0.0.1
Log file:
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/log/021_row_visibility_primary.log
# Running: initdb -D
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_primary_data/pgdata
-A trust -N
The files belonging to this database system will be owned by user "IEUser".
This user must also own the server process.
The database cluster will be initialized with locale "English_United
States.1252".
The default database encoding has accordingly been set to "WIN1252".
The default text search configuration will be set to "english".
Data page checksums are disabled.
creating directory
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_primary_data/pgdata
... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... windows
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... US/Pacific
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
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_primary_data/pgdata
-l logfile start
# Running: C:/Users/IEUser/git/postgres/Release/pg_regress/pg_regress
--config-auth
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_primary_data/pgdata
### Starting node "primary"
# Running: pg_ctl -D
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_primary_data/pgdata
-l
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/log/021_row_visibility_primary.log
-o --cluster-name=primary start
waiting for server to start.... done
server started
# Postmaster PID for node "primary" is 3428
# Taking pg_basebackup my_backup from node "primary"
# Running: pg_basebackup -D
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_primary_data/backup/my_backup
-h 127.0.0.1 -p 57417 --checkpoint fast --no-sync
# Backup finished
# Checking port 57418
# Found port 57418
Name: standby
Data directory:
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_standby_data/pgdata
Backup directory:
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_standby_data/backup
Archive directory:
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_standby_data/archives
Connection string: port=57418 host=127.0.0.1
Log file:
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/log/021_row_visibility_standby.log
# Initializing node "standby" from backup "my_backup" of node "primary"
### Enabling streaming replication for node "standby"
### Starting node "standby"
# Running: pg_ctl -D
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/t_021_row_visibility_standby_data/pgdata
-l
C:/Users/IEUser/git/postgres/src/test/recovery/tmp_check/log/021_row_visibility_standby.log
-o --cluster-name=standby start
waiting for server to start.... done
server started
# Postmaster PID for node "standby" is 3144
ok 1 - data not visible
Waiting for replication conn standby's replay_lsn to pass '0/3002640' on primary
done
ok 2 - insert visible
ok 3 - UPDATE
541
Waiting for replication conn standby's replay_lsn to pass '0/30026B8' on primary
done
ok 4 - uncommitted update invisible
ok 5 - COMMIT
Waiting for replication conn standby's replay_lsn to pass '0/30026E0' on primary
done
ok 6 - committed update visible
ok 7 - prepared will_commit
ok 8 - prepared will_abort
Waiting for replication conn standby's replay_lsn to pass '0/30029E0' on primary
done
ok 9 - uncommitted prepared invisible
Waiting for replication conn standby's replay_lsn to pass '0/3002A40' on primary
done
ok 10 - finished prepared visible
Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
Terminating on signal SIGBREAK(21)
signature.asc
Description: PGP signature
