postgrespro / pg_probackup

Backup and recovery manager for PostgreSQL
https://postgrespro.github.io/pg_probackup/
Other
703 stars 86 forks source link

WAL segment is absent... И как быть? #587

Closed ktulkhu closed 1 year ago

ktulkhu commented 1 year ago

При попытке восстановления на заданное время, возникает ошибка

WARNING: Skipping backup RPQT69, because it has non-valid status: ERROR
WARNING: Thread [1]: Could not read WAL record at 1/7C030DD8
ERROR: Thread [1]: WAL segment "/backup/pg/probackup/wal/hr/00000001000000010000007C" is absent
ERROR: Thread [2]: Interrupted during WAL reading
WARNING: Recovery can be done up to time 2023-02-07 22:44:33+07, xid 38885 and LSN 1/7C030DD8
ERROR: Not enough WAL records to time 2023-02-08 00:00:00+07

смотрю при этом, бэкапы PAGE - сделались, со статусом OK, время, на которое восстанавливаюсь, лежит между последним и предпоследним PAGE бэкапами:

# pg_probackup-14 show --instance=hr -B /backup/pg/probackup
========================================================================================================================================
 Instance  Version  ID      Recovery Time           Mode   WAL Mode  TLI     Time    Data   WAL  Zratio  Start LSN   Stop LSN    Status
========================================================================================================================================
 hr        14       RPSPCN  2023-02-09 11:19:40+07  PAGE   ARCHIVE   1/1   10m:9s   245kB  16MB    1.00  1/840000D8  1/840001C0  OK
 hr        14       RPRFB4  2023-02-08 18:45:08+07  PAGE   ARCHIVE   1/1   10m:8s    33MB  16MB    1.00  1/83000028  1/83000110  OK
 hr        14       RPR8Q4  2023-02-08 16:22:56+07  PAGE   ARCHIVE   1/1   10m:8s   245kB  16MB    1.00  1/83000028  1/83000110  OK
 hr        14       RPR6I8  2023-02-08 15:35:00+07  PAGE   ARCHIVE   1/1   10m:9s    33MB  16MB    1.00  1/83000028  1/83000110  OK
 hr        14       RPQZTZ  2023-02-08 13:10:50+07  PAGE   ARCHIVE   1/1   10m:8s   245kB  16MB    1.03  1/83000028  1/83000110  OK
 hr        14       RPQY5F  2023-02-08 12:36:07+07  PAGE   ARCHIVE   1/1   6m:48s    33MB  16MB    1.00  1/82000028  1/83000028  OK
 hr        14       RPQXZA  2023-02-08 12:31:04+07  DELTA  STREAM    1/1   2m:54s   271kB  16MB    1.47  1/82000028  1/820000A0  OK
 hr        14       RPQT69  ----                    PAGE   ARCHIVE   1/1    5m:3s       0     0    1.00  1/7C030CF0  0/0         ERROR
 hr        14       RPQSBP  2023-02-08 10:28:52+07  DELTA  STREAM    1/1  10m:26s    33MB  16MB    1.00  1/7C030CF0  1/7C030DD8  OK
 hr        14       RPQR60  2023-02-08 10:03:52+07  DELTA  STREAM    1/1  10m:24s   119kB  16MB    1.00  1/7C030CF0  1/7C030DD8  OK
 hr        14       RPQJ7A  2023-02-08 07:14:43+07  FULL   STREAM    1/0  13m:22s  3233MB  16MB    2.07  1/7C030CF0  1/7C030DD8  OK
 hr        14       RPPVKY  2023-02-07 22:44:33+07  FULL ``  STREAM    1/0  13m:28s  3233MB  16MB    2.07  1/7C030CF0  1/7C030DD8  OK
 hr        14       RPPTQO  ----                    FULL   STREAM    1/0   6m:32s  2297MB     0    2.49  1/7C030CF0  0/0         ERROR
 hr        ----     RPPTQD  ----                    FULL   STREAM    0/0        0       0     0    1.00  0/0         0/0         ERROR
 hr        ----     RPPTKV  ----                    FULL   STREAM    0/0       1s       0     0    1.00  0/0         0/0         ERROR

