archive-push problem #330

hunterhuang8810 · 2021-02-18T05:06:37Z

I want to use archive-push to move pg wal files from archive folder to backup wal folder, i.e. copy all archived wal files from
/home/service/var/pgdata/archivedir to pg_probackup wal archive folder , but I can't run success:

pg_probackup-12 archive-push -B /home/postgres/pg_backup --instance pgsql --wal-file-name=000000010000000000000020 --wal-file-path=/home/service/var/pgdata/archivedir

ERROR: Could not open file "/home/service/var/pgdata/archivedir/global/pg_control" for reading: No such file or directory

How do I use archive-push command to move all archived wal files from one folder to pg_probackup base folder?

gsmolk · 2021-02-18T06:53:05Z

Hello!

ERROR: Could not open file "/home/service/var/pgdata/archivedir/global/pg_control" for reading: No such file or directory

We are trying to get system ID here before pushing WAL to make sure that we are pushing to the correct repo.
And currently this behaviour cannot be disabled.
It is a known issue and we will fix it in the upcoming patch-release:
#265

Currently I can only recommend to use cp to solve this problem =(

hunterhuang8810 · 2021-02-18T06:59:32Z

Hello!

ERROR: Could not open file "/home/service/var/pgdata/archivedir/global/pg_control" for reading: No such file or directory

We are trying to get system ID here before pushing WAL to make sure that we are pushing to the correct repo.
And currently this behaviour cannot be disabled.
It is a known issue and we will fix it in the upcoming patch-release:
#265

Currently I can only recommend to use cp to solve this problem =(

OK , noted

hunterhuang8810 · 2021-02-18T07:11:45Z

BTW,

annother question, I have changed postgres instance archive_timeout to 4min, but the backup still failed.
As no data change, I found wal archive will not triggerred even when after set archive_timeout , so the backup fail. any solution for this?

[[email protected] pgsql]$ pg_probackup-12 backup -B /home/postgres/pg_backup --instance pgsql -b full
INFO: Backup start, pg_probackup version: 2.4.9, instance: pgsql, backup ID: QOPQ0B, backup mode: FULL, wal mode: ARCHIVE, remote: false, compress-algorithm: none, compress-level: 1
WARNING: Current PostgreSQL role is superuser. It is not recommended to run backup or checkdb as superuser.
INFO: Backup QOPQ0B is going to be taken from standby
INFO: Wait for WAL segment /home/postgres/pg_backup/wal/pgsql/000000010000000000000024 to be archived
WARNING: By default pg_probackup assume WAL delivery method to be ARCHIVE. If continuous archiving is not set up, use '--stream' option to make autonomous backup. Otherwise check that continuous archiving works correctly.
ERROR: WAL segment 000000010000000000000024 could not be archived in 300 seconds
WARNING: backup in progress, stop backup
WARNING: Backup QOPQ0B is running, setting its status to ERROR
[[email protected] pgsql]$

gsmolk · 2021-02-18T07:19:09Z

Did you set archive_timeout on master?

hunterhuang8810 · 2021-02-18T07:25:41Z

Did you set archive_timeout on master?

yes, I set on all instance, including master and standby

hunterhuang8810 · 2021-02-18T07:52:14Z

how to solve this? the root cause is , if no any data change, pg will not switch wal files, so as for archive_timeout.

postgres=# show archive_timeout ;
archive_timeout

4min
(1 row)

postgres=# select pg_switch_wal();
pg_switch_wal

0/2A000000
(1 row)

postgres=# select pg_switch_wal();
pg_switch_wal

0/2A000000
(1 row)

postgres=#

--I tried stream mode, still need archive. I don't understand why must archive before backup db? And what's the solution for this scenario?
[[email protected] pgsql]$ pg_probackup-12 backup -B /home/postgres/pg_backup --instance pgsql -b full --stream
INFO: Backup start, pg_probackup version: 2.4.9, instance: pgsql, backup ID: QOPS81, backup mode: FULL, wal mode: STREAM, remote: false, compress-algorithm: none, compress-level: 1
WARNING: Current PostgreSQL role is superuser. It is not recommended to run backup or checkdb as superuser.
INFO: Backup QOPS81 is going to be taken from standby
INFO: PGDATA size: 142MB
INFO: Start transferring data files
INFO: Data files are transferred, time elapsed: 0
INFO: wait for pg_stop_backup()
INFO: pg_stop backup() successfully executed
INFO: Wait for WAL segment /home/postgres/pg_backup/backups/pgsql/QOPS81/database/pg_wal/00000001000000000000002A to be streamed
WARNING: WAL segment 00000001000000000000002A could not be streamed in 300 seconds

gsmolk · 2021-02-18T07:54:19Z

Can you please rerun this backup with --log-level-file=VERBOSE and then attach file here?

hunterhuang8810 · 2021-02-18T08:03:39Z

Can you please rerun this backup with --log-level-file=VERBOSE and then attach file here?

-------backup on standby, all cluster instance archive_timeout=4min, pg_probackup archive_timeout=5min------
[[email protected] pgsql]$ pg_probackup-12 show-config -B /home/postgres/pg_backup --instance pgsql

Backup instance information

pgdata = /home/service/var/pgdata
system-identifier = 6926437883201436364
xlog-seg-size = 16777216

Connection parameters

pgdatabase = postgres

Replica parameters

replica-timeout = 5min

Archive parameters

archive-timeout = 5min

Logging parameters

log-level-console = INFO
log-level-file = OFF
log-filename = pg_probackup.log
log-rotation-size = 0TB
log-rotation-age = 0d

Retention parameters

retention-redundancy = 0
retention-window = 0
wal-depth = 0

Compression parameters

compress-algorithm = none
compress-level = 1

Remote access parameters

remote-proto = ssh
[[email protected] pgsql]$

[[email protected] pgsql]$ pg_probackup-12 backup -B /home/postgres/pg_backup --instance pgsql -b full --log-level-file=VERBOSE
INFO: Backup start, pg_probackup version: 2.4.9, instance: pgsql, backup ID: QOPSTD, backup mode: FULL, wal mode: ARCHIVE, remote: false, compress-algorithm: none, compress-level: 1
WARNING: Current PostgreSQL role is superuser. It is not recommended to run backup or checkdb as superuser.
INFO: Backup QOPSTD is going to be taken from standby
INFO: Wait for WAL segment /home/postgres/pg_backup/wal/pgsql/000000010000000000000029 to be archived
WARNING: By default pg_probackup assume WAL delivery method to be ARCHIVE. If continuous archiving is not set up, use '--stream' option to make autonomous backup. Otherwise check that continuous archiving works correctly.
ERROR: WAL segment 000000010000000000000029 could not be archived in 300 seconds
WARNING: backup in progress, stop backup
WARNING: Backup QOPSTD is running, setting its status to ERROR
[[email protected] pgsql]$

gsmolk · 2021-02-18T08:18:48Z

Please attach /home/postgres/pg_backup/log/pg_probackup.log file.

hunterhuang8810 · 2021-02-18T08:27:26Z

[[email protected] ~]$ pg_probackup-12 backup -B /home/postgres/pg_backup --instance pgsql -b full --log-level-file=VERBOSE
INFO: Backup start, pg_probackup version: 2.4.9, instance: pgsql, backup ID: QOPTVM, backup mode: FULL, wal mode: ARCHIVE, remote: false, compress-algorithm: none, compress-level: 1
WARNING: Current PostgreSQL role is superuser. It is not recommended to run backup or checkdb as superuser.
INFO: Backup QOPTVM is going to be taken from standby
INFO: Wait for WAL segment /home/postgres/pg_backup/wal/pgsql/00000001000000000000002C to be archived
WARNING: By default pg_probackup assume WAL delivery method to be ARCHIVE. If continuous archiving is not set up, use '--stream' option to make autonomous backup. Otherwise check that continuous archiving works correctly.
ERROR: WAL segment 00000001000000000000002C could not be archived in 300 seconds
WARNING: backup in progress, stop backup
WARNING: Backup QOPTVM is running, setting its status to ERROR
[[email protected] ~]$

[[email protected] log]$ cat pg_probackup.log
2021-02-18 16:21:22 CST [292130]: INFO: command: pg_probackup-12 backup -B /home/postgres/pg_backup --instance pgsql -b full --log-level-file=VERBOSE
2021-02-18 16:21:22 CST [292130]: INFO: Backup start, pg_probackup version: 2.4.9, instance: pgsql, backup ID: QOPTVM, backup mode: FULL, wal mode: ARCHIVE, remote: false, compress-algorithm: none, compress-level: 1
2021-02-18 16:21:22 CST [292130]: LOG: Backup destination is initialized
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SELECT pg_catalog.current_setting($1)
2021-02-18 16:21:22 CST [292130]: VERBOSE: (param:0) = block_size
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SELECT pg_catalog.current_setting($1)
2021-02-18 16:21:22 CST [292130]: VERBOSE: (param:0) = wal_block_size
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SELECT pg_catalog.current_setting('is_superuser')
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SELECT proname FROM pg_proc WHERE proname='pgpro_edition'
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SELECT pg_catalog.pg_is_in_recovery()
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SHOW data_checksums
2021-02-18 16:21:22 CST [292130]: LOG: This PostgreSQL instance was initialized with data block checksums. Data block corruption will be detected
2021-02-18 16:21:22 CST [292130]: WARNING: Current PostgreSQL role is superuser. It is not recommended to run backup or checkdb as superuser.
2021-02-18 16:21:22 CST [292130]: INFO: Backup QOPTVM is going to be taken from standby
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SELECT system_identifier FROM pg_catalog.pg_control_system()
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SELECT extnamespace::regnamespace, extversion FROM pg_catalog.pg_extension WHERE extname = 'ptrack'
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SELECT proname FROM pg_proc WHERE proname='ptrack_version'
2021-02-18 16:21:22 CST [292130]: LOG: Database backup start
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SELECT pg_catalog.pg_start_backup($1, $2, false)
2021-02-18 16:21:22 CST [292130]: VERBOSE: (param:0) = 2021-02-18 16:21:22+08 with pg_probackup
2021-02-18 16:21:22 CST [292130]: VERBOSE: (param:1) = true
2021-02-18 16:21:22 CST [292130]: VERBOSE: (query) SELECT timeline_id FROM pg_control_checkpoint()
2021-02-18 16:21:22 CST [292130]: LOG: Looking for segment: 00000001000000000000002C
2021-02-18 16:21:23 CST [292130]: INFO: Wait for WAL segment /home/postgres/pg_backup/wal/pgsql/00000001000000000000002C to be archived
2021-02-18 16:21:52 CST [292130]: WARNING: By default pg_probackup assume WAL delivery method to be ARCHIVE. If continuous archiving is not set up, use '--stream' option to make autonomous backup. Otherwise check that continuous archiving works correctly.
2021-02-18 16:26:23 CST [292130]: ERROR: WAL segment 00000001000000000000002C could not be archived in 300 seconds
2021-02-18 16:26:23 CST [292130]: WARNING: backup in progress, stop backup
2021-02-18 16:26:23 CST [292130]: VERBOSE: (query) SET client_min_messages = warning;
2021-02-18 16:26:23 CST [292130]: VERBOSE: (query) SET datestyle = 'ISO, DMY';
2021-02-18 16:26:23 CST [292130]: VERBOSE: (query) SELECT pg_catalog.txid_snapshot_xmax(pg_catalog.txid_current_snapshot()), current_timestamp(0)::timestamptz, pg_catalog.pg_last_wal_replay_lsn(), labelfile, spcmapfile FROM pg_catalog.pg_stop_backup(false, false)
2021-02-18 16:26:23 CST [292130]: WARNING: Backup QOPTVM is running, setting its status to ERROR
[[email protected] log]$

hunterhuang8810 · 2021-02-18T08:29:22Z

I hope provide a solution to backup success no dependent on wal archive, backup sucess first.

backup sucess first.

gsmolk · 2021-02-18T09:19:53Z

Please try this one and attach the file /home/postgres/pg_backup/log/pg_probackup.log:

pg_probackup-12 backup -B /home/postgres/pg_backup --instance pgsql -b full --log-level-file=VERBOSE --stream

hunterhuang8810 · 2021-02-18T09:41:28Z

seems --stream will finally success, though still wait archive failed.

as below, log file contents is long, I not find where to upload file

[[email protected] ~]$ pg_probackup-12 backup -B /home/postgres/pg_backup --instance pgsql -b full --log-level-file=VERBOSE --stream
INFO: Backup start, pg_probackup version: 2.4.9, instance: pgsql, backup ID: QOPWNX, backup mode: FULL, wal mode: STREAM, remote: false, compress-algorithm: none, compress-level: 1
WARNING: Current PostgreSQL role is superuser. It is not recommended to run backup or checkdb as superuser.
INFO: Backup QOPWNX is going to be taken from standby
INFO: PGDATA size: 158MB
INFO: Start transferring data files
INFO: Data files are transferred, time elapsed: 0
INFO: wait for pg_stop_backup()
INFO: pg_stop backup() successfully executed
INFO: Wait for WAL segment /home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_wal/00000001000000000000002D to be streamed
WARNING: WAL segment 00000001000000000000002D could not be streamed in 300 seconds
WARNING: Failed to get next WAL record after 0/2D000000, looking for previous WAL record
INFO: Syncing backup files to disk
INFO: Backup files are synced, time elapsed: 0
INFO: Validating backup QOPWNX
INFO: Backup QOPWNX data files are valid
INFO: Backup QOPWNX resident size: 174MB
INFO: Backup QOPWNX completed
[[email protected] ~]$

gsmolk · 2021-02-18T09:52:16Z

as below, log file contents is long, I not find where to upload file

You can just attach here - drag and drop.

hunterhuang8810 · 2021-02-18T10:01:11Z

we are not allowed to upload files in company env, so can't upload , need you need still as it can finally success with --stream mode

gsmolk · 2021-02-18T10:11:37Z

Then post messages about WAL streaming after pg_stop_backup execution.

hunterhuang8810 · 2021-02-18T10:13:53Z

2021-02-18 17:21:33 CST [297499]: INFO: command: pg_probackup-12 backup -B /home/postgres/pg_backup --instance pgsql -b full --log-level-file=VERBOSE --stream
2021-02-18 17:21:33 CST [297499]: INFO: Backup start, pg_probackup version: 2.4.9, instance: pgsql, backup ID: QOPWNX, backup mode: FULL, wal mode: STREAM, remote: false, compress-algorithm: none, compress-level: 1
2021-02-18 17:21:33 CST [297499]: LOG: Backup destination is initialized
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT pg_catalog.current_setting($1)
2021-02-18 17:21:33 CST [297499]: VERBOSE: (param:0) = block_size
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT pg_catalog.current_setting($1)
2021-02-18 17:21:33 CST [297499]: VERBOSE: (param:0) = wal_block_size
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT pg_catalog.current_setting('is_superuser')
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT proname FROM pg_proc WHERE proname='pgpro_edition'
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT pg_catalog.pg_is_in_recovery()
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SHOW data_checksums
2021-02-18 17:21:33 CST [297499]: LOG: This PostgreSQL instance was initialized with data block checksums. Data block corruption will be detected
2021-02-18 17:21:33 CST [297499]: WARNING: Current PostgreSQL role is superuser. It is not recommended to run backup or checkdb as superuser.
2021-02-18 17:21:33 CST [297499]: INFO: Backup QOPWNX is going to be taken from standby
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT system_identifier FROM pg_catalog.pg_control_system()
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT extnamespace::regnamespace, extversion FROM pg_catalog.pg_extension WHERE extname = 'ptrack'
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT proname FROM pg_proc WHERE proname='ptrack_version'
2021-02-18 17:21:33 CST [297499]: LOG: Database backup start
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT pg_catalog.pg_start_backup($1, $2, false)
2021-02-18 17:21:33 CST [297499]: VERBOSE: (param:0) = 2021-02-18 17:21:33+08 with pg_probackup
2021-02-18 17:21:33 CST [297499]: VERBOSE: (param:1) = true
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT timeline_id FROM pg_control_checkpoint()
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) show checkpoint_timeout
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) IDENTIFY_SYSTEM
2021-02-18 17:21:33 CST [297499]: LOG: started streaming WAL at 0/2C000000 (timeline 1)
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding file: standby.signal
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding directory content: pg_snapshots
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding directory content: log
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding directory content: pg_serial
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding directory content: pg_stat_tmp
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding directory content: pg_subtrans
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding directory content: pg_replslot
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding file: postmaster.pid
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding file: postmaster.opts
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding directory content: pg_dynshmem
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding directory content: pg_wal
2021-02-18 17:21:33 CST [297499]: VERBOSE: Excluding directory content: pg_notify
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT oid, datname FROM pg_catalog.pg_database WHERE datname NOT IN ('template1', 'template0')
2021-02-18 17:21:33 CST [297499]: INFO: PGDATA size: 158MB
2021-02-18 17:21:33 CST [297499]: LOG: Current Start LSN: 0/2C000060, TLI: 1
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/archivedir'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/base'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/base/1'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/base/12675'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/base/12676'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/base/16385'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/global'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/log'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_commit_ts'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_dynshmem'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_logical'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_logical/mappings'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_logical/snapshots'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_multixact'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_multixact/members'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_multixact/offsets'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_notify'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_replslot'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_serial'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_snapshots'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_stat'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_stat_tmp'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_subtrans'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_tblspc'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_twophase'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_wal'
2021-02-18 17:21:33 CST [297499]: VERBOSE: Create directory '/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_xact'
2021-02-18 17:21:33 CST [297499]: INFO: Start transferring data files
2021-02-18 17:21:33 CST [297499]: VERBOSE: Start thread num: 0
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/PG_VERSION". Copied 3 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/base/16385/PG_VERSION". Copied 3 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/base/12675/PG_VERSION". Copied 3 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/base/1/PG_VERSION". Copied 3 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/base/12676/PG_VERSION". Copied 3 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/pg_logical/replorigin_checkpoint". Copied 8 bytes
。。。。。。。
2021-02-18 17:21:33 CST [297499]: VERBOSE: Writing headers for file "base/12675/1255" offset: 57645, len: 1136, crc: 3150584530
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/base/12675/1255". Copied 647800 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: Writing headers for file "base/12676/1255" offset: 58781, len: 1136, crc: 3150584530
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/base/12676/1255". Copied 647800 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: Writing headers for file "base/16385/1255" offset: 59917, len: 1136, crc: 3150584530
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/base/16385/1255". Copied 647800 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/archivedir/000000010000000000000025". Copied 16777216 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/archivedir/00000001000000000000002B". Copied 16777216 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/archivedir/000000010000000000000021". Copied 16777216 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/archivedir/000000010000000000000020". Copied 16777216 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/archivedir/000000010000000000000014". Copied 16777216 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/archivedir/000000010000000000000024". Copied 16777216 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/archivedir/000000010000000000000023". Copied 16777216 bytes
2021-02-18 17:21:33 CST [297499]: VERBOSE: File "/home/service/var/pgdata/archivedir/000000010000000000000022". Copied 16777216 bytes
2021-02-18 17:21:33 CST [297499]: INFO: Data files are transferred, time elapsed: 0
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SET client_min_messages = warning;
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SET datestyle = 'ISO, DMY';
2021-02-18 17:21:33 CST [297499]: VERBOSE: (query) SELECT pg_catalog.txid_snapshot_xmax(pg_catalog.txid_current_snapshot()), current_timestamp(0)::timestamptz, pg_catalog.pg_last_wal_replay_lsn(), labelfile, spcmapfile FROM pg_catalog.pg_stop_backup(false, false)
2021-02-18 17:21:34 CST [297499]: INFO: wait for pg_stop_backup()
2021-02-18 17:21:34 CST [297499]: INFO: pg_stop backup() successfully executed
2021-02-18 17:21:34 CST [297499]: LOG: Invalid offset in stop_lsn value 0/2D000000, trying to fix
2021-02-18 17:21:34 CST [297499]: LOG: Looking for segment: 00000001000000000000002D
2021-02-18 17:21:35 CST [297499]: INFO: Wait for WAL segment /home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_wal/00000001000000000000002D to be streamed
2021-02-18 17:26:35 CST [297499]: WARNING: WAL segment 00000001000000000000002D could not be streamed in 300 seconds
2021-02-18 17:26:35 CST [297499]: VERBOSE: Thread [0]: Need to switch to the next WAL segment, page LSN 0/2D000000, record being read LSN 0/0
2021-02-18 17:31:36 CST [297499]: WARNING: Failed to get next WAL record after 0/2D000000, looking for previous WAL record
2021-02-18 17:31:36 CST [297499]: LOG: Looking for LSN 0/2D000000 in segment: 00000001000000000000002C
2021-02-18 17:31:36 CST [297499]: LOG: Found WAL segment: /home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_wal/00000001000000000000002C
2021-02-18 17:31:36 CST [297499]: VERBOSE: Thread [0]: Need to switch to the next WAL segment, page LSN 0/2C000000, record being read LSN 0/2C000060
2021-02-18 17:31:36 CST [297499]: LOG: Thread [0]: Opening WAL segment "/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_wal/00000001000000000000002C"
2021-02-18 17:31:36 CST [297499]: LOG: Record 0/2C000148 has endpoint 0/2D000000 which is equal or greater than requested LSN 0/2D000000
2021-02-18 17:31:36 CST [297499]: LOG: Found prior LSN: 0/2C000148
2021-02-18 17:31:36 CST [297499]: LOG: stop_lsn: 0/2D000000
2021-02-18 17:31:43 CST [297499]: LOG: finished streaming WAL at 0/2D000000 (timeline 1)
2021-02-18 17:31:43 CST [297499]: LOG: Getting the Recovery Time from WAL
2021-02-18 17:31:43 CST [297499]: VERBOSE: Thread [0]: Need to switch to the next WAL segment, page LSN 0/2C000000, record being read LSN 0/2C000148
2021-02-18 17:31:43 CST [297499]: LOG: Thread [0]: Opening WAL segment "/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/pg_wal/00000001000000000000002C"
2021-02-18 17:31:43 CST [297499]: LOG: Failed to find Recovery Time in WAL, forced to trust current_timestamp
2021-02-18 17:31:43 CST [297499]: LOG: Current minRecPoint 0/2D000000
2021-02-18 17:31:43 CST [297499]: LOG: Setting minRecPoint to 0/2C000148
2021-02-18 17:31:43 CST [297499]: INFO: Syncing backup files to disk
2021-02-18 17:31:43 CST [297499]: INFO: Backup files are synced, time elapsed: 0
2021-02-18 17:31:43 CST [297499]: INFO: Validating backup QOPWNX
2021-02-18 17:31:43 CST [297499]: VERBOSE: Validate relation blocks for file "/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/base/1/2702"
2021-02-18 17:31:43 CST [297499]: VERBOSE: Validate relation blocks for file "/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/base/1/112"
。。。。。
2021-02-18 17:31:43 CST [297499]: VERBOSE: Validate relation blocks for file "/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/base/12676/1255"
2021-02-18 17:31:43 CST [297499]: VERBOSE: Validate relation blocks for file "/home/postgres/pg_backup/backups/pgsql/QOPWNX/database/base/16385/1255"
2021-02-18 17:31:43 CST [297499]: INFO: Backup QOPWNX data files are valid
2021-02-18 17:31:43 CST [297499]: INFO: Backup QOPWNX resident size: 174MB
2021-02-18 17:31:43 CST [297499]: INFO: Backup QOPWNX completed

