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

On Thu, Feb 25, 2016 at 12:54 AM, Oleksii Kliukin <alexk@hintbits.com> wrot=
e:
>> On 22 Feb 2016, at 15:31, eshkinkot@gmail.com wrote:
>> 2016-02-22 17:23:16.983 MSK pid=3D19436,user=3D,db=3D,host=3D LOG: resto=
red log file
>> "00000001000074A7000000C4" from archive
>> 2016-02-22 17:23:17.119 MSK pid=3D19436,user=3D,db=3D,host=3D LOG: unexp=
ected
>> pageaddr 74A4/C8000000 in log segment 00000001000074A7000000C5, offset 0

[...]

>> 2016-02-22 17:23:21.189 MSK pid=3D19436,user=3D,db=3D,host=3D LOG: resto=
red log file
>> "00000001000074A7000000C7" from archive
>> 2016-02-22 17:23:21.361 MSK pid=3D19436,user=3D,db=3D,host=3D LOG: unexp=
ected
>> 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=3D19436,user=3D,db=3D,host=3D LOG: resto=
red log file
>> "00000001000074A7000000C7" from archive
>> [...]
>> 2016-02-22 17:23:30.695 MSK pid=3D19436,user=3D,db=3D,host=3D LOG: resto=
red log file
>> "00000001000074A7000000C7" from archive
>
> I think it=E2=80=99s 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, unles=
s 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?
--=20
Michael