проверяю наличие WAL в каталоге бэкапа

# pg_probackup-14 show --instance=hr -B /backup/pg/probackup --archive
ARCHIVE INSTANCE 'hr'
================================================================================================================================
 TLI  Parent TLI  Switchpoint  Min Segno                 Max Segno                 N segments  Size   Zratio  N backups  Status
================================================================================================================================
 1    0           0/0          000000010000000100000080  000000010000000100000084  5           359kB  228.38  13         OK

прогоняю тестирование:

 pg_probackup-14 validate --instance=hr -B /backup/pg/probackup --recovery-target-time="2023-02-08 19:50:08" -j 2
INFO: Validating parents for backup RPRFB4
INFO: Validating backup RPQJ7A
INFO: Backup RPQJ7A data files are valid
INFO: Validating backup RPQR60
INFO: Backup RPQR60 data files are valid
INFO: Validating backup RPQSBP
INFO: Backup RPQSBP data files are valid
INFO: Validating backup RPQXZA
INFO: Backup RPQXZA data files are valid
INFO: Validating backup RPQY5F
INFO: Backup RPQY5F data files are valid
INFO: Validating backup RPQZTZ
INFO: Backup RPQZTZ data files are valid
INFO: Validating backup RPR6I8
INFO: Backup RPR6I8 data files are valid
INFO: Validating backup RPR8Q4
INFO: Backup RPR8Q4 data files are valid
INFO: Validating backup RPRFB4
INFO: Backup RPRFB4 data files are valid
WARNING: Thread [2]: Could not read WAL record at 1/85000000
ERROR: Thread [2]: WAL segment "/backup/pg/probackup/wal/hr/000000010000000100000085" is absent
ERROR: Thread [1]: Interrupted during WAL reading
WARNING: Recovery can be done up to time 2023-02-08 18:45:08+07, xid 0 and LSN 1/840001C0
ERROR: Not enough WAL records to time 2023-02-08 19:50:08+07

начинаю разбираться.. в логе бэкапа:

08-02-2023 18:45:04: start PAGE backup of hr
INFO: Backup start, pg_probackup version: 2.5.11, instance: hr, backup ID: RPRFB4, backup mode: PAGE, wal mode: ARCHIVE, remote: true, compress-algorithm: zlib, compress-level: 1
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'.
INFO: Backup RPRFB4 is going to be taken from standby
INFO: Database backup start
INFO: wait for pg_start_backup()
INFO: Parent backup: RPR8Q4
INFO: PGDATA size: 6687MB
INFO: Current Start LSN: 1/83000028, TLI: 1
INFO: Parent Start LSN: 1/83000028, TLI: 1
INFO: Extracting pagemap of changed blocks
INFO: Pagemap successfully extracted, time elapsed: 0 sec
INFO: Start transferring data files
INFO: Data files are transferred, time elapsed: 1s
INFO: wait for pg_stop_backup()
INFO: pg_stop backup() successfully executed
INFO: Wait for WAL segment /backup/pg/probackup/wal/hr/000000010000000100000084 to be archived
WARNING: WAL segment 000000010000000100000084 could not be archived in 300 seconds
WARNING: Failed to get next WAL record after 1/84000000, looking for previous WAL record
INFO: stop_lsn: 1/84000000
INFO: Getting the Recovery Time from WAL
INFO: Failed to find Recovery Time in WAL, forced to trust current_timestamp
INFO: Syncing backup files to disk
INFO: Backup files are synced, time elapsed: 0
INFO: Validating backup RPRFB4
INFO: Backup RPRFB4 data files are valid
INFO: Backup RPRFB4 resident size: 33MB
INFO: Backup RPRFB4 completed
INFO: Evaluate backups by retention
INFO: Backup RPRFB4, mode: PAGE, status: OK. Redundancy: 1/2, Time Window: 0d/14d. Active
INFO: Backup RPR8Q4, mode: PAGE, status: OK. Redundancy: 1/2, Time Window: 0d/14d. Active
INFO: Backup RPR6I8, mode: PAGE, status: OK. Redundancy: 1/2, Time Window: 0d/14d. Active
INFO: Backup RPQZTZ, mode: PAGE, status: OK. Redundancy: 1/2, Time Window: 0d/14d. Active
INFO: Backup RPQY5F, mode: PAGE, status: OK. Redundancy: 1/2, Time Window: 0d/14d. Active
INFO: Backup RPQXZA, mode: DELTA, status: OK. Redundancy: 1/2, Time Window: 0d/14d. Active
INFO: Backup RPQT69, mode: PAGE, status: ERROR. Redundancy: 1/2, Time Window: 0d/14d. Active
INFO: Backup RPQSBP, mode: DELTA, status: OK. Redundancy: 1/2, Time Window: 0d/14d. Active
INFO: Backup RPQR60, mode: DELTA, status: OK. Redundancy: 1/2, Time Window: 0d/14d. Active
INFO: Backup RPQJ7A, mode: FULL, status: OK. Redundancy: 1/2, Time Window: 0d/14d. Active
INFO: Backup RPPVKY, mode: FULL, status: OK. Redundancy: 2/2, Time Window: 0d/14d. Active
INFO: Backup RPPTQO, mode: FULL, status: ERROR. Redundancy: 3/2, Time Window: 0d/14d. Active
INFO: Backup RPPTQD, mode: FULL, status: ERROR. Redundancy: 3/2, Time Window: 0d/14d. Active
INFO: Backup RPPTKV, mode: FULL, status: ERROR. Redundancy: 3/2, Time Window: 0d/14d. Active
INFO: Retention merging finished
INFO: There are no backups to merge by retention policy
INFO: There are no backups to delete by retention policy
INFO: There is no WAL to purge by retention policy
08-02-2023 18:55:13: PAGE backup of hr finished
08-02-2023 18:55:13: last backup is: "OK"

обращаю внимание на вот такие строчки:

INFO: Wait for WAL segment /backup/pg/probackup/wal/hr/000000010000000100000084 to be archived
WARNING: WAL segment 000000010000000100000084 could not be archived in 300 seconds
WARNING: Failed to get next WAL record after 1/84000000, looking for previous WAL record

подозреваю, что какая-то проблема с WAL.. смотрю, какие WAL создавались в класетере постгри в это время выясняю, что в базе не было никакой активности, следовательно, нет и вообще никаких WAL.. (база тестовая)

в настройках кластера, что касается WAL:

archive_timeout = 240
checkpoint_timeout = 15min

но при этом в документации сказано: Когда этот параметр (checkpoint_timeout) больше нуля, сервер будет переключаться на новый файл сегмента, если с момента последнего переключения на новый файл прошло заданное время и наблюдалась какая-то активность базы данных, даже если это была просто контрольная точка. (Контрольные точки пропускаются, если в базе отсутствует активность).

следовательно, если нет активности вообще, то не будет и переключения WAL. И тогда бэкапы в режиме PAGE будут вот такими.. как будто бы живыми, но на самом деле - поломанными, чтоли?

Ради проверки, я создал просто запись в таблице, произошло принудительное переключение WAL, он приехал в каталог бэкапов..

# pg_probackup-14 show --instance=hr -B /backup/pg/probackup --archive

ARCHIVE INSTANCE 'hr'
================================================================================================================================
 TLI  Parent TLI  Switchpoint  Min Segno                 Max Segno                 N segments  Size   Zratio  N backups  Status
================================================================================================================================
 1    0           0/0          000000010000000100000080  000000010000000100000085  6           430kB  228.36  13         OK

Запустил валидацию, она на этот раз прошла успешно (ну а чо, WAL же есть консистентный :))

