0

We are running Postgres 9.6, with 10+TB size. Backups have been taken using a homegrown tool "pgrsync", which uses S3 as the repository. Both the backup files and WAL archives are stored on S3.

Problem: While trying to restore, the WAL archives restore randomly fails for some backups.

In this case, the backup start location is 00000002000544C60000006B and stop location is 00000002000545210000008D, (based on pg_stop_backup() output) but it stops in between at 005493D and terminates the restore. If I redo the restore again, it stops exactly at the same point. Similar results from couple of more backups, while other backups successfully restores.

It is possibly an indication of some specific WAL files got corrupted during the backup/restore process. Is that the correct interpretation?

Questions:

  1. Are there any ways of identifying if the WAL file is corrupted?
  2. Is there a way to move ahead without losing data? (I am wary of using pg_resetxlog)

First the backup file (from the WAL location 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

Then the log files:

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

It looks like the WAL file is probably corrupted.

Here is the correct WAL file which restored fine:

-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

Here is the WAL file that actually stopped the archive recovery processing:

-bash-4.2$ /usr/pgsql-9.6/bin/pg_xlogdump 000000020005451D0000008B
pg_xlogdump: FATAL:  could not find a valid record after 5451D/8B000000
3
  • pg_stop_backup was definitely run, during the backup. The output of that was stored as backup_label, without which postgres would not start recovery. The recovery went on for 3+ hours, before it stopped here. – rsmoorthy Nov 13 '20 at 5:15
  • 2E is restored, then 2F is restored and then it says redo done at 2E. Probably either 2E or 2F is corrupted? Also pasted at pastebin.com/98J1hS3A – rsmoorthy Nov 13 '20 at 15:16
  • It is vanilla Postgresql, no modifications. That message 'consistent recovery point reached' did not YET happen, before that it aborted. Before it reached 54521, it gave error at 5493D itself. (We have other successful backups which go all the way to the end and gives that 'consistent recovery..' message) – rsmoorthy Nov 13 '20 at 15:21
1

The only explanation for this is that the recovery process never saw a BACKUP_END WAL entry, that is, it never read a WAL segment that contains the effect of a pg_stop_backup call.

Now you argue convincingly that you have run the function, otherwise you wouldn't have the backup_label file that is generated by this function in a non-exclusive backup.

Archive recovery won't allow you to skip over a WAL segment during recovery, so it is impossible that recovery skipped that segment.

That leaves a few explanations:

  1. You used a backup_label file from some other backup because something got mixed up.

  2. You restored a WAL segment with the same name from a different cluster that did not contain the BACKUP_END entry.

  3. You got mixed up with timelines, and there was a timeline switch during the backup, so the BACKUP_END is actually in 00000003000545210000008D or so.

    (I am not sure if that is possible or if a timeline switch will break an online backup; I didn't test.)

If everything is like you expect it to be, then 00000002000545210000008D must contain a BACKUP_END entry. Verify that with

pg_waldump 00000002000545210000008D | grep BACKUP_END

As soon as this entry is processed, PostgreSQL will emit the log line

consistent recovery state reached
2
  • You are right, I made a horrible mistake of sharing a different set of logs. I mixed up two different sequences in my discussion. Thanks! And sorry for taking you the wrong path. FTR: 00000002000545210000008D indeed contains BACKUP_END, but it did not reach there and aborted before at 000000020005451D0000008B – rsmoorthy Nov 13 '20 at 18:46
  • My summary question was to find out if the WAL archives is corrupted or not. You had given pointers to it, to use pg_xlogdump (for 9.6). That turned out to be helpful and I am able to scan all the WAL archives (during a period) to determine if they are corrupted. Happy to accept your answer! I am trying to figure out why this caused corruption and suspecting due to this -- dba.stackexchange.com/q/279683/85814 – rsmoorthy Nov 14 '20 at 9:05

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.