BUG #16894: PANIC: WAL contains references to invalid pages

From: PG Bug reporting form <noreply(at)postgresql(dot)org>
To: pgsql-bugs(at)lists(dot)postgresql(dot)org
Cc: antkurochkin(at)gmail(dot)com
Subject: BUG #16894: PANIC: WAL contains references to invalid pages
Date: 2021-02-24 09:42:45
Message-ID: 16894-c29735df12727642@postgresql.org
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

The following bug has been logged on the website:

Bug reference: 16894
Logged by: Anton
Email address: antkurochkin(at)gmail(dot)com
PostgreSQL version: 9.6.20
Operating system: Oracle Linux Server 7.6
Description:

Good day,

We got error when PITR restoring individual databases from a backup using
pgbackrest.

Opened issue in pgbackrest repository:
https://github.com/pgbackrest/pgbackrest/issues/796
It would be great if you would look at this problem. All the information is
in the issue.

Pgbackrest developers offered to provide this information to the postgres
folks.

Turned out that the problem is playing WAL files on databases that are
restored with zero files.
The database files from the backup are restored successfully, but an error
occurs when starting PG and playing WAL:

```
< 2021-02-21 10:34:57.950 UTC > LOG: starting archive recovery
< 2021-02-21 10:34:58.137 UTC > LOG: restored log file
"000000010000007E0000007D" from archive
< 2021-02-21 10:34:58.151 UTC > LOG: redo starts at 7E/7D0090A8
< 2021-02-21 10:34:58.521 UTC > LOG: restored log file
"000000010000007E0000007E" from archive
< 2021-02-21 10:34:58.711 UTC > LOG: consistent recovery state reached at
7E/7EF5E478
< 2021-02-21 10:34:58.915 UTC > LOG: restored log file
"000000010000007E0000007F" from archive
< 2021-02-21 10:34:59.415 UTC > LOG: restored log file
"000000010000007E00000080" from archive
< 2021-02-21 10:35:01.521 UTC > LOG: restored log file
"000000010000007E00000081" from archive
< 2021-02-21 10:35:02.110 UTC > LOG: restored log file
"000000010000007E00000082" from archive
< 2021-02-21 10:35:02.577 UTC > LOG: restored log file
"000000010000007E00000083" from archive
< 2021-02-21 10:35:03.045 UTC > LOG: restored log file
"000000010000007E00000084" from archive
< 2021-02-21 10:35:03.544 UTC > LOG: restored log file
"000000010000007E00000085" from archive
< 2021-02-21 10:35:03.985 UTC > LOG: restored log file
"000000010000007E00000086" from archive
< 2021-02-21 10:35:05.394 UTC > LOG: restored log file
"000000010000007E00000087" from archive
< 2021-02-21 10:35:05.945 UTC > LOG: restored log file
"000000010000007E00000088" from archive
< 2021-02-21 10:35:06.623 UTC > LOG: restored log file
"000000010000007E00000089" from archive
< 2021-02-21 10:35:07.264 UTC > LOG: restored log file
"000000010000007E0000008A" from archive
< 2021-02-21 10:35:07.831 UTC > LOG: restored log file
"000000010000007E0000008B" from archive
< 2021-02-21 10:35:08.318 UTC > LOG: restored log file
"000000010000007E0000008C" from archive
< 2021-02-21 10:35:08.892 UTC > LOG: restored log file
"000000010000007E0000008D" from archive
< 2021-02-21 10:35:09.050 UTC > WARNING: page 22659 of relation
base/17221/17557 is uninitialized
< 2021-02-21 10:35:09.050 UTC > CONTEXT: xlog redo at 7E/8D9C04C0 for
Heap2/VISIBLE: cutoff xid 810424291 flags 1
< 2021-02-21 10:35:09.050 UTC > PANIC: WAL contains references to invalid
pages
< 2021-02-21 10:35:09.050 UTC > CONTEXT: xlog redo at 7E/8D9C04C0 for
Heap2/VISIBLE: cutoff xid 810424291 flags 1
< 2021-02-21 10:35:09.675 UTC > LOG: startup process (PID 9) was terminated
by signal 6: Aborted
```

In WAL there is only one line for `page 27536`:

```
rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn:
7E/8D9C04C0, prev 7E/8D9BE508, desc: VISIBLE cutoff xid 810424291 flags 1,
blkref #0: rel 1663/17221/17557 fork vm blk 0, blkref #1: rel
1663/17221/17557 blk 22659
```

We tried to find another information in WALs for `xid 810424291` and `blk
22659` - nothing.

A few records before 7E/8D9C04C0 from last checkpoint:

