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

On Thu, Feb 25, 2016 at 12:54 AM, Oleksii Kliukin <alexk(at)hintbits(dot)com> wrote:
>> On 22 Feb 2016, at 15:31, eshkinkot(at)gmail(dot)com wrote:
>> 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: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

Those two entries are weird. A segment has been restored, but then a
complain comes from segment+1 in the error context given here. Looking
at xlogreader.c there is no one-off kind of problems in the reader
machinery.

>> 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
>
> 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).

This error message is reported by Postgres once a segment is being
correctly restored in pg_xlog and that it is found to have a correct
size. What is actually restore_cmd doing?
--
Michael