Почему возникает ошибка при восстановлении PiTR Postgres WAL-G?

Question

[igortru]

Привет.

Пытаюсь смоделировать ситуацию восстановления БД на определенный момент времени.

[root@test-db log]# /usr/local/bin/wal-g --config=/mnt/pg-data/.walg.json backup-list
name                          last_modified        wal_segment_backup_start
base_000000180000000000000057 2023-06-13T17:00:05Z 000000180000000000000057
base_000000180000000000000059 2023-06-14T17:00:04Z 000000180000000000000059
base_00000018000000000000005B 2023-06-15T17:00:05Z 00000018000000000000005B

Делаю восстановление из бекапа base_000000180000000000000057

/usr/local/bin/wal-g --config=/mnt/pg-data/.walg.json backup-fetch /mnt/pg-data/14 base_000000180000000000000057

postgresql.conf указываю следующее

recovery_target = ''
recovery_target_lsn = ''
recovery_target_name = ''
recovery_target_time = ''
#recovery_target_timeline = ''
recovery_target_xid = ''
restore_command = 'wal-g --config=/mnt/pg-data/.walg.json wal-fetch \"%f\" \"%p\" >> /var/log/wal-g/wal_g_restore_command.log 2>&1'
recovery_target_time = '2023-06-13 17:30:00'

При запуске Postgres получаю ошибку:

2023-06-16 13:31:03.820 GMT [14644] LOG:  starting PostgreSQL 14.8 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit
2023-06-16 13:31:03.820 GMT [14644] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-06-16 13:31:03.820 GMT [14644] LOG:  listening on IPv6 address "::", port 5432
2023-06-16 13:31:03.822 GMT [14644] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-06-16 13:31:03.823 GMT [14644] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-06-16 13:31:03.826 GMT [14647] LOG:  database system was interrupted; last known up at 2023-06-13 17:00:03 GMT
2023-06-16 13:31:03.984 GMT [14647] LOG:  restored log file "00000019.history" from archive
2023-06-16 13:31:04.183 GMT [14647] LOG:  starting point-in-time recovery to 2023-06-13 17:30:00+00
2023-06-16 13:31:04.301 GMT [14647] LOG:  restored log file "00000019.history" from archive
2023-06-16 13:31:04.433 GMT [14647] LOG:  restored log file "000000180000000000000057" from archive
2023-06-16 13:31:04.576 GMT [14647] LOG:  restored log file "00000018.history" from archive
2023-06-16 13:31:04.614 GMT [14647] LOG:  redo starts at 0/57000028
2023-06-16 13:31:04.615 GMT [14647] LOG:  consistent recovery state reached at 0/57000100
2023-06-16 13:31:04.616 GMT [14644] LOG:  database system is ready to accept read-only connections
2023-06-16 13:31:04.638 GMT [14647] LOG:  restored log file "000000180000000000000058" from archive
2023-06-16 13:31:04.661 GMT [14647] LOG:  restored log file "000000180000000000000059" from archive
2023-06-16 13:31:04.686 GMT [14647] LOG:  restored log file "00000018000000000000005A" from archive
2023-06-16 13:31:04.732 GMT [14647] LOG:  restored log file "00000018000000000000005B" from archive
2023-06-16 13:31:04.931 GMT [14647] LOG:  restored log file "00000019000000000000005C" from archive
2023-06-16 13:31:05.106 GMT [14647] LOG:  redo done at 0/5C0000D8 system usage: CPU: user: 0.00 s, system: 0.01 s, elapsed: 0.49 s
2023-06-16 13:31:05.106 GMT [14647] FATAL:  recovery ended before configured recovery target was reached
2023-06-16 13:31:05.107 GMT [14644] LOG:  startup process (PID 14647) exited with exit code 1
2023-06-16 13:31:05.107 GMT [14644] LOG:  terminating any other active server processes
2023-06-16 13:31:05.108 GMT [14644] LOG:  shutting down due to startup process failure
2023-06-16 13:31:05.112 GMT [14644] LOG:  database system is shut down

Пробовал в различных вариациях - другой бекап, другое время. Ошибка.

Что не так?

Comments

[Melkij]

когда снятие этого бекапа base_000000180000000000000057 было завершено?
00000019000000000000005D есть в архиве?
что в wal_g_restore_command.log?

[igortru]

Melkij, БД маленькая, задание выполняется несколько секунд. Журнал выполнения ниже. Задание запускаеися с такими параметрами:

su postgres -c 'wal-g --config=/mnt/pg-data/.walg.json delete retain FULL 2 --confirm >> /var/log/wal-g/wal_g_backup.log 2>&1'
su postgres -c 'wal-g --config=/mnt/pg-data/.walg.json backup-push /mnt/pg-data/14 >> /var/log/wal-g/wal_g_backup.log 2>&1'

Журнал выполнения за 14-е число.

INFO: 2023/06/14 17:00:01.158815 retrieving permanent objects
INFO: 2023/06/14 17:00:01.574465 Start delete
INFO: 2023/06/14 17:00:01.692653 Objects in folder:
INFO: 2023/06/14 17:00:01.692701        will be deleted: basebackups_005/base_000000180000000000000053_backup_stop_sentinel.json
INFO: 2023/06/14 17:00:01.692789        will be deleted: wal_005/000000180000000000000053.00000028.backup.br
INFO: 2023/06/14 17:00:01.692810        will be deleted: wal_005/000000180000000000000053.br
INFO: 2023/06/14 17:00:01.692818        will be deleted: wal_005/000000180000000000000054.br
INFO: 2023/06/14 17:00:01.692860        will be deleted: basebackups_005/base_000000180000000000000053/metadata.json
INFO: 2023/06/14 17:00:01.692885        will be deleted: basebackups_005/base_000000180000000000000053/tar_partitions/part_001.tar.br
INFO: 2023/06/14 17:00:01.692894        will be deleted: basebackups_005/base_000000180000000000000053/tar_partitions/part_003.tar.br
INFO: 2023/06/14 17:00:01.692905        will be deleted: basebackups_005/base_000000180000000000000053/tar_partitions/pg_control.tar.br
INFO: 2023/06/14 17:00:01.761965 Selecting the latest backup as the base for the current delta backup...
INFO: 2023/06/14 17:00:01.792326 Calling pg_start_backup()
INFO: 2023/06/14 17:00:01.956149 Starting a new tar bundle
INFO: 2023/06/14 17:00:01.956204 Walking ...
INFO: 2023/06/14 17:00:01.956486 Starting part 1 ...
INFO: 2023/06/14 17:00:02.370733 Packing ...
INFO: 2023/06/14 17:00:02.371676 Finished writing part 1.
INFO: 2023/06/14 17:00:03.540698 Starting part 2 ...
INFO: 2023/06/14 17:00:03.540770 /global/pg_control
INFO: 2023/06/14 17:00:03.541743 Finished writing part 2.
INFO: 2023/06/14 17:00:03.542964 Calling pg_stop_backup()
INFO: 2023/06/14 17:00:04.861308 Starting part 3 ...
INFO: 2023/06/14 17:00:04.861406 backup_label
INFO: 2023/06/14 17:00:04.861419 tablespace_map
INFO: 2023/06/14 17:00:04.863097 Finished writing part 3.
INFO: 2023/06/14 17:00:04.954148 Wrote backup with name base_000000180000000000000059

Возможно ли поведение WAL-G когда он удаляет все предыдущие WAL при создании нового полного бекапа? т.е. восстановить предыдущее 2 полных возможно но без привязки по времени?

Попробовал восстановить из вчерашнего бекапа, получил другую ошибку :

Новых данных в БД не заносится, размен как ранее писал очень мал - 11МБ.

2023-06-17 02:01:45.454 GMT [19421] LOG:  starting PostgreSQL 14.8 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit
2023-06-17 02:01:45.456 GMT [19421] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-06-17 02:01:45.456 GMT [19421] LOG:  listening on IPv6 address "::", port 5432
2023-06-17 02:01:45.458 GMT [19421] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-06-17 02:01:45.461 GMT [19421] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-06-17 02:01:45.464 GMT [19424] LOG:  database system was interrupted; last known up at 2023-06-16 17:00:02 GMT
2023-06-17 02:01:45.648 GMT [19424] LOG:  restored log file "00000019.history" from archive
2023-06-17 02:01:45.895 GMT [19424] LOG:  starting point-in-time recovery to 2023-06-17 00:00:00+00
2023-06-17 02:01:45.996 GMT [19424] LOG:  restored log file "00000019.history" from archive
2023-06-17 02:01:46.363 GMT [19424] LOG:  restored log file "00000018000000000000005D" from archive
<b>2023-06-17 02:01:46.369 GMT [19424] FATAL:  requested timeline 25 is not a child of this server's history
2023-06-17 02:01:46.369 GMT [19424] DETAIL:  Latest checkpoint is at 0/5D000060 on timeline 24, but in the history of the requested timeline, the server forked off from that timeline at 0/5C00000
</b>2023-06-17 02:01:46.370 GMT [19421] LOG:  startup process (PID 19424) exited with exit code 1
2023-06-17 02:01:46.370 GMT [19421] LOG:  aborting startup due to startup process failure
2023-06-17 02:01:46.373 GMT [19421] LOG:  database system is shut down