```
rmgr: XLOG len (rec/tot): 106/ 106, tx: 0, lsn:
7E/8D99C4B0, prev 7E/8D99C478, desc: CHECKPOINT_ONLINE redo 7E/8D90D0D8; tli
1; prev tli 1; fpw true; xid 0:810982162; oid 476718; multi 1; offset 0;
oldest xid 628489828 in DB 16386; oldest multi 1 in DB 17221; oldest/newest
commit timestamp xid: 0/0; oldest running xid 810982162; online
rmgr: Heap2 len (rec/tot): 57/ 7965, tx: 0, lsn:
7E/8D99C520, prev 7E/8D99C4B0, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 3, blkref #0: rel 1663/17221/17557 blk 22557 FPW
rmgr: Heap2 len (rec/tot): 57/ 8213, tx: 0, lsn:
7E/8D99E458, prev 7E/8D99C520, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 1, blkref #0: rel 1663/17221/17557 blk 22631 FPW
rmgr: Heap2 len (rec/tot): 57/ 8229, tx: 0, lsn:
7E/8D9A0488, prev 7E/8D99E458, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 3, blkref #0: rel 1663/17221/17557 blk 22632 FPW
rmgr: Heap2 len (rec/tot): 57/ 8117, tx: 0, lsn:
7E/8D9A24C8, prev 7E/8D9A0488, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 3, blkref #0: rel 1663/17221/17557 blk 22633 FPW
rmgr: Heap2 len (rec/tot): 57/ 8093, tx: 0, lsn:
7E/8D9A4498, prev 7E/8D9A24C8, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 1, blkref #0: rel 1663/17221/17557 blk 22634 FPW
rmgr: Heap2 len (rec/tot): 64/ 8256, tx: 0, lsn:
7E/8D9A6450, prev 7E/8D9A4498, desc: VISIBLE cutoff xid 0 flags 2, blkref
#0: rel 1663/17221/17557 fork vm blk 0 FPW, blkref #1: rel
1663/17221/17557 blk 22634
rmgr: Heap2 len (rec/tot): 57/ 8101, tx: 0, lsn:
7E/8D9A84A8, prev 7E/8D9A6450, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 4, blkref #0: rel 1663/17221/17557 blk 22639 FPW
rmgr: Heap2 len (rec/tot): 57/ 8149, tx: 0, lsn:
7E/8D9AA468, prev 7E/8D9A84A8, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 1, blkref #0: rel 1663/17221/17557 blk 22640 FPW
rmgr: Heap2 len (rec/tot): 57/ 8213, tx: 0, lsn:
7E/8D9AC458, prev 7E/8D9AA468, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 1, blkref #0: rel 1663/17221/17557 blk 22641 FPW
rmgr: Heap2 len (rec/tot): 57/ 8093, tx: 0, lsn:
7E/8D9AE488, prev 7E/8D9AC458, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 4, blkref #0: rel 1663/17221/17557 blk 22642 FPW
rmgr: Heap2 len (rec/tot): 57/ 8141, tx: 0, lsn:
7E/8D9B0440, prev 7E/8D9AE488, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 2, blkref #0: rel 1663/17221/17557 blk 22643 FPW
rmgr: Heap2 len (rec/tot): 57/ 8125, tx: 0, lsn:
7E/8D9B2428, prev 7E/8D9B0440, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 1, blkref #0: rel 1663/17221/17557 blk 22646 FPW
rmgr: Heap2 len (rec/tot): 57/ 8245, tx: 0, lsn:
7E/8D9B4400, prev 7E/8D9B2428, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 3, blkref #0: rel 1663/17221/17557 blk 22648 FPW
rmgr: Heap2 len (rec/tot): 57/ 8237, tx: 0, lsn:
7E/8D9B6450, prev 7E/8D9B4400, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 1, blkref #0: rel 1663/17221/17557 blk 22649 FPW
rmgr: Heap2 len (rec/tot): 57/ 8221, tx: 0, lsn:
7E/8D9B8498, prev 7E/8D9B6450, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 3, blkref #0: rel 1663/17221/17557 blk 22652 FPW
rmgr: Heap2 len (rec/tot): 57/ 8229, tx: 0, lsn:
7E/8D9BA4D0, prev 7E/8D9B8498, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 3, blkref #0: rel 1663/17221/17557 blk 22653 FPW
rmgr: Heap2 len (rec/tot): 57/ 8157, tx: 0, lsn:
7E/8D9BC510, prev 7E/8D9BA4D0, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 3, blkref #0: rel 1663/17221/17557 blk 22655 FPW
rmgr: Heap2 len (rec/tot): 57/ 8093, tx: 0, lsn:
7E/8D9BE508, prev 7E/8D9BC510, desc: FREEZE_PAGE cutoff xid 760982701
ntuples 1, blkref #0: rel 1663/17221/17557 blk 22657 FPW
rmgr: Heap2 len (rec/tot): 59/ 59, tx: 0, lsn:
7E/8D9C04C0, prev 7E/8D9BE508, desc: VISIBLE cutoff xid 810424291 flags 1,
blkref #0: rel 1663/ 17221/17557 fork vm blk 0, blkref #1: rel
1663/17221/17557 blk 22659
```

File `base/17221/17557` - is a file for DB, which restored with zero
files.

recovery.conf:

```
restore_command = 'pgbackrest --stanza=foo-db archive-get %f "%p"'
recovery_target_time = '2021-02-20 07:00:00'
recovery_target_action = 'promote'
```

Responses

Browse pgsql-bugs by date

  From Date Subject
Next Message PG Bug reporting form 2021-02-24 11:34:23 BUG #16895: Multicolumn GiST index returns incomplete results
Previous Message PG Bug reporting form 2021-02-24 07:52:36 BUG #16893: JDBC Error