pg_probackup-14 validate --instance=hr -B /backup/pg/probackup --recovery-target-time="2023-02-08 19:50:08" -j 2
INFO: Validating parents for backup RPRFB4
INFO: Validating backup RPQJ7A
INFO: Backup RPQJ7A data files are valid
INFO: Validating backup RPQR60
INFO: Backup RPQR60 data files are valid
INFO: Validating backup RPQSBP
INFO: Backup RPQSBP data files are valid
INFO: Validating backup RPQXZA
INFO: Backup RPQXZA data files are valid
INFO: Validating backup RPQY5F
INFO: Backup RPQY5F data files are valid
INFO: Validating backup RPQZTZ
INFO: Backup RPQZTZ data files are valid
INFO: Validating backup RPR6I8
INFO: Backup RPR6I8 data files are valid
INFO: Validating backup RPR8Q4
INFO: Backup RPR8Q4 data files are valid
INFO: Validating backup RPRFB4
INFO: Backup RPRFB4 data files are valid
INFO: Backup validation completed successfully on time 2023-02-09 16:20:06+07, xid 38889 and LSN 1/85000108
INFO: Backup RPRFB4 is valid.
INFO: Validate of backup RPRFB4 completed.

Это подтвердило мою мысль, что дело в этом, в отстутсвии активности, и как следствие, WAL-ов. Но, при этом, восстанавливаться бэкап все-равно отказался, с той же ошибкой:

WARNING: Skipping backup RPQT69, because it has non-valid status: ERROR
WARNING: Thread [1]: Could not read WAL record at 1/7C030DD8
ERROR: Thread [1]: WAL segment "/backup/pg/probackup/wal/hr/00000001000000010000007C" is absent
WARNING: Thread [2]: Could not read WAL record at 1/7D000000
ERROR: Thread [2]: WAL segment "/backup/pg/probackup/wal/hr/00000001000000010000007D" is absent
WARNING: Recovery can be done up to time 2023-02-07 22:44:33+07, xid 38885 and LSN 1/7C030DD8
ERROR: Not enough WAL records to time 2023-02-08 00:00:00+07

Причем, pg_probackup считает при этом всю цепочку бэкапов поломанной, и сообщает, что время, на которое можно восстановиться - вообще от самого первого фулла в цеопчке: 2023-02-07 22:44:33+07

hr 14 RPPVKY 2023-02-07 22:44:33+07 FULL STREAM 1/0 13m:28s 3233MB 16MB 2.07 1/7C030CF0 1/7C030DD8 OK

При этом, если поглядеть, то WAL-файлы то есть:

ls -l /backup/pg/probackup/wal/hr
total 504
-rw------- 1 postgres postgres 73524 Feb  8 12:26 000000010000000100000080.gz
-rw------- 1 postgres postgres 73381 Feb  8 12:26 000000010000000100000081.gz
-rw------- 1 postgres postgres 73545 Feb  8 12:37 000000010000000100000082.gz
-rw------- 1 postgres postgres 73410 Feb  8 12:41 000000010000000100000083.gz
-rw------- 1 postgres postgres 73453 Feb  9 10:14 000000010000000100000084.gz
-rw------- 1 postgres postgres 73494 Feb  9 16:21 000000010000000100000085.gz
-rw------- 1 postgres postgres 73409 Feb  9 16:25 000000010000000100000086.gz

но, так как они очень редкие, и сделаны не во время выполнения инкрементных бэкапов, то сами бэкапы закончились с ворнингами по таймаутам, и, следовательно, считаются вот такими, хоромыми.. я не знаю, как правильно и последовательно объяснить этот механизм, но думаю, дело как раз в этом, в крайне редком переключении WAL.. Следовательно, PITR восстановление в этом случае не будет отрабатывать. Нужно еще будет проверить, если указать какой-то из PAGE бэкапов директивно, будет ли восстанавливаться успешно по цепочке инкрементов, при отсутствии "промежуточных" WAL между инкрементами..

Оно, вроде, получается, и не баг.. Но поведение какое-то странное. Как и что нужно делать в этом случае? Все бы решило директивное переключение WAL в кластере, но я не нашел настроек, которые бы позволили это сделать при нулевой активности в базе.

Получается, если, например, выходные, никто ничего в базе не поделал, то и бэкапы, которые инкрементные в автоматическом режиме, они тоже будут иметь такой вот статус.. "консистентно-неконсистентный".. И как быть в этом случае..? Ведь любой PITR при этом будет завершаться сбоем и нужно будет каждый раз проводить расследование?

