curious postgres (crash) recovery behavior

From: "Zwettler Markus (OIZ)" <Markus(dot)Zwettler(at)zuerich(dot)ch>
To: "pgsql-general(at)lists(dot)postgresql(dot)org" <pgsql-general(at)lists(dot)postgresql(dot)org>
Subject: curious postgres (crash) recovery behavior
Date: 2023-01-04 16:54:26
Message-ID: 3bf6e04d6433401e9249517419f76ff6@zuerich.ch
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

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?

Responses

Browse pgsql-general by date

  From Date Subject
Next Message Rébeli-Szabó Tamás 2023-01-04 21:00:12 Re: REINDEX vs VACUUM
Previous Message Ron 2023-01-04 15:34:42 Re: REINDEX vs VACUUM