BUG #13977: Strange behavior with WAL archive recovery

Hi,

On 22 Feb 2016, at 15:31, eshkinkot@gmail.com wrote:

The following bug has been logged on the website:

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:

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

On Thu, Feb 25, 2016 at 12:54 AM, Oleksii Kliukin <alexk@hintbits.com> wrote:

On 22 Feb 2016, at 15:31, eshkinkot@gmail.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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs