Incremental PAGE backup: Could not read WAL record

[slothfk]

I have a some problem with incremental backup (PAGE)

Backup log looks like

2021-06-07 22:04:29 MSK [9524]: INFO: command: /usr/bin/pg_probackup-11 backup --instance pg_server -b PAGE --compress -j 2 --delete-expired --merge-expired --delete-wal
2021-06-07 22:04:29 MSK [9524]: INFO: Backup start, pg_probackup version: 2.4.15, instance: pg_server, backup ID: QUCIBH, backup mode: PAGE, wal mode: ARCHIVE, remote: true, compress-algorithm: zlib, compress-level: 1
2021-06-07 22:04:29 MSK [9524]: WARNING: This PostgreSQL instance was initialized without data block checksums. pg_probackup have no way to detect data block corruption without them. Reinitialize PGDATA with option '--data-checksums'.
2021-06-07 22:04:30 MSK [9524]: INFO: wait for pg_start_backup()
2021-06-07 22:04:30 MSK [9524]: INFO: Parent backup: QUAPJ1
2021-06-07 22:04:32 MSK [9524]: INFO: Wait for WAL segment /export/backup/wal/pg_server/00000001000000E10000008C to be archived
2021-06-07 22:04:36 MSK [9524]: INFO: PGDATA size: 20GB
2021-06-07 22:04:36 MSK [9524]: INFO: Extracting pagemap of changed blocks
2021-06-07 22:04:39 MSK [9524]: WARNING: Thread [1]: Could not read WAL record at E0/94799998: unexpected pageaddr E0/94800000 in log segment 00000001000000E000000094, offset 7970816
2021-06-07 22:04:39 MSK [9524]: ERROR: Thread [1]: Possible WAL corruption. Error has occured during reading WAL segment "/export/backup/wal/pg_server/00000001000000E000000094"
2021-06-07 22:04:39 MSK [9524]: ERROR: Thread [2]: Interrupted during WAL reading
2021-06-07 22:04:39 MSK [9524]: ERROR: Pagemap extraction failed, time elasped: 3 sec
2021-06-07 22:04:39 MSK [9524]: WARNING: backup in progress, stop backup

My system is

$ cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=18.04
DISTRIB_CODENAME=bionic
DISTRIB_DESCRIPTION="Ubuntu 18.04.5 LTS"

$ pg_probackup-11 --version
pg_probackup-11 2.4.15 (PostgreSQL 11.11)

$ /usr/lib/postgresql/11/bin/postgres --version
postgres (PostgreSQL) 11.7 (Ubuntu 11.7-5.1C)

I have this problem on two different servers and no idea what is wrong

[slothfk]

I think it's may be important too, because backup is remote

$ sudo -i -u probackup pg_probackup-11 show-config --instance pg_server
# Backup instance information
pgdata = /pgdata/postgresql/11/main
system-identifier = 6896808033732677837
xlog-seg-size = 16777216
external-dirs = /etc/postgresql/11/main
# Connection parameters
pgdatabase = probackup
pghost = pg_server
# Replica parameters
replica-timeout = 5min
# Archive parameters
archive-timeout = 5min
# Logging parameters
log-level-console = OFF
log-level-file = INFO
log-filename = pg_probackup.log
log-directory = /export/backup/log
log-rotation-size = 0TB
log-rotation-age = 0d
# Retention parameters
retention-redundancy = 2
retention-window = 30
wal-depth = 3
# Compression parameters
compress-algorithm = none
compress-level = 1
# Remote access parameters
remote-proto = ssh
remote-host = pg_server
remote-port = 22
remote-user = postgres

[slothfk]

Another server backup log

