BUG #7883: "PANIC: WAL contains references to invalid pages" on replica recovery

[m***@heroku.com]

The following bug has been logged on the website:

Bug reference: 7883
Logged by: Maciek Sakrejda
Email address: ***@heroku.com
PostgreSQL version: 9.1.8
Operating system: Ubuntu 12.04 64-bit
Description:

We ran into a customer database giving us the error above when replicating
from 9.1.7 to 9.1.8 and attempting to fail over to the 9.1.8. I noticed
several fixes to WAL replay in 9.1.8--could this be a factor in this case?
We're trying again with a fresh replica; hopefully that will just work. Logs
from the incident are below.

Thanks,
Maciek

Feb 15 00:49:12 wal_e.worker.s3_worker INFO MSG: could not locate object
while performing wal restore#012 DETAIL: The absolute URI that could
not be located is
s3://wal-e-[redacted]/wal-e-backups/timeline-0e0b390f-cb3f-4192-8cdb-fced4d54b0a2/wal_005/000000010000003C00000094.lzo.#012
HINT: This can be normal when Postgres is trying to detect what
timelines are available during restoration.
Feb 15 00:49:12 [1300-1] [COPPER] LOG: invalid magic number 0000 in log
file 60, segment 148, offset 0
Feb 15 00:49:13 wal_e.worker.s3_worker INFO MSG: could not locate object
while performing wal restore#012 DETAIL: The absolute URI that could
not be located is
s3://wal-e-[redacted]/wal-e-backups/timeline-0e0b390f-cb3f-4192-8cdb-fced4d54b0a2/wal_005/000000010000003C00000094.lzo.#012
HINT: This can be normal when Postgres is trying to detect what
timelines are available during restoration.
Feb 15 00:49:13 [1301-1] [COPPER] LOG: redo done at 3C/930000B0
Feb 15 00:49:13 [1302-1] [COPPER] LOG: last completed transaction was at
log time 2013-02-14 22:35:05.338681+00
Feb 15 00:49:15 wal_e.worker.s3_worker INFO MSG: completed download and
decompression#012 DETAIL: Downloaded and decompressed
"s3://wal-e-[redacted]/wal-e-backups/timeline-0e0b390f-cb3f-4192-8cdb-fced4d54b0a2/wal_005/000000010000003C00000093.lzo"
to "pg_xlog/RECOVERYXLOG"
Feb 15 00:49:15 [1303-1] [COPPER] LOG: restored log file
"000000010000003C00000093" from archive
Feb 15 00:49:15 wal_e.worker.s3_worker INFO MSG: could not locate object
while performing wal restore#012 DETAIL: The absolute URI that could
not be located is
s3://wal-e-[redacted]/wal-e-backups/timeline-0e0b390f-cb3f-4192-8cdb-fced4d54b0a2/wal_005/00000002.history.lzo.#012
HINT: This can be normal when Postgres is trying to detect what
timelines are available during restoration.
Feb 15 00:49:16 [1304-1] [COPPER] LOG: selected new timeline ID: 2
Feb 15 00:49:16 wal_e.worker.s3_worker INFO MSG: could not locate object
while performing wal restore#012 DETAIL: The absolute URI that could
not be located is
s3://wal-e-[redacted]/wal-e-backups/timeline-0e0b390f-cb3f-4192-8cdb-fced4d54b0a2/wal_005/00000001.history.lzo.#012
HINT: This can be normal when Postgres is trying to detect what
timelines are available during restoration.
Feb 15 00:49:16 [1305-1] [COPPER] LOG: archive recovery complete
Feb 15 00:49:16 [1306-1] [COPPER] WARNING: page 37956 of relation
base/16385/16430 was uninitialized
Feb 15 00:49:16 [1307-1] [COPPER] PANIC: WAL contains references to
invalid pages
Feb 15 00:49:17 [3-1] [COPPER] LOG: startup process (PID 7) was terminated
by signal 6: Aborted
Feb 15 00:49:17 [4-1] [COPPER] LOG: terminating any other active server
processes
Feb 15 00:49:17 [37-1] collectd [COPPER] WARNING: terminating connection
because of crash of another server process
Feb 15 00:49:17 [37-2] collectd [COPPER] DETAIL: The postmaster has
commanded this server process to roll back the current transaction and exit,
because another server process exited abnormally and possibly corrupted
shared memory.
Feb 15 00:49:17 [37-3] collectd [COPPER] HINT: In a moment you should be
able to reconnect to the database and repeat your command.