restore_command = 'wal-g --config=/mnt/pg-data/.walg.json wal-fetch \"%f\" \"%p\" >> /var/log/wal-g/wal_g_restore_command.log 2>&1'
recovery_target_time = '2023-06-17 00:00:00'

/var/log/wal-g/wal_g_restore_command.log

ERROR: 2023/06/17 02:00:32.899667 Archive '0000001A.history' does not exist.
ERROR: 2023/06/17 02:00:33.195372 Archive '00000019000000000000005D' does not exist.
ERROR: 2023/06/17 02:01:45.894435 Archive '0000001A.history' does not exist.
ERROR: 2023/06/17 02:01:46.197105 Archive '00000019000000000000005D' does not exist.

Журнал выполнения бекапа с сервера за 16-е число.

INFO: 2023/06/16 17:00:01.582475 retrieving permanent objects
INFO: 2023/06/16 17:00:02.072793 Start delete
INFO: 2023/06/16 17:00:02.222819 Objects in folder:
INFO: 2023/06/16 17:00:02.222870        will be deleted: basebackups_005/base_000000180000000000000057_backup_stop_sentinel.json
INFO: 2023/06/16 17:00:02.222954        will be deleted: wal_005/000000180000000000000057.00000028.backup.br
INFO: 2023/06/16 17:00:02.222963        will be deleted: wal_005/000000180000000000000057.br
INFO: 2023/06/16 17:00:02.222972        will be deleted: wal_005/000000180000000000000058.br
INFO: 2023/06/16 17:00:02.223025        will be deleted: basebackups_005/base_000000180000000000000057/metadata.json
INFO: 2023/06/16 17:00:02.223052        will be deleted: basebackups_005/base_000000180000000000000057/tar_partitions/part_001.tar.br
INFO: 2023/06/16 17:00:02.223066        will be deleted: basebackups_005/base_000000180000000000000057/tar_partitions/part_003.tar.br
INFO: 2023/06/16 17:00:02.223077        will be deleted: basebackups_005/base_000000180000000000000057/tar_partitions/pg_control.tar.br
INFO: 2023/06/16 17:00:02.292458 Selecting the latest backup as the base for the current delta backup...
INFO: 2023/06/16 17:00:02.320451 Calling pg_start_backup()
INFO: 2023/06/16 17:00:02.473048 Starting a new tar bundle
INFO: 2023/06/16 17:00:02.473108 Walking ...
INFO: 2023/06/16 17:00:02.473456 Starting part 1 ...
INFO: 2023/06/16 17:00:02.905460 Packing ...
INFO: 2023/06/16 17:00:02.906443 Finished writing part 1.
INFO: 2023/06/16 17:00:04.052359 Starting part 2 ...
INFO: 2023/06/16 17:00:04.052436 /global/pg_control
INFO: 2023/06/16 17:00:04.053475 Finished writing part 2.
INFO: 2023/06/16 17:00:04.054552 Calling pg_stop_backup()
INFO: 2023/06/16 17:00:05.096904 Starting part 3 ...
INFO: 2023/06/16 17:00:05.097015 backup_label
INFO: 2023/06/16 17:00:05.097027 tablespace_map
INFO: 2023/06/16 17:00:05.098561 Finished writing part 3.
INFO: 2023/06/16 17:00:05.203537 Wrote backup with name base_00000018000000000000005D

С рабочего сервера, больше записей нет - /var/log/wal-g/wal_g_archive_command.log