2021-06-06 22:00:01 MSK [48221]: INFO: command: /usr/bin/pg_probackup-11 backup --instance pg_server1 -b PAGE --compress -j 2 --delete-expired --merge-expired --delete-wal
2021-06-06 22:00:01 MSK [48221]: INFO: Backup start, pg_probackup version: 2.4.15, instance: pg_server1, backup ID: QUANG1, backup mode: PAGE, wal mode: ARCHIVE, remote: true, compress-algorithm: zlib, compress-level: 1
2021-06-06 22:00:01 MSK [48221]: WARNING: This PostgreSQL instance was initialized without data block checksums. pg_probackup have no way to detect data block corruption without them. Reinitialize PGDATA with option '--data-checksums'.
2021-06-06 22:00:03 MSK [48221]: INFO: wait for pg_start_backup()
2021-06-06 22:00:03 MSK [48221]: INFO: Parent backup: QU8SS1
2021-06-06 22:00:04 MSK [48221]: INFO: Wait for WAL segment /export/backup/wal/pg_server1/000000010000001F0000000B to be archived
2021-06-06 22:00:07 MSK [48221]: INFO: PGDATA size: 434MB
2021-06-06 22:00:07 MSK [48221]: INFO: Extracting pagemap of changed blocks
2021-06-06 22:00:08 MSK [48221]: WARNING: Thread [2]: Could not read WAL record at 1E/FA8B9FF8: unexpected pageaddr 1E/FA900000 in log segment 000000010000001E000000FA, offset 9150464
2021-06-06 22:00:08 MSK [48221]: ERROR: Thread [2]: Possible WAL corruption. Error has occured during reading WAL segment "/export/backup/wal/pg_server1/000000010000001E000000FA"
2021-06-06 22:00:08 MSK [48221]: ERROR: Thread [1]: Interrupted during WAL reading
2021-06-06 22:00:08 MSK [48221]: ERROR: Pagemap extraction failed, time elasped: 1 sec
2021-06-06 22:00:08 MSK [48221]: WARNING: backup in progress, stop backup
2021-06-06 22:00:08 MSK [48221]: WARNING: Backup QUANG1 is running, setting its status to ERROR

[gsmolk]

Hello!
Can you provide the pg_waldump output for these files - 00000001000000E000000094 and 000000010000001E000000FA?

[slothfk]

Tail of pg_waldump for 000000010000001E000000FA look like

$ /usr/lib/postgresql/11/bin/pg_waldump -p ./ -s 1E/FA8B9000
первая запись обнаружена после 1E/FA8B9000, в позиции 1E/FA8B9CE8, пропускается 3304 Б
rmgr: Transaction len (rec/tot):     34/    34, tx:   41588807, lsn: 1E/FA8B9CE8, prev 1E/FA8B86E8, desc: COMMIT 2021-06-06 01:59:21.586417 MSK
rmgr: Heap        len (rec/tot):     89/    89, tx:   41588808, lsn: 1E/FA8B9D10, prev 1E/FA8B9CE8, desc: HOT_UPDATE off 4 xmax 41588808 ; new off 5 xmax 0, blkref #0: rel 1663/61568/3050978 blk 1
rmgr: Transaction len (rec/tot):     34/    34, tx:   41588808, lsn: 1E/FA8B9D70, prev 1E/FA8B9D10, desc: COMMIT 2021-06-06 01:59:21.618743 MSK
rmgr: Heap        len (rec/tot):    174/   174, tx:   41588809, lsn: 1E/FA8B9D98, prev 1E/FA8B9D70, desc: HOT_UPDATE off 10 xmax 41588809 ; new off 16 xmax 0, blkref #0: rel 1663/61568/3043386 blk 0
rmgr: Transaction len (rec/tot):     34/    34, tx:   41588809, lsn: 1E/FA8B9E48, prev 1E/FA8B9D98, desc: COMMIT 2021-06-06 01:59:22.279005 MSK
rmgr: Heap        len (rec/tot):     54/    54, tx:   41588810, lsn: 1E/FA8B9E70, prev 1E/FA8B9E48, desc: DELETE off 44 KEYS_UPDATED , blkref #0: rel 1663/61568/3047747 blk 0
rmgr: Heap        len (rec/tot):    135/   135, tx:   41588810, lsn: 1E/FA8B9EA8, prev 1E/FA8B9E70, desc: INSERT off 5, blkref #0: rel 1663/61568/3047747 blk 0
rmgr: Btree       len (rec/tot):    104/   104, tx:   41588810, lsn: 1E/FA8B9F30, prev 1E/FA8B9EA8, desc: INSERT_LEAF off 13, blkref #0: rel 1663/61568/3835328 blk 1
rmgr: Transaction len (rec/tot):     34/    34, tx:   41588810, lsn: 1E/FA8B9F98, prev 1E/FA8B9F30, desc: COMMIT 2021-06-06 01:59:22.297038 MSK
rmgr: Heap        len (rec/tot):     54/    54, tx:   41588811, lsn: 1E/FA8B9FC0, prev 1E/FA8B9F98, desc: DELETE off 41 KEYS_UPDATED , blkref #0: rel 1663/61568/3050651 blk 0
pg_waldump: СБОЙ:  ошибка в записи WAL в позиции 1E/FA8B9FC0: unexpected pageaddr 1E/FA900000 in log segment 000000000000001E000000FA, offset 9150464