hunterhuang8810 · 2021-02-18T10:14:35Z

like above, I skip same kind lines with 。。。。。。

gsmolk · 2021-02-18T10:18:25Z

So with --stream everything works ok.
You should use it =)

hunterhuang8810 · 2021-02-18T10:20:15Z

So with --stream everything works ok.
You should use it =)

stream mode can also support PITR, right?

gsmolk · 2021-02-18T10:51:36Z

stream mode can also support PITR, right?

If archiving is enabled - sure.

hunterhuang8810 · 2021-02-18T10:57:37Z

stream mode can also support PITR, right?

If archiving is enabled - sure.

for not stream issue, do you think it's a bug and should be fixed in future version?

hunterhuang8810 · 2021-02-18T10:59:13Z

stream mode can also support PITR, right?

If archiving is enabled - sure.

for not stream issue, do you think it's a bug and should be fixed in future version?

when db no trasaction, no data change, wal will not switch. under this scenario, backup will failed.
I think db backup should not relate to wal switch and archive.

gsmolk · 2021-02-18T11:10:53Z

for not stream issue, do you think it's a bug and should be fixed in future version?

Yeah, probably, we will think about it.

hunterhuang8810 · 2021-02-19T01:33:38Z

for not stream issue, do you think it's a bug and should be fixed in future version?

