postgres: WAL termina prima della fine del backup online

Question

Stiamo eseguendo Postgres 9.6, con una dimensione di 10+ TB. I backup sono stati eseguiti utilizzando uno strumento creato internamente "pgrsync", che utilizza S3 come repository. Sia i file di backup che gli archivi WAL sono archiviati su S3.

Problema: durante il tentativo di ripristino, il ripristino casuale degli archivi WAL non riesce per alcuni backup.

In questo caso, la posizione di inizio del backup è 00000002000544C60000006Be la posizione di arresto è 00000002000545210000008D, (in base all'output di pg_stop_backup ()) ma si ferma tra 005493D e termina il ripristino. Se rifaccio di nuovo il ripristino, si ferma esattamente nello stesso punto. Risultati simili da un paio di più backup, mentre altri backup vengono ripristinati correttamente.

È possibile che sia un'indicazione di alcuni file WAL specifici che sono stati danneggiati durante il processo di backup / ripristino. È questa l'interpretazione corretta?

Domande:

1. Esistono modi per identificare se il file WAL è danneggiato?
2. C'è un modo per andare avanti senza perdere dati? (Sono diffidente nell'usare pg_resetxlog)

---

Prima il file di backup (dalla posizione WAL 00000002000544C60000006B.0001E9A0.backup)

START WAL LOCATION: 544C6/6B01E9A0 (file 00000002000544C60000006B)
STOP WAL LOCATION: 54521/8D235490 (file 00000002000545210000008D)
CHECKPOINT LOCATION: 544C6/BA84E0A8
BACKUP METHOD: streamed
BACKUP FROM: master
START TIME: 2020-11-04 03:24:14 UTC
LABEL: inc04nov
STOP TIME: 2020-11-04 09:21:38 UTC

Quindi i file di registro:

2020-11-11 06:38:08 UTC [21731]: [22299-1] user=,db=LOG:  restored log file "000000020005451D00000080" from archive
2020-11-11 06:38:08 UTC [21731]: [22300-1] user=,db=LOG:  restored log file "000000020005451D00000081" from archive
2020-11-11 06:38:08 UTC [21731]: [22301-1] user=,db=LOG:  restored log file "000000020005451D00000082" from archive
2020-11-11 06:38:08 UTC [21731]: [22302-1] user=,db=LOG:  restored log file "000000020005451D00000083" from archive
2020-11-11 06:38:08 UTC [21731]: [22303-1] user=,db=LOG:  restored log file "000000020005451D00000084" from archive
2020-11-11 06:38:08 UTC [21731]: [22304-1] user=,db=LOG:  restored log file "000000020005451D00000085" from archive
2020-11-11 06:38:08 UTC [21731]: [22305-1] user=,db=LOG:  restored log file "000000020005451D00000086" from archive
2020-11-11 06:38:08 UTC [21731]: [22306-1] user=,db=LOG:  restored log file "000000020005451D00000087" from archive
2020-11-11 06:38:08 UTC [21731]: [22307-1] user=,db=LOG:  restored log file "000000020005451D00000088" from archive
2020-11-11 06:38:08 UTC [21731]: [22308-1] user=,db=LOG:  restored log file "000000020005451D00000089" from archive
2020-11-11 06:38:08 UTC [21731]: [22309-1] user=,db=LOG:  restored log file "000000020005451D0000008A" from archive
2020-11-11 06:38:08 UTC [21731]: [22310-1] user=,db=LOG:  restored log file "000000020005451D0000008B" from archive
2020-11-11 06:38:08 UTC [21731]: [22311-1] user=,db=LOG:  redo done at 5451D/8AFFE500
2020-11-11 06:38:08 UTC [21731]: [22312-1] user=,db=LOG:  last completed transaction was at log time 2020-11-04 09:10:42.219935+00
2020-11-11 06:38:11 UTC [21731]: [22314-1] user=,db=FATAL:  WAL ends before end of online backup
2020-11-11 06:38:11 UTC [21731]: [22315-1] user=,db=HINT:  All WAL generated while online backup was taken must be available at recovery.
2020-11-11 06:38:13 UTC [21728]: [3-1] user=,db=LOG:  startup process (PID 21731) exited with exit code 1
2020-11-11 06:38:13 UTC [21728]: [4-1] user=,db=LOG:  terminating any other active server processes
2020-11-11 06:38:16 UTC [4559]: [1-1] user=postgres,db=postgresFATAL:  the database system is in recovery mode
2020-11-11 06:38:16 UTC [4561]: [1-1] user=postgres,db=postgresFATAL:  the database system is in recovery mode
2020-11-11 06:38:16 UTC [4576]: [1-1] user=postgres,db=postgresFATAL:  the database system is in recovery mode
2020-11-11 06:38:25 UTC [21728]: [5-1] user=,db=LOG:  database system is shut down

---

Sembra che il file WAL sia probabilmente danneggiato.

Ecco il file WAL corretto che è stato ripristinato correttamente:

-bash-4.2$ /usr/pgsql-9.6/bin/pg_xlogdump 000000020005451D0000008A | head -2
rmgr: Heap        len (rec/tot):    151/   151, tx: 3501354263, lsn: 5451D/8A0001D8, prev 5451D/89FFE1E8, desc: INSERT off 15, blkref #0: rel 3435996123/765803221/4171942326 blk 15806513
rmgr: Btree       len (rec/tot):     72/    72, tx: 3501354263, lsn: 5451D/8A000270, prev 5451D/8A0001D8, desc: INSERT_LEAF off 2, blkref #0: rel 3435996123/765803221/4171944289 blk 3881149

Ecco il file WAL che ha effettivamente interrotto l'elaborazione del ripristino dell'archivio:

-bash-4.2$ /usr/pgsql-9.6/bin/pg_xlogdump 000000020005451D0000008B
pg_xlogdump: FATAL:  could not find a valid record after 5451D/8B000000

Answer 1

L'unica spiegazione di ciò è che il processo di ripristino non ha mai visto una BACKUP_ENDvoce WAL, ovvero non ha mai letto un segmento WAL che contiene l'effetto di una pg_stop_backupchiamata.

Ora sostieni in modo convincente di aver eseguito la funzione, altrimenti non avresti il backup_labelfile generato da questa funzione in un backup non esclusivo.

Il ripristino dell'archivio non ti consentirà di saltare un segmento WAL durante il ripristino, quindi è impossibile che il ripristino abbia saltato quel segmento.

Ciò lascia alcune spiegazioni:

1. Hai usato un backup_labelfile da qualche altro backup perché qualcosa si è confuso.

2. Hai ripristinato un segmento WAL con lo stesso nome da un cluster diverso che non conteneva la BACKUP_ENDvoce.

3. Ti sei confuso con le sequenze temporali e durante il backup si è verificato un cambio di sequenza temporale, quindi BACKUP_ENDin realtà è 00000003000545210000008Do giù di lì.

   (Non sono sicuro se ciò sia possibile o se un cambio di sequenza temporale interromperà un backup online; non ho provato.)

Se tutto è come ti aspetti, 00000002000545210000008Ddeve contenere una BACKUP_ENDvoce. Verificalo con

pg_waldump 00000002000545210000008D | grep BACKUP_END

Non appena questa voce viene elaborata, PostgreSQL emetterà la riga di registro

consistent recovery state reached