Re: Re: Hot standby 9.2.6 -> 9.2.6 PANIC: WAL contains references to invalid pages

On 06/09/2014 02:27 PM, jlrando wrote:
> Hi all,
>
> I am also facing this issue. I set up streaming replication for a PG 9.2.6
> database in both master and slave. I have used pg_basebackup to dump master
> database to slave. It took two hours to complete pg_basebackup. During this
> time a lot of wal files were archived. As expected, when slave database
> started up it went through archived wal files for 5 hours to catch the
> master. During recovery from archived wal files appeared some warnings like
> this:
>
> ...
> Jun 6 14:55:50 VNWID1-4 postgres[17024]: [177-1] [2014-06-06 14:55:50 CEST]
> 17024@ LOG: restored log file "000000010000066C000000E4" from archive
> Jun 6 14:55:51 VNWID1-4 postgres[17032]: [1-1] [2014-06-06 14:55:51 CEST]
> 17032@ WARNING: xlog min recovery request 67B/B36ABD78 is past current
> point 66C/E4FFFFE8
> Jun 6 14:55:51 VNWID1-4 postgres[17032]: [1-2] [2014-06-06 14:55:51 CEST]
> 17032@ CONTEXT: writing block 0 of relation
> pg_tblspc/16756/PG_9.2_201204301/16757/1116517382_vm
> Jun 6 14:55:51 VNWID1-4 postgres[17024]: [178-1] [2014-06-06 14:55:51 CEST]
> 17024@ LOG: restored log file "000000010000066C000000E5" from archive
> ...
>
> It seems they are harmless and can be safely ignored, but I prefer to state
> this in the post in case be relevant for any reason.

Hmm. That warning shouldn't happen, but looking at the visibility map
code, I see how it could:

During the WAL replay, a heap update is replayed, which clears a bit in
the visibility map. That dirties the VM page, but we intentionally don't
check or update the LSN on the VM page. The VM buffer is now dirty in
the buffer pool, but if it was backed up later during the backup, it has
a greater LSN than what we're currently replaying. When that buffer gets
written out, you get the warning.

Yeah, I think that's harmless. But we should look into fixing that...

> It seems that all is ok until now. And no other message was logged until the
> crash. After some hours of replication being working properly, Postgres
> stopped and log contains this:
>
> Jun 7 17:52:45 VNWID1-4 postgres[17024]: [15765-1] [2014-06-07 17:52:45
> CEST] 17024@ WARNING: page 916 of relation
> pg_tblspc/16756/PG_9.2_201204301/16757/402007830 is uninitialized
> Jun 7 17:52:45 VNWID1-4 postgres[17024]: [15765-2] [2014-06-07 17:52:45
> CEST] 17024@ CONTEXT: xlog redo vacuum: rel 16756/16757/402007830; blk
> 917, lastBlockVacuumed 915
> Jun 7 17:52:45 VNWID1-4 postgres[17024]: [15766-1] [2014-06-07 17:52:45
> CEST] 17024@ PANIC: WAL contains references to invalid pages
> Jun 7 17:52:45 VNWID1-4 postgres[17024]: [15766-2] [2014-06-07 17:52:45
> CEST] 17024@ CONTEXT: xlog redo vacuum: rel 16756/16757/402007830; blk
> 917, lastBlockVacuumed 915
> Jun 7 17:52:45 VNWID1-4 postgres[17021]: [2-1] [2014-06-07 17:52:45 CEST]
> 17021@ LOG: startup process (PID 17024) was terminated by signal 6: Aborted
> Jun 7 17:52:45 VNWID1-4 postgres[17021]: [3-1] [2014-06-07 17:52:45 CEST]
> 17021@ LOG: terminating any other active server processes
>
> I think that this issue is exactly the same that is being discussed in this
> thread and I have seen that a patch was released for this bug.

Yeah, that looks like the same bug.

> Could anyone tell me how to get / apply this patch?

It's included in 9.2.8. Just update the binaries.

- Heikki