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

Hi,

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

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=3D=E2=80=98debug=E2=80=99 helps finding out the reason =
why PostgreSQL is unable to restore the given segment.

--
Oleksii