funny-falcon commented 1 year ago
 hr        14       RPQSBP  2023-02-08 10:28:52+07  DELTA  STREAM    1/1  10m:26s    33MB  16MB    1.00  1/7C030CF0  1/7C030DD8  OK
 hr        14       RPQR60  2023-02-08 10:03:52+07  DELTA  STREAM    1/1  10m:24s   119kB  16MB    1.00  1/7C030CF0  1/7C030DD8  OK
 hr        14       RPQJ7A  2023-02-08 07:14:43+07  FULL   STREAM    1/0  13m:22s  3233MB  16MB    2.07  1/7C030CF0  1/7C030DD8  OK

У вас тут одинаковые start и stop lsn. Т.е. не было активности вообще?

 hr        14       RPQT69  ----                    PAGE   ARCHIVE   1/1    5m:3s       0     0    1.00  1/7C030CF0  0/0         ERROR

Не дождался архивации?

Как и что нужно делать в этом случае?

Для работы PITR должна быть настроена архивация логов. У вас логи начинаются 000000010000000100000080.gz . Логов 00000001000000010000007x.gz у вас нет в папке wal. Что вы хотите? Наверняка такие файлы есть в папках pg_wal (pg_xlog?) конкретных бэкапов. Но там будет на момент бэкапа (между start lsn и stop lsn). Вы можете попробовать скопировать их оттуда в папку wal/hr

ktulkhu commented 1 year ago

У вас тут одинаковые start и stop lsn. Т.е. не было активности вообще?

Да. Не было активности вообще. Я об этом и говорю. И WAL не генерились. Тоже вообще. Ни одного. И да, бэкап не дождался архивации, я ж об этом и написал. Не генерируются логи, хотя их архивация настроена.

FULL делались еще когда архивация не была настроена, они в режиме STREAM. Потом я настроил архивацию и сделал DELTA, чтобы бэкап сделался уже при ключенном режиме архивации, и уже следом сделал PAGE.. И восстанавливать я пробую на время между валидными PAGE. Насколько я понимаю, даже для PITR не нужны промежуточные WAL между инкрементными бэкапами? Он же накатывает фулл, потом инкремент, потом следующий инкремент (пропуская накатывание WAL между ними) и WAL начинают уже использоваться при накатывании от последнего использованного инкремента до конкретного момента времени.. Или нет? это подтверждает тот факт, что накатываясь просто на последний инкрементный бэкап (по ID, без PITR), вся цепочка инкрементов отработала нормально..

я пробую восстанавливаться на время 2023-02-08 19:50, это время после инкрементного бэкапа RPRFB4, зачем ему WAL от бэкапов RPR8Q4 и ранее?

 hr        14       RPSPCN  2023-02-09 11:19:40+07  PAGE   ARCHIVE   1/1   10m:9s   245kB  16MB    1.00  1/840000D8  1/840001C0  OK
 hr        14       RPRFB4  2023-02-08 18:45:08+07  PAGE   ARCHIVE   1/1   10m:8s    33MB  16MB    1.00  1/83000028  1/83000110  OK
 hr        14       RPR8Q4  2023-02-08 16:22:56+07  PAGE   ARCHIVE   1/1   10m:8s   245kB  16MB    1.00  1/83000028  1/83000110  OK

Если я просто восстановливаю бэкап по ID: -i RPSPCN то все отрабатывает, тоесть, цепочка инкрементов - валидна.. Но проблема в том, что в момент создания бэкапов, не происходит переключений WAL, бэкап не дожидатеся этих переключений, и вот так вот с ворнингом прерывается.. хотя состояние его OK

или я не понял, на что вы хотите указать, или вы не поняли, о чем мой вопрос :)

Уже просматривая все issues подряд, нашел похожий вопрос.. он немного про другое, но в целом, похож на мой.. там тоже отсутствуют необходимые WAL, но у меня они отсутствуют вполне легитимно, так сам postgres работает postgrespro-1c-14

Логика восстановления PITR при отсутствии необходмых wal https://github.com/postgrespro/pg_probackup/issues/404

funny-falcon commented 1 year ago

я пробую восстанавливаться на время 2023-02-08 19:50

В оригинальном сообщении:

