postgres: WAL termina antes do fim do backup online

Question

Estamos executando o Postgres 9.6, com tamanho de 10 + TB. Os backups foram feitos usando uma ferramenta própria "pgrsync", que usa S3 como repositório. Os arquivos de backup e os arquivos WAL são armazenados no S3.

Problema: ao tentar restaurar, a restauração dos arquivos WAL falha aleatoriamente para alguns backups.

Neste caso, o local de início do backup é 00000002000544C60000006Be o local de parada é 00000002000545210000008D, (com base na saída pg_stop_backup ()), mas ele para no meio em 005493D e termina a restauração. Se eu refazer a restauração novamente, ela para exatamente no mesmo ponto. Resultados semelhantes de mais alguns backups, enquanto outros backups são restaurados com sucesso.

É possivelmente uma indicação de que alguns arquivos WAL específicos foram corrompidos durante o processo de backup / restauração. Essa é a interpretação correta?

Questões:

1. Existe alguma maneira de identificar se o arquivo WAL está corrompido?
2. Existe uma maneira de seguir em frente sem perder dados? (Estou desconfiado de usar pg_resetxlog)

---

Primeiro, o arquivo de backup (do local 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

Em seguida, os arquivos de log:

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

---

Parece que o arquivo WAL provavelmente está corrompido.

Aqui está o arquivo WAL correto que foi restaurado corretamente:

-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

Aqui está o arquivo WAL que realmente interrompeu o processamento de recuperação do arquivo:

-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

A única explicação para isso é que o processo de recuperação nunca viu uma BACKUP_ENDentrada do WAL, ou seja, nunca leu um segmento do WAL que contenha o efeito de uma pg_stop_backupchamada.

Agora você argumenta de forma convincente que executou a função, caso contrário, não teria o backup_labelarquivo gerado por essa função em um backup não exclusivo.

A recuperação do arquivo não permite que você pule um segmento do WAL durante a recuperação, portanto, é impossível que a recuperação pule esse segmento.

Isso deixa algumas explicações:

1. Você usou um backup_labelarquivo de outro backup porque algo se confundiu.

2. Você restaurou um segmento WAL com o mesmo nome de um cluster diferente que não continha a BACKUP_ENDentrada.

3. Você se confundiu com as linhas do tempo e houve uma mudança na linha do tempo durante o backup, então o BACKUP_ENDestá na verdade 00000003000545210000008Dou algo assim.

   (Não tenho certeza se isso é possível ou se uma mudança de linha do tempo interromperá um backup online; eu não testei.)

Se tudo estiver como você espera, 00000002000545210000008Ddeve conter uma BACKUP_ENDentrada. Verifique isso com

pg_waldump 00000002000545210000008D | grep BACKUP_END

Assim que esta entrada for processada, o PostgreSQL irá emitir a linha de log

consistent recovery state reached