[gsmolk]

Looks like a WAL Archive corruption.
How WAL archive is populated? pg_receivexlog? archive_command? If so, please provide the archive_command.

[slothfk]

00000001000000E000000094 and 000000010000001E000000FA

This files have a different size by other

$ du -b /export/backup/wal/pg_server1/000000010000001E000000FA 
10620928        /export/backup/wal/pg_server1/000000010000001E000000FA
$ du -b /export/backup/wal/pg_server1/000000010000001E000000F9
16777216        /export/backup/wal/pg_server1/000000010000001E000000F9
$ du -b /export/backup/wal/pg_server1/000000010000001E000000FB
16777216        /export/backup/wal/pg_server1/000000010000001E000000FB
$ du -b /export/backup/wal/pg_server/00000001000000E000000094
9019392 /export/backup/wal/pg_server/00000001000000E000000094
$ du -b /export/backup/wal/pg_server/00000001000000E000000093
16777216        /export/backup/wal/pg_server/00000001000000E000000093
$ du -b /export/backup/wal/pg_server/00000001000000E000000095
16777216        /export/backup/wal/pg_server/00000001000000E000000095

wal files archive by command

archive_command = '/usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=%f --remote-user probackup --remote-host file_server'

[gsmolk]

Can you lookup the PostgreSQL server log at the mtime of those files ? It will help to understand what went wrong with archive-push

[slothfk]

Wow!

2021-06-06 02:34:21 MSK [21706]: [1-1]: ERROR: Cannot write to the remote file "/export/backup/wal/pg_server1/000000010000001E000000FA.part": No space left on device

I'm surprised! I need a time to find out the details!

[gsmolk]

But how 000000010000001E000000FA.part ended up in 000000010000001E000000FA ?
Did you by any chance renamed it manually?

[gsmolk]

Is there a later record in PostgreSQL log about successful archiving of 000000010000001E000000FA ?

[slothfk]

The moment when

000000010000001E000000FA.part ended up in 000000010000001E000000FA

in postgres log look like

2021-06-06 07:02:27 MSK [45620]: [1-1]: ERROR: Cannot write to the remote file "/export/backup/wal/pg_server1/000000010000001E000000FA.part": No space left on device
2021-06-06 07:02:27.246 MSK [43834] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
2021-06-06 07:02:27.246 MSK [43834] ПОДРОБНОСТИ: Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=000000010000001E000000FA --remote-user probackup --remote-host file_server
2021-06-06 07:02:29 MSK [45677]: [1-1]: INFO: pg_probackup archive-push WAL file: 000000010000001E000000FA, threads: 1/1, batch: 1/1, compression: none
2021-06-06 07:02:30 MSK [45677]: [1-1]: INFO: pg_probackup archive-push completed successfully, pushed: 1, skipped: 0, time elapsed: 311ms
2021-06-06 07:02:31 MSK [45694]: [1-1]: INFO: pg_probackup archive-push WAL file: 000000010000001E000000FB, threads: 1/1, batch: 1/1, compression: none
2021-06-06 07:02:32 MSK [45694]: [1-1]: ERROR: Cannot write to the remote file "/export/backup/wal/pg_server1/000000010000001E000000FB.part": No space left on device
2021-06-06 07:02:32.099 MSK [43834] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
2021-06-06 07:02:32.099 MSK [43834] ПОДРОБНОСТИ: Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=000000010000001E000000FB --remote-user probackup --remote-host file_server
2021-06-06 07:02:34 MSK [45767]: [1-1]: INFO: pg_probackup archive-push WAL file: 000000010000001E000000FB, threads: 1/1, batch: 1/1, compression: none
2021-06-06 07:02:35 MSK [45767]: [1-1]: ERROR: Cannot write to the remote file "/export/backup/wal/pg_server1/000000010000001E000000FB.part": No space left on device
2021-06-06 07:02:35.029 MSK [43834] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
2021-06-06 07:02:35.029 MSK [43834] ПОДРОБНОСТИ: Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=000000010000001E000000FB --remote-user probackup --remote-host file_server

