Thread: curious postgres (crash) recovery behavior
We are using Crunchy PGO which uses "pgbackrest".
Over Christmas we had a disk full error on the "pgbackrest" repo followed by a disk full error on the PostgreSQL instance pod.
Unfortunately, a colleague then deleted the current "pg_wal" directory on the instance pod.
So we had to do a point-in-time recovery to overcome this situation.
we started a PITR to 2022-12-23 01:34 based on the following "pgbackrest" backup:
sh-4.4$ pgbackrest info
stanza: db
status: ok
cipher: none
db (current)
wal archive min/max (13): 0000000B0000010B000000C1/0000000C000001110000000A
full backup: 20221222-230004F
timestamp start/stop: 2022-12-22 23:00:04 / 2022-12-23 01:32:17
wal start/stop: 0000000B0000010B000000C1 / 0000000B0000010C0000005C
database size: 46.3GB, database backup size: 46.3GB
repo1: backup set size: 17.6GB, backup size: 17.6GB
During the point-in-time recovery, the "pgbackrest" pod terminated incorrectly with an error "pg_ctl: server did not start in time".
There is a known PGO bug on this (pg_ctl default timeout of 60 secs cannot be changed).
PGO started the instance pod anyway in following, which leads to a regular PostgreSQL crash recovery ending with "last completed transaction was at log time 2022-12-23 20:52:29.584555+01":
...
2023-01-04 15:26:35 CET : =>@ : 94-4=>63b58c9b.5e : 00000 LOG: starting PostgreSQL 13.7 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-10), 64-bit
2023-01-04 15:26:35 CET : =>@ : 94-5=>63b58c9b.5e : 00000 LOG: listening on IPv4 address "0.0.0.0", port 5432
2023-01-04 15:26:35 CET : =>@ : 94-6=>63b58c9b.5e : 00000 LOG: listening on IPv6 address "::", port 5432
2023-01-04 15:26:35 CET : =>@ : 94-7=>63b58c9b.5e : 00000 LOG: listening on Unix socket "/tmp/postgres/.s.PGSQL.5432"
2023-01-04 15:26:35 CET : =>@ : 108-1=>63b58c9b.6c : 00000 LOG: database system was interrupted while in recovery at log time 2022-12-23 01:06:58 CET
2023-01-04 15:26:35 CET : =>@ : 108-2=>63b58c9b.6c : 00000 HINT: If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
2023-01-04 15:26:35 CET : =>@ : 108-3=>63b58c9b.6c : 00000 LOG: entering standby mode
2023-01-04 15:26:35 CET : =>@ : 108-4=>63b58c9b.6c : 00000 LOG: restored log file "0000000B.history" from archive
2023-01-04 15:26:35 CET : =>@ : 108-5=>63b58c9b.6c : 00000 LOG: restored log file "0000000B0000010C0000000C" from archive
...
2023-01-04 15:30:06 CET : =>@ : 108-1198=>63b58c9b.6c : 00000 LOG: restored log file "0000000B00000110000000AD" from archive
2023-01-04 15:30:06 CET : =>@ : 108-1199=>63b58c9b.6c : 00000 LOG: received promote request
2023-01-04 15:30:06 CET : =>@ : 108-1200=>63b58c9b.6c : 00000 LOG: redo done at 110/AD0005B8
2023-01-04 15:30:06 CET : =>@ : 108-1201=>63b58c9b.6c : 00000 LOG: last completed transaction was at log time 2022-12-23 20:52:29.584555+01
2023-01-04 15:30:07 CET : =>@ : 108-1202=>63b58c9b.6c : 00000 LOG: restored log file "0000000B00000110000000AD" from archive
2023-01-04 15:30:07 CET : =>@ : 108-1203=>63b58c9b.6c : 00000 LOG: selected new timeline ID: 12
2023-01-04 15:30:07 CET : =>@ : 108-1204=>63b58c9b.6c : 00000 LOG: archive recovery complete
2023-01-04 15:30:07 CET : =>@ : 108-1205=>63b58c9b.6c : 00000 LOG: restored log file "0000000B.history" from archive
2023-01-04 15:30:07 CET : =>@ : 94-9=>63b58c9b.5e : 00000 LOG: database system is ready to accept connections
...
QUESTION:
=========
I wondered how the crash recovery can run to 2022-12-23 20:52:29.584555 and simply open the database?
When I got it right the full backup itself would be consistent with "wal stop 0000000B0000010C0000005C".
PostgreSQL additionally added some wal files until 0000000B00000110000000AD (2022-12-23 20:52:29.584555) because it didn't find any more before the recovery target of 2022-12-23 01:34.
Am I right or did I miss something?
I think your log shows a continued archive recovery (PITR), not a crash
recovery.
For a crash recovery (automatic recovery), you would see something like
this in the server log:
LOG: database system was interrupted; last known up at 2022-12-23
20:50:13 CET
LOG: database system was not properly shut down; automatic recovery in
progress
In your case, the server started in archive recovery mode (standby mode)
again, restored archived WAL, and recovered the cluster from it.
You must have set the recovery_target_action parameter to 'promote'
(probably via pgbackrest's --target-action parameter), because the
server started in production mode (read-write mode) after a successful
archive recovery.
The server started in standby mode again because the recovery had not
completed, so the standby.signal file had not been deleted from the data
directory.
The server knew that it was an interrupted recovery by looking at the
database cluster state in the control file ("in archive recovery"
instead of "shutdown in recovery").