[Heikki Linnakangas]

Post by m***@heroku.com
Bug reference: 7883
Logged by: Maciek Sakrejda
PostgreSQL version: 9.1.8
Operating system: Ubuntu 12.04 64-bit
We ran into a customer database giving us the error above when replicating
from 9.1.7 to 9.1.8 and attempting to fail over to the 9.1.8. I noticed
several fixes to WAL replay in 9.1.8--could this be a factor in this case?
...
Feb 15 00:49:16 [1305-1] [COPPER] LOG: archive recovery complete
Feb 15 00:49:16 [1306-1] [COPPER] WARNING: page 37956 of relation
base/16385/16430 was uninitialized
Feb 15 00:49:16 [1307-1] [COPPER] PANIC: WAL contains references to
invalid pages

Hmm, that sure looks like the same issue Kyotaro HORIGUCHI reported
(http://www.postgresql.org/message-id/***@lab.ntt.co.jp),
but that was fixed in 9.1.8. Maybe there's some corner case where it's
still not working.

Did you keep a copy of the WAL involved? Any chance of running xlogdump
on it, and posting the results, or just sending over the WAL files so I
could take a look?

- Heikki

[Maciek Sakrejda]

Hmm, that sure looks like the same issue Kyotaro HORIGUCHI reported (
but that was fixed in 9.1.8. Maybe there's some corner case where it's
still not working.

We reproduce it on a separate replica with the same base backup. Tried a
new base backup; that worked.

Did you keep a copy of the WAL involved? Any chance of running xlogdump on
it, and posting the results, or just sending over the WAL files so I could
take a look?

Yes, we have the WAL. I can't share it as it's customer data. I tried
setting up xlogdump (this, yes? https://github.com/snaga/xlogdump ), but
ran into problems building it (tag REL0_5_2):

***@host:/home/heroku/xlogdump# PATH=/usr/lib/postgresql/9.1/bin:$PATH
USE_PGXS=1 make
gcc -g -O2 -fstack-protector --param=ssp-buffer-size=4 -Wformat
-Wformat-security -Werror=format-security -fPIC -Wall -Wmissing-prototypes
-Wpointer-arith -Wdeclaration-after-statement -Wendif-labels
-Wformat-security -fno-strict-aliasing -fwrapv -fexcess-precision=standard
-g -I/usr/include/postgresql -DDATADIR=\"/usr/share/postgresql/9.1\" -I.
-I. -I/usr/include/postgresql/9.1/server -I/usr/include/postgresql/internal
-D_FORTIFY_SOURCE=2 -DLINUX_OOM_ADJ=0 -D_GNU_SOURCE -I/usr/include/libxml2
-I/usr/include/tcl8.5 -c -o xlogdump.o xlogdump.c
xlogdump.c: In function ‘ReadRecord’:
xlogdump.c:321:7: warning: format ‘%u’ expects argument of type ‘unsigned
int’, but argument 3 has type ‘long unsigned int’ [-Wformat]
xlogdump.c: At top level:
xlogdump.c:865:1: error: conflicting types for ‘ExceptionalCondition’
/usr/include/postgresql/postgres.h:686:13: note: previous declaration of
‘ExceptionalCondition’ was here
make: *** [xlogdump.o] Error 1

[Daniel Farina]

On Fri, Feb 15, 2013 at 7:10 AM, Heikki Linnakangas <

Hmm, that sure looks like the same issue Kyotaro HORIGUCHI reported (
but that was fixed in 9.1.8. Maybe there's some corner case where it's
still not working.

We reproduce it on a separate replica with the same base backup. Tried a
new base backup; that worked.

Did you keep a copy of the WAL involved? Any chance of running xlogdump
on it, and posting the results, or just sending over the WAL files so I
could take a look?

Yes, we have the WAL. I can't share it as it's customer data. I tried
setting up xlogdump (this, yes? https://github.com/snaga/xlogdump ), but
USE_PGXS=1 make
gcc -g -O2 -fstack-protector --param=ssp-buffer-size=4 -Wformat
-Wformat-security -Werror=format-security -fPIC -Wall -Wmissing-prototypes
-Wpointer-arith -Wdeclaration-after-statement -Wendif-labels
-Wformat-security -fno-strict-aliasing -fwrapv -fexcess-precision=standard
-g -I/usr/include/postgresql -DDATADIR=\"/usr/share/postgresql/9.1\" -I.
-I. -I/usr/include/postgresql/9.1/server -I/usr/include/postgresql/internal
-D_FORTIFY_SOURCE=2 -DLINUX_OOM_ADJ=0 -D_GNU_SOURCE -I/usr/include/libxml2
-I/usr/include/tcl8.5 -c -o xlogdump.o xlogdump.c
xlogdump.c:321:7: warning: format ‘%u’ expects argument of type ‘unsigned
int’, but argument 3 has type ‘long unsigned int’ [-Wformat]
xlogdump.c:865:1: error: conflicting types for ‘ExceptionalCondition’
/usr/include/postgresql/postgres.h:686:13: note: previous declaration of
‘ExceptionalCondition’ was here
make: *** [xlogdump.o] Error 1

Can you try master on xlogdump instead of the release? I have fixed a few
bugs there a year ago that don't seem to be in the release, and will fix
more if necessary.

[Maciek Sakrejda]

Post by Daniel Farina
Can you try master on xlogdump instead of the release? I have fixed a few
bugs there a year ago that don't seem to be in the release, and will fix
more if necessary.

Had tried that, too--complained about a missing pg_crc_tables.h

[Daniel Farina]

Post by Maciek Sakrejda

Post by Daniel Farina
Can you try master on xlogdump instead of the release? I have fixed a few
bugs there a year ago that don't seem to be in the release, and will fix
more if necessary.

Had tried that, too--complained about a missing pg_crc_tables.h

I'm poking at this and somehow it seems like the wrong PG_VERSION_NUM is
being slurped in -- even though the gcc invocation would suggest it is
properly targeting 9.1 -- which is causing xlogdump to have a cow with
versions < 9.2.

I think the problem is related to this:

/usr/include/postgresql/9.1/server/fmgr.h: PG_VERSION_NUM / 100, \
/usr/include/postgresql/9.1/server/pg_config.h:#define PG_VERSION_NUM 90108
/usr/include/postgresql/pg_config.h:#define PG_VERSION_NUM 90203 <-- this
one
/usr/include/postgresql/9.2/server/fmgr.h: PG_VERSION_NUM / 100, \
/usr/include/postgresql/9.2/server/pg_config.h:#define PG_VERSION_NUM 90203

And USE_PGXS=1 make yields something like....
gcc -g -O2 -fstack-protector --param=ssp-buffer-size=4 -Wformat
-Werror=format-security -fPIC -pie -Wall -Wmissing-prototypes
-Wpointer-arith -Wdeclaration-after-statement -Wendif-labels
-Wformat-security -fno-strict-aliasing -fwrapv -fexcess-precision=standard
-g -DVERSION_STR=\""0.6devel"\" -I. -I/usr/include/postgresql
-DDATADIR=\"/usr/share/postgresql/9.1\" -I. -I.
-I/usr/include/postgresql/9.1/server -I/usr/include/postgresql/internal
-D_FORTIFY_SOURCE=2 -DLINUX_OOM_ADJ=0 -D_GNU_SOURCE -I/usr/include/libxml2
-I/usr/include/tcl8.5 -c -o strlcpy.o strlcpy.c

Where, notably, both the 9.1 and /usr/include/postgresql directories are in
place. Hence, which ever pg_config gets loaded in first decides what
PG_VERSION_NUM is compiling against...that's no good...

Why is it there...because:

dpkg -S /usr/include/postgresql/pg_config.h
libpq-dev: /usr/include/postgresql/pg_config.h

I guess that means Ubuntu (and probably Debian?) libpq-dev breaks
PG_VERSION_NUM for PGXS=1.

[Maciek Sakrejda]

Purged and reinstalled the dev packages (only reinstalled 9.1) and I still
get the same error. The pg_config.h in /usr/include/postgresql/ looks legit:

***@ip-10-99-18-64:~/xlogdump$ grep PG_VERSION
/usr/include/postgresql/pg_config.h
#define PG_VERSION "9.1.8"
#define PG_VERSION_NUM 90108
#define PG_VERSION_STR "PostgreSQL 9.1.8 on x86_64-unknown-linux-gnu,
compiled by gcc-4.6.real (Ubuntu/Linaro 4.6.3-1ubuntu5) 4.6.3, 64-bit"

Any ideas?

[Heikki Linnakangas]

Post by Daniel Farina
I guess that means Ubuntu (and probably Debian?) libpq-dev breaks
PG_VERSION_NUM for PGXS=1.

That obviously needs to be fixed in debian. Meanwhile, Maciek, I'd
suggest that you build PostgreSQL from sources, install it to some
temporary location, and then build xlogdump against that.

- Heikki

[Maciek Sakrejda]

On Mon, Feb 18, 2013 at 12:57 AM, Heikki Linnakangas <

Post by Daniel Farina
I guess that means Ubuntu (and probably Debian?) libpq-dev breaks
PG_VERSION_NUM for PGXS=1.

That obviously needs to be fixed in debian. Meanwhile, Maciek, I'd suggest
that you build PostgreSQL from sources, install it to some temporary
location, and then build xlogdump against that.

That worked, thanks. I have a working xlogdump. Any pointers as to what I
should look for? This is the contents of the pg_xlog directory:

total 49160
-rw------- 1 udrehggpif7kft postgres 16777216 Feb 15 00:00
000000010000003C00000093
-rw------- 1 udrehggpif7kft postgres 16777216 Feb 15 00:47
000000010000003C00000094
-rw------- 1 udrehggpif7kft postgres 16777216 Feb 15 00:49
000000020000003C00000093
-rw------- 1 udrehggpif7kft postgres 56 Feb 15 00:49 00000002.history
drwx------ 2 udrehggpif7kft postgres 4096 Feb 15 00:49 archive_status


This is what's in 00000002.history:

1 000000010000003C00000093 no recovery target specified

[Heikki Linnakangas]

On Mon, Feb 18, 2013 at 12:57 AM, Heikki Linnakangas<

Post by Daniel Farina
I guess that means Ubuntu (and probably Debian?) libpq-dev breaks
PG_VERSION_NUM for PGXS=1.

That obviously needs to be fixed in debian. Meanwhile, Maciek, I'd suggest
that you build PostgreSQL from sources, install it to some temporary
location, and then build xlogdump against that.

That worked, thanks. I have a working xlogdump. Any pointers as to what I
total 49160
-rw------- 1 udrehggpif7kft postgres 16777216 Feb 15 00:00
000000010000003C00000093
-rw------- 1 udrehggpif7kft postgres 16777216 Feb 15 00:47
000000010000003C00000094
-rw------- 1 udrehggpif7kft postgres 16777216 Feb 15 00:49
000000020000003C00000093
-rw------- 1 udrehggpif7kft postgres 56 Feb 15 00:49 00000002.history
drwx------ 2 udrehggpif7kft postgres 4096 Feb 15 00:49 archive_status

I'd like to see the contents of the WAL, starting from the last
checkpoint, up to the point where failover happened. In particular, any
actions on the relation base/16385/16430, which caused the error.
pg_controldata output on the base backup would also interesting, as well
as the contents of backup_label file.

How long did the standby run between the base backup and the failover?
How many WAL segments?

One more thing you could try to narrow down the error: restore from the
base backup, and let it run up to the point of failover, but shut it
down just before the failover with "pg_ctl stop -m fast". That should
create a restartpoint, at the latest checkpoint record. Then restart,
and perform failover. If it still throws the same error, we know that
the WAL record that touched the page that doesn't exist was after the
last checkpoint.

- Heikki

[Maciek Sakrejda]

Post by Heikki Linnakangas
I'd like to see the contents of the WAL, starting from the last
checkpoint, up to the point where failover happened. In particular, any
actions on the relation base/16385/16430, which caused the error.
pg_controldata output on the base backup would also interesting, as well as
the contents of backup_label file.
How long did the standby run between the base backup and the failover? How
many WAL segments?
One more thing you could try to narrow down the error: restore from the
base backup, and let it run up to the point of failover, but shut it down
just before the failover with "pg_ctl stop -m fast". That should create a
restartpoint, at the latest checkpoint record. Then restart, and perform
failover. If it still throws the same error, we know that the WAL record
that touched the page that doesn't exist was after the last checkpoint.

Unfortunately, it looks like we lost the bad wal segments and necessary
base backup due to our archiving mechanism. We don't yet have a principled
way of saving systems for forensics. I thought I had manually accounted for
everything to keep this "on ice" but I missed a step and the system was
archived. I apologize. I'll see if I can add something for us to better
support this.

For what it's worth the failover was done at 2013-02-14 23:55:44 +0000 and
the base backup used was dated 2013-02-15 00:49:22 +0000.

I'll follow up in case we run into this again.