Incremental PAGE backup: Could not read WAL record #394

slothfk · 2021-06-07T21:36:42Z

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 · 2021-06-07T21:43:33Z

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 · 2021-06-07T21:49:58Z

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 · 2021-06-08T06:34:32Z

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

slothfk · 2021-06-08T08:29:03Z

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 · 2021-06-08T08:37:09Z

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

slothfk · 2021-06-08T08:44:34Z

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 · 2021-06-08T08:47:39Z

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 · 2021-06-08T09:09:08Z

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 · 2021-06-08T09:14:56Z

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

gsmolk · 2021-06-08T09:16:09Z

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

slothfk · 2021-06-08T09:51:18Z

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 · 2021-06-08T10:03:38Z

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 · 2021-06-08T10:15:02Z

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 · 2021-06-08T10:27:03Z

Problem file is 00000001000000E000000094

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

slothfk · 2021-06-08T11:42:33Z

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

gsmolk · 2021-06-08T12:43:20Z

Can you please provide a chunk of postgresql-Mon.log log around 2021-06-07 07:00:32.672 ?

slothfk · 2021-06-08T14:20:33Z

Can you please provide a chunk of postgresql-Mon.log log around 2021-06-07 07:00:32.672 ?

I wrote about this in comment #394 (comment)

If this is not enough, then here is a little more

2021-06-07 07:00:26.808 MSK [57702] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
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] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
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] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 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
2021-06-07 07:01:39.705 MSK [57702] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
2021-06-07 07:01:39.705 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
2021-06-07 07:01:42.666 MSK [57702] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
2021-06-07 07:01:42.666 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
2021-06-07 07:01:42.666 MSK [57702] ПРЕДУПРЕЖДЕНИЕ: заархивировать файл журнала предзаписи "00000001000000E000000095" не удалось много раз подряд; следующая попытка будет сделана позжеСООБЩЕНИ
2021-06-07 07:02:44.677 MSK [57702] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
2021-06-07 07:02:44.677 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
2021-06-07 07:02:47.510 MSK [57702] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
2021-06-07 07:02:47.510 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
2021-06-07 07:02:50.358 MSK [57702] СООБЩЕНИЕ: команда архивации завершилась ошибкой с кодом 1
2021-06-07 07:02:50.358 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
2021-06-07 07:02:50.358 MSK [57702] ПРЕДУПРЕЖДЕНИЕ: заархивировать файл журнала предзаписи "00000001000000E000000095" не удалось много раз подряд; следующая попытка будет сделана позжеСООБЩЕНИ

gsmolk · 2021-06-09T15:21:54Z

Нашел баг, который потенциально мог привести к подобному.

gsmolk · 2021-06-09T15:29:04Z

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

Не очень понятно, почему постгрес вдруг забыл про 00000001000000E000000094 и перешел к 00000001000000E000000095 .
Есть ли возможность предоставить этот участок лога целиком?

slothfk · 2021-06-09T15:38:10Z

Есть ли возможность предоставить этот участок лога целиком?

Участок лога привел целиком, скорее всего уровень логировния отличный от первого сервера, надо посмотреть. Хотел это сделать вчера, но отвлекся ...

slothfk · 2021-06-09T15:48:54Z

скорее всего уровень логировния отличный от первого сервера,

странно, настройки логов вроде одинаковые ...

на другом проекте я видел ситуацию, что в лог сыпятся только ошибки возникающие при архивировании, а успешное архивирование никак не фигурирует в логе

в контексте pg_probackup, может ли быть причина в том, что в конфиге я log-level-console перевел в off, а log-level-file в info?

gsmolk · 2021-06-09T16:26:25Z

в контексте pg_probackup, может ли быть причина в том, что в конфиге я log-level-console перевел в off, а log-level-file в info?

Да, может. archive-push и archive-get в remote режиме умеют только в консоль выхлоп давать.

slothfk · 2021-06-09T16:37:34Z

в контексте pg_probackup, может ли быть причина в том, что в конфиге я log-level-console перевел в off, а log-level-file в info?

Да, может. archive-push и archive-get в remote режиме умеют только в консоль выхлоп давать.

Понял, придется вернуть назад ;)

gsmolk · 2021-06-10T09:22:29Z

Можете привести опции монтирования файловой системы, на которой лежат бэкапы?

gsmolk · 2021-06-10T10:24:05Z

Смог воспроизвести.

gsmolk · 2021-06-10T10:27:00Z

$ stat /tmp/test_close/wal/node/00000001000000000000000C
  File: /tmp/test_close/wal/node/00000001000000000000000C
  Size: 16470016

gsmolk · 2021-06-10T10:37:20Z

TODO:

check rc for close()
(sanity?) check uncompressed file size for already existing file in case of checksum mismatch

slothfk · 2021-06-10T11:01:45Z