При попытке восстановления на заданное время, возникает ошибка ERROR: Not enough WAL records to time 2023-02-08 00:00:00+07

Вы уверены, что пытаетесь восстановиться на 2023-02-08 19:50 ? Вы приводили пример запускаемых команд валидации, но ни разу не привели пример команды восстановления.

Заметьте, что в команде валидации в ошибке было как раз 19:50

ERROR: Not enough WAL records to time 2023-02-08 19:50:08+07

А время вроде бы (как я вижу в коде) парсится одинаково и для валидации, и для восстановления.

Не может быть такого, что в команду восстановления вы собираете скриптом, и забыли время взять в кавычки? Простите за такое наивное предположение.

ktulkhu commented 1 year ago

Не может быть такого, что в команду восстановления вы собираете скриптом, и забыли время взять в кавычки? Простите за такое наивное предположение.

Вы правы. Я восстанавливаю через скрипт. И там использую такую конструкцию: ${PGPB_BIN} restore ${PGPB_INSTANCE} -B ${PGPB_DATA} -D "${PG_DATA}" -j 2 ${PG_RECOVERY_PARAMETERS} --remote-proto=none ${PGPB_LOG_SETTINGS}

где PG_RECOVERY_PARAMETERS="--recovery-target-time=\"2023-02-08 19:50:08\""

когда я выполнил из командной строки целиком команду /usr/bin/pg_probackup-14 restore --instance=hr -B /backup/pg/probackup -D /var/lib/pgpro/1c-14/hr -j 2 --recovery-target-time="2023-02-08 19:50:08" --remote-proto=none --log-level-console=warning --log-level-file=log --log-directory=/var/log/pg_probackup --log-filename=cluster_hr_restore_$(date "+%d-%m-%Y_%H-%M").log

она отработала корректно. Посыпаю голову пеплом.

в свое оправдание, могу сказать лишь, что этот скрипт отрабатывает при этом корректно на другой инсталляции (я его, собственно, и взял уже отлаженный и проверенный с другого сервака). Различия лишь в том, что там, где он работает - Oracle Linux, а вот здесь, где с ним возникли проблемы - Ubuntu..

Более того, когда я смотрел в лог восстановления, которое срубалось с ошибкой, то там первой же записью идет такая строка:

2023-02-09 13:24:21 +07 [2478]: INFO: command: /usr/bin/pg_probackup-14 restore --instance=hr -B /backup/pg/probackup -D /var/lib/pgpro/1c-14/hr -j 2 --recovery-target-time="2023-02-08 19:50:08" --remote-proto
=none --log-level-console=warning --log-level-file=log --log-directory=/var/log/pg_probackup --log-filename=cluster_hr_restore_09-02-2023_13-24.log

обратите внимание, она то как раз корректно "закавычена" :) --recovery-target-time="2023-02-08 19:50:08"

а вот запись из лога, когда восстановление из командной строки прошло успешно:

2023-02-17 09:27:43 +07 [73623]: INFO: command: /usr/bin/pg_probackup-14 restore --instance=hr -B /backup/pg/probackup -D /var/lib/pgpro/1c-14/hr -j 2 --recovery-target-time=2023-02-08 19:50:08 --remote-proto=
none --log-level-console=warning --log-level-file=log --log-directory=/var/log/pg_probackup --log-filename=cluster_hr_restore_17-02-2023_09-27.log

и вот тут то как раз кавычек нет :) --recovery-target-time=2023-02-08 19:50:08

я глядел в лог, у меня были подозрения, но, как раз, увидев кавычки я решил, что все верно.

Более того, когда я изначально отлаживал скрипт, я помню, что на некорректно указанный параметр --recovery-target-time (если ошибся в формате даты, или, как раз, напетлял с кавычками) - шла прям явная ругань.. в процессе отладки, как раз, и родилась вышеуказанная конструкция: PG_RECOVERY_PARAMETERS="--recovery-target-time=\"2023-02-08 19:50:08\""

Так что ваше предположение оказалось полностью верным (включая использование скрипта), видимо, сказался богатый опыт. Так что это я прошу прощения за потраченное время. Благодарю за помощь.