In log on file_server i can't find anything suspected

[gsmolk]

Interesting.

2021-06-06 07:02:27 MSK [45620]: [1-1]: ERROR: Cannot write to the remote file "/export/backup/wal/pg_server1/000000010000001E000000FA.part": No space left on device
2021-06-06 07:02:29 MSK [45677]: [1-1]: INFO: pg_probackup archive-push WAL file: 000000010000001E000000FA, threads: 1/1, batch: 1/1, compression: none
2021-06-06 07:02:30 MSK [45677]: [1-1]: INFO: pg_probackup archive-push completed successfully, pushed: 1, skipped: 0, time elapsed: 311ms

It may indicate that we somehow ignored out of space condition second time we run archive-push.
I will look into it.
Can you also grep log about 00000001000000E10000008C from second PostgreSQL instance?

[slothfk]

Can you also grep log about 00000001000000E10000008C from second PostgreSQL instance?

But not 00000001000000E10000008C ! Problem file is 00000001000000E000000094

2021-06-07 22:04:39 MSK [9524]: WARNING: Thread [1]: Could not read WAL record at E0/94799998: unexpected pageaddr E0/94800000 in log segment 00000001000000E000000094, offset 7970816

Postgres log at this time

2021-06-07 07:00:32.672 MSK [57702] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
2021-06-07 07:00:32.672 MSK [57702] ПОДРОБНОСТИ: Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 07:00:32.672 MSK [57702] ПРЕДУПРЕЖДЕНИЕ: заархивировать файл журнала предзаписи "00000001000000E000000094" не удалось много раз подряд; следующая попытка будет сделана позжеПРЕДУПРЕ
2021-06-07 07:01:36.794 MSK [57702] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
2021-06-07 07:01:36.794 MSK [57702] ПОДРОБНОСТИ: Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000095 --remote-user probackup --remote-host file_server

[gsmolk]

Problem file is 00000001000000E000000094

Sure, my mistake.
Can you just run grep 00000001000000E000000094 on PostgreSQL server logs ?

[slothfk]

Can you just run grep 00000001000000E000000094 on PostgreSQL server logs ?

$ sudo grep 00000001000000E000000094 /pgdata/postgresql/11/main/pg_log/postgresql-Mon.log > pg.log

$ wc -l pg.log 
1068 pg.log

$ head pg.log 
2021-06-07 02:20:58.967 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 02:21:01.753 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 02:21:04.613 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 02:21:04.613 MSK [57702] ПРЕДУПРЕЖДЕНИЕ:  заархивировать файл журнала предзаписи "00000001000000E000000094" не удалось много раз подряд; следующая попытка будет сделана позже000000E0
2021-06-07 02:22:06.563 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 02:22:09.240 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 02:22:11.873 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 02:22:11.873 MSK [57702] ПРЕДУПРЕЖДЕНИЕ:  заархивировать файл журнала предзаписи "00000001000000E000000094" не удалось много раз подряд; следующая попытка будет сделана позже000000E0
2021-06-07 02:23:13.812 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 02:23:16.676 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server

$ tail pg.log                                                                                                      
2021-06-07 06:58:16.869 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 06:58:16.869 MSK [57702] ПРЕДУПРЕЖДЕНИЕ:  заархивировать файл журнала предзаписи "00000001000000E000000094" не удалось много раз подряд; следующая попытка будет сделана позжеПОДРОБНО
2021-06-07 06:59:18.834 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 06:59:21.829 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 06:59:24.787 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 06:59:24.787 MSK [57702] ПРЕДУПРЕЖДЕНИЕ:  заархивировать файл журнала предзаписи "00000001000000E000000094" не удалось много раз подряд; следующая попытка будет сделана позже000000E0
2021-06-07 07:00:26.808 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 07:00:29.758 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 07:00:32.672 MSK [57702] ПОДРОБНОСТИ:  Команда архивации с ошибкой: /usr/bin/pg_probackup-11 archive-push -B /export/backup --instance $(hostname -s) --wal-file-name=00000001000000E000000094 --remote-user probackup --remote-host file_server
2021-06-07 07:00:32.672 MSK [57702] ПРЕДУПРЕЖДЕНИЕ:  заархивировать файл журнала предзаписи "00000001000000E000000094" не удалось много раз подряд; следующая попытка будет сделана позже000000E0