INFO: 2023/06/12 17:00:04.588456 FILE PATH: 000000180000000000000055.br
INFO: 2023/06/13 17:00:03.180230 FILE PATH: 000000180000000000000056.br
INFO: 2023/06/13 17:00:04.911261 FILE PATH: 000000180000000000000057.00000028.backup.br
INFO: 2023/06/13 17:00:04.917427 FILE PATH: 000000180000000000000057.br
INFO: 2023/06/14 17:00:01.995453 FILE PATH: 000000180000000000000058.br
INFO: 2023/06/14 17:00:03.984552 FILE PATH: 000000180000000000000059.00000028.backup.br
INFO: 2023/06/14 17:00:03.986231 FILE PATH: 000000180000000000000059.br
INFO: 2023/06/15 17:00:02.916916 FILE PATH: 00000018000000000000005A.br
INFO: 2023/06/15 17:00:04.716082 FILE PATH: 00000018000000000000005B.br
INFO: 2023/06/15 17:00:04.716215 FILE PATH: 00000018000000000000005B.00000028.backup.br
INFO: 2023/06/16 17:00:02.556806 FILE PATH: 00000018000000000000005C.br
INFO: 2023/06/16 17:00:04.229296 FILE PATH: 00000018000000000000005D.00000028.backup.br
INFO: 2023/06/16 17:00:04.230712 FILE PATH: 00000018000000000000005D.br

[igortru]

wal-g --config=/mnt/pg-data/.walg.json wal-show

[igortru]

Попробовал восстановить БД побольше 4Гб, судя по журналам WAL пишутся в S3 каждые пол часа.

restore_command = 'wal-g --config=/mnt/pg-data/.walg.json wal-fetch \"%f\" \"%p\" >> /var/log/wal-g/wal_g_restore_command.log 2>&1'
recovery_target_time = '2023-06-16 23:00:00 '

wal_g_restore_command.log

ERROR: 2023/06/17 02:55:40.458071 Archive '0000000D.history' does not exist.
ERROR: 2023/06/17 02:55:40.971844 Archive '0000000C0000003100000095' does not exist.
ERROR: 2023/06/17 02:55:41.148688 Archive '0000000B0000003100000095' does not exist.
ERROR: 2023/06/17 02:55:41.277587 Archive '0000000A0000003100000095' does not exist.

postgresql-Sat.log

2023-06-17 02:55:39.463 GMT [22637] LOG:  starting PostgreSQL 14.8 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit
2023-06-17 02:55:39.463 GMT [22637] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-06-17 02:55:39.463 GMT [22637] LOG:  listening on IPv6 address "::", port 5432
2023-06-17 02:55:39.464 GMT [22637] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-06-17 02:55:39.466 GMT [22637] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2023-06-17 02:55:39.470 GMT [22641] LOG:  database system was interrupted; last known up at 2023-06-16 17:00:03 GMT
2023-06-17 02:55:40.039 GMT [22641] LOG:  restored log file "0000000A.history" from archive
2023-06-17 02:55:40.135 GMT [22641] LOG:  restored log file "0000000B.history" from archive
2023-06-17 02:55:40.237 GMT [22641] LOG:  restored log file "0000000C.history" from archive
2023-06-17 02:55:40.459 GMT [22641] LOG:  starting point-in-time recovery to 2023-06-16 23:00:00+00
2023-06-17 02:55:40.773 GMT [22641] LOG:  restored log file "0000000C.history" from archive
2023-06-17 02:55:41.573 GMT [22641] LOG:  restored log file "000000090000003100000095" from archive
2023-06-17 02:55:41.611 GMT [22641] FATAL:  requested timeline 12 is not a child of this server's history
2023-06-17 02:55:41.611 GMT [22641] DETAIL:  Latest checkpoint is at 31/95000060 on timeline 9, but in the history of the requested timeline, the server forked off from that timeline at 2A/6C0000
A0.
2023-06-17 02:55:41.612 GMT [22637] LOG:  startup process (PID 22641) exited with exit code 1
2023-06-17 02:55:41.612 GMT [22637] LOG:  aborting startup due to startup process failure
2023-06-17 02:55:41.616 GMT [22637] LOG:  database system is shut down

[Melkij]

собственно по первой маленькой базе выглядит так, что причина проблемы именно в малой активности и объёме. Нет WAL в архиве, перед которым нужно остановиться для достижения заданного recovery_target_time. А пока нет wal - recovery не может понять, то ли можно завершать работу уже т..к. изменений и не будет или это проблема и невозможно достичь заданного pitr т.к. отсутствуют требуемые wal.
Для продакшена это можно решить используя archive_timeout - база будет по меньшей мере раз в этот интервал переключать сегмент wal и архивировать. Но на неактивной базе это соответственно даст много пустых WAL по объёму.

по requested timeline 12 is not a child of this server's history - соответственно разбираться с таймлайнами. Каждый таймлайн - это promote (а так же успешный выход из point in time recovery при recovery_target_action = promote), то есть разветвление истории изменений. recovery_target_timeline можно использовать для восстановления на нужный timeline, но для этого, конечно, надо понимать, где какой таймлайн.