Re: BUG #13977: Strange behavior with WAL archive recovery

Hi,

> On 22 Feb 2016, at 15:31, eshkinkot(at)gmail(dot)com wrote:
>
> The following bug has been logged on the website:
>
> Bug reference: 13977
> Logged by: Sergey Burladyan
> Email address: eshkinkot(at)gmail(dot)com
> PostgreSQL version: 9.4.6
> Operating system: Debian GNU/Linux 8.2 (jessie)
> Description:
>
> Hello
>
> I see in postgresql.log what server constantly receives the same file from
> WAL archive. I does not see this in 9.2 version.
>
> recovery.conf:
> restore_command = 'restore_cmd /mnt/WALs %f %p'
> recovery_target_timeline = 'latest'
> standby_mode = on
>
> 2016-02-22 17:23:15.820 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C1" from archive
> 2016-02-22 17:23:16.323 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C2" from archive
> 2016-02-22 17:23:16.639 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C3" from archive
> 2016-02-22 17:23:16.983 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C4" from archive
> 2016-02-22 17:23:17.119 MSK pid=19436,user=,db=,host= LOG: unexpected
> pageaddr 74A4/C8000000 in log segment 00000001000074A7000000C5, offset 0
> 2016-02-22 17:23:20.279 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C4" from archive
> 2016-02-22 17:23:20.473 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C5" from archive
> 2016-02-22 17:23:20.809 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C6" from archive
> 2016-02-22 17:23:21.189 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C7" from archive
> 2016-02-22 17:23:21.361 MSK pid=19436,user=,db=,host= LOG: unexpected
> pageaddr 74A4/D5000000 in log segment 00000001000074A7000000C8, offset 0
> 2016-02-22 17:23:25.527 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C7" from archive
> 2016-02-22 17:23:30.695 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C7" from archive
> 2016-02-22 17:23:35.864 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C7" from archive
> 2016-02-22 17:23:41.033 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C7" from archive
> 2016-02-22 17:23:45.200 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C7" from archive
> 2016-02-22 17:23:50.374 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C7" from archive
> 2016-02-22 17:23:55.546 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C7" from archive
> 2016-02-22 17:24:00.717 MSK pid=19436,user=,db=,host= LOG: restored log file
> "00000001000074A7000000C7" from archive

I think it’s expected. PostgreSQL reports the latest file it has restored, meaning that once it restored 00000001000074A7000000C7 it was not able to get the following one (presumably, 00000001000074A7000000C8, unless there was a timeline change).

If there is a 00000001000074A7000000C8 in the archive, then perhaps there is something wrong with it (check the md5). Sometimes turning on log_min_messages=‘debug’ helps finding out the reason why PostgreSQL is unable to restore the given segment.

--
Oleksii