Yeah, probably, we will think about it.

As when no any trasaction , wal won't archive, it will always happen, backup will fail.
so I think this should be fixed, backup should not depend on wal archvie I think.

Thanks for your support!

hunterhuang8810 · 2021-02-19T03:28:30Z

--for incremental backup , same issue exists as well:
[[email protected] pgsql]$ pg_probackup-12 backup -B /mnt/cfs/pg_backup --instance pgsql -b DELTA
INFO: Backup start, pg_probackup version: 2.4.9, instance: pgsql, backup ID: QORAIF, backup mode: DELTA, wal mode: ARCHIVE, remote: false, compress-algorithm: none, compress-level: 1
WARNING: Current PostgreSQL role is superuser. It is not recommended to run backup or checkdb as superuser.
INFO: Backup QORAIF is going to be taken from standby
INFO: Parent backup: QOR9EA
INFO: Wait for WAL segment /mnt/cfs/pg_backup/wal/pgsql/000000010000000000000046 to be archived
WARNING: By default pg_probackup assume WAL delivery method to be ARCHIVE. If continuous archiving is not set up, use '--stream' option to make autonomous backup. Otherwise check that continuous archiving works correctly.
ERROR: WAL segment 000000010000000000000046 could not be archived in 300 seconds
WARNING: backup in progress, stop backup
WARNING: Backup QORAIF is running, setting its status to ERROR
[[email protected] pgsql]$