Можете привести опции монтирования файловой системы, на которой лежат бэкапы?

$ cat /etc/fstab | grep data1
/dev/mapper/data-data /mnt/data1      ext4    defaults        0       2
/mnt/data1/backup       /export/backup          none    bind    0       0

не спрашивайте меня, зачем так, я все равно ответа не знаю :)

…e is implemented

gsmolk · 2021-06-14T11:01:12Z

Исправил.
Фикс выйдет в 2.4.17

slothfk · 2021-06-15T05:51:08Z

Исправил.
Фикс выйдет в 2.4.17

Спасибо!

gsmolk added the bug label Jun 14, 2021

gsmolk self-assigned this Jun 14, 2021

gsmolk added this to the 2.4.17 milestone Jun 14, 2021

gsmolk added a commit that referenced this issue Jun 14, 2021

[Issue #394] correctly detect ENOSPC when using write(): durable_writ…

8ae217b

…e is implemented

gsmolk added a commit that referenced this issue Jun 14, 2021

[Issue #394] fio_close is now synchronous

da2cbcb

gsmolk closed this as completed Jun 14, 2021

gsmolk added a commit that referenced this issue Jun 14, 2021

[Issue #394] use durable_write in fio_write

d1106e5

gsmolk modified the milestones: 2.4.17, 2.5.2 Oct 15, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Incremental PAGE backup: Could not read WAL record #394

Incremental PAGE backup: Could not read WAL record #394

slothfk commented Jun 7, 2021

slothfk commented Jun 7, 2021 •

edited

Loading

slothfk commented Jun 7, 2021

gsmolk commented Jun 8, 2021

slothfk commented Jun 8, 2021

gsmolk commented Jun 8, 2021

slothfk commented Jun 8, 2021

gsmolk commented Jun 8, 2021 •

edited

Loading

slothfk commented Jun 8, 2021 •

edited

Loading

gsmolk commented Jun 8, 2021 •

edited

Loading

gsmolk commented Jun 8, 2021

slothfk commented Jun 8, 2021

gsmolk commented Jun 8, 2021 •

edited

Loading

slothfk commented Jun 8, 2021 •

edited

Loading

gsmolk commented Jun 8, 2021

slothfk commented Jun 8, 2021

gsmolk commented Jun 8, 2021

slothfk commented Jun 8, 2021

gsmolk commented Jun 9, 2021

gsmolk commented Jun 9, 2021

slothfk commented Jun 9, 2021

slothfk commented Jun 9, 2021

gsmolk commented Jun 9, 2021

slothfk commented Jun 9, 2021

gsmolk commented Jun 10, 2021

gsmolk commented Jun 10, 2021

gsmolk commented Jun 10, 2021

gsmolk commented Jun 10, 2021

slothfk commented Jun 10, 2021

gsmolk commented Jun 14, 2021

slothfk commented Jun 15, 2021

Incremental PAGE backup: Could not read WAL record #394

Incremental PAGE backup: Could not read WAL record #394

Comments

slothfk commented Jun 7, 2021

slothfk commented Jun 7, 2021 • edited Loading

slothfk commented Jun 7, 2021

gsmolk commented Jun 8, 2021

slothfk commented Jun 8, 2021

gsmolk commented Jun 8, 2021

slothfk commented Jun 8, 2021

gsmolk commented Jun 8, 2021 • edited Loading

slothfk commented Jun 8, 2021 • edited Loading

gsmolk commented Jun 8, 2021 • edited Loading

gsmolk commented Jun 8, 2021

slothfk commented Jun 8, 2021

gsmolk commented Jun 8, 2021 • edited Loading

slothfk commented Jun 8, 2021 • edited Loading

gsmolk commented Jun 8, 2021

slothfk commented Jun 8, 2021

gsmolk commented Jun 8, 2021

slothfk commented Jun 8, 2021

gsmolk commented Jun 9, 2021

gsmolk commented Jun 9, 2021

slothfk commented Jun 9, 2021

slothfk commented Jun 9, 2021

gsmolk commented Jun 9, 2021

slothfk commented Jun 9, 2021

gsmolk commented Jun 10, 2021

gsmolk commented Jun 10, 2021

gsmolk commented Jun 10, 2021

gsmolk commented Jun 10, 2021

slothfk commented Jun 10, 2021

gsmolk commented Jun 14, 2021

slothfk commented Jun 15, 2021

slothfk commented Jun 7, 2021 •

edited

Loading

gsmolk commented Jun 8, 2021 •

edited

Loading

slothfk commented Jun 8, 2021 •

edited

Loading

gsmolk commented Jun 8, 2021 •

edited

Loading

gsmolk commented Jun 8, 2021 •

edited

Loading

slothfk commented Jun 8, 2021 •

edited

Loading