if I add --stream for incr backup, finally will success, but got so much warning message:
[[email protected] pgsql]$ pg_probackup-12 backup -B /mnt/cfs/pg_backup --instance pgsql -b DELTA --stream
INFO: Backup start, pg_probackup version: 2.4.9, instance: pgsql, backup ID: QORAFO, backup mode: DELTA, wal mode: STREAM, remote: false, compress-algorithm: none, compress-level: 1
WARNING: Current PostgreSQL role is superuser. It is not recommended to run backup or checkdb as superuser.
INFO: Backup QORAFO is going to be taken from standby
INFO: Parent backup: QOR9EA
INFO: PGDATA size: 158MB
INFO: Start transferring data files
INFO: Data files are transferred, time elapsed: 0
INFO: wait for pg_stop_backup()
INFO: pg_stop backup() successfully executed
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
INFO: Wait for LSN 0/46000148 in streamed WAL segment /mnt/cfs/pg_backup/backups/pgsql/QORAFO/database/pg_wal/000000010000000000000046
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0
INFO: Syncing backup files to disk
INFO: Backup files are synced, time elapsed: 0
INFO: Validating backup QORAFO
INFO: Backup QORAFO data files are valid
INFO: Backup QORAFO resident size: 16MB
INFO: Backup QORAFO completed
[[email protected] pgsql]$

Hope this can be fixed, backup success is first I concerned.

gsmolk · 2021-03-20T23:04:37Z

if I add --stream for incr backup, finally will success, but got so much warning message:

This is due to how pg_stop_backup() function works in PostgreSQL.
It sometimes returns LSN, pointing to the beginning of the record and sometimes to the end of record.

WARNING: Could not read WAL record at 0/46000148: invalid record length at 0/46000148: wanted 24, got 0

In this case it is the latter.
pg_probackup tries to be conservative here and at first treat the record as if it was pointing to the start of the record.
It this approach fails for 1/2 archive-timeout time, pg_probackup will fallback to treating the LSN as poiting to the end of message.

gsmolk added the bug label Feb 18, 2021

gsmolk added this to the 2.4.11 milestone Feb 18, 2021

gsmolk removed this from the 2.4.12 milestone Mar 25, 2021

gsmolk added this to the 2.4.13 milestone Mar 25, 2021

kulaginm modified the milestones: 2.4.18, 2.5.3 Oct 15, 2021

kulaginm linked a pull request Nov 18, 2021 that will close this issue

Pgpro 5421. --wal-file-path option #437

Merged

kulaginm closed this as completed in #437 Nov 22, 2021

kulaginm modified the milestones: 2.5.4, 2.5.3 Dec 27, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

archive-push problem #330

archive-push problem #330

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 19, 2021

hunterhuang8810 commented Feb 19, 2021

gsmolk commented Mar 20, 2021

archive-push problem #330

archive-push problem #330

Comments

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

postgres=# show archive_timeout ; archive_timeout

postgres=# select pg_switch_wal(); pg_switch_wal

postgres=# select pg_switch_wal(); pg_switch_wal

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

Backup instance information

Connection parameters

Replica parameters

Archive parameters

Logging parameters

Retention parameters

Compression parameters

Remote access parameters

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

hunterhuang8810 commented Feb 18, 2021

gsmolk commented Feb 18, 2021

hunterhuang8810 commented Feb 19, 2021

hunterhuang8810 commented Feb 19, 2021

gsmolk commented Mar 20, 2021

postgres=# show archive_timeout ;
archive_timeout

postgres=# select pg_switch_wal();
pg_switch_wal

postgres=# select pg_switch_wal();
pg_switch_wal