The following bug has been logged on the website:
Bug reference: 7969
Logged by: Yunong Xiao
Email address: yjxiao@gmail.com
PostgreSQL version: 9.2.2
Operating system: SmartOS (Solaris)
Description: =
I have an instance of postgresql 9.2.2 running on Solaris. At some point the
zone the postgresql was running on was restarted (effectively a power cycle)
and postgresql consistently crashes on recovery with the following log
snippet: (full log and postgresql.conf attached at the end of this email)
2013-03-15 22:00:49.510 UTCLOG: database system was not properly shut down;
automatic recovery in progress
2013-03-15 22:00:49.510 UTCDEBUG: resetting unlogged relations: cleanup 1
init 0
2013-03-15 22:00:49.511 UTCLOG: redo starts at 0/551EC58
2013-03-15 22:00:49.515 UTCDEBUG: page 10 of relation base/16384/16666 does
not exist
2013-03-15 22:00:49.515 UTCCONTEXT: xlog redo update: rel 1663/16384/16666;
tid 8/4; new 10/5
2013-03-15 22:00:49.515 UTCFATAL: incorrect local pin count: 2
I am running postgres on ZFS with fsync=3Don, which as far as I can tell,
guarantees that there can be no data corruption. I have included the
postgres data directory as a tarball here:
https://download.joyent.com/pub/postgresql/corrupted-pg.tar and this problem
can be reproduced by untarring the data directory and running as the
postgres user `postgres -D <path_to_data_dir>`
Full postgresql logs:
2013-03-15 22:00:49.509 UTCLOG: database system was interrupted while in
recovery at 2013-03-15 21:55:49 UTC
2013-03-15 22:00:49.509 UTCHINT: This probably means that some data is
corrupted and you will have to use the last backup for recovery.
2013-03-15 22:00:49.510 UTCDEBUG: checkpoint record is at 0/551F6B0
2013-03-15 22:00:49.510 UTCDEBUG: redo record is at 0/551EC58; shutdown
FALSE
2013-03-15 22:00:49.510 UTCDEBUG: next transaction ID: 0/1693; next OID:
24576
2013-03-15 22:00:49.510 UTCDEBUG: next MultiXactId: 1; next
MultiXactOffset: 0
2013-03-15 22:00:49.510 UTCDEBUG: oldest unfrozen transaction ID: 665, in
database 1
2013-03-15 22:00:49.510 UTCDEBUG: transaction ID wrap limit is 2147484312,
limited by database with OID 1
2013-03-15 22:00:49.510 UTCLOG: database system was not properly shut down;
automatic recovery in progress
2013-03-15 22:00:49.510 UTCDEBUG: resetting unlogged relations: cleanup 1
init 0
2013-03-15 22:00:49.511 UTCLOG: redo starts at 0/551EC58
2013-03-15 22:00:49.515 UTCDEBUG: page 10 of relation base/16384/16666 does
not exist
2013-03-15 22:00:49.515 UTCCONTEXT: xlog redo update: rel 1663/16384/16666;
tid 8/4; new 10/5
2013-03-15 22:00:49.515 UTCFATAL: incorrect local pin count: 2
2013-03-15 22:00:49.515 UTCCONTEXT: xlog redo clean: rel 1663/16384/16666;
blk 8 remxid 1729
2013-03-15 22:00:49.515 UTCDEBUG: shmem_exit(1): 4 callbacks to make
2013-03-15 22:00:49.515 UTCDEBUG: proc_exit(1): 2 callbacks to make
2013-03-15 22:00:49.515 UTCDEBUG: exit(1)
2013-03-15 22:00:49.515 UTCDEBUG: shmem_exit(-1): 0 callbacks to make
2013-03-15 22:00:49.515 UTCDEBUG: proc_exit(-1): 0 callbacks to make
2013-03-15 22:00:49.518 UTCDEBUG: reaping dead processes
2013-03-15 22:00:49.518 UTCLOG: startup process (PID 23162) exited with
exit code 1
2013-03-15 22:00:49.518 UTCLOG: aborting startup due to startup process
failure
2013-03-15 22:00:49.518 UTCDEBUG: shmem_exit(1): 3 callbacks to make
2013-03-15 22:00:49.524 UTCDEBUG: proc_exit(1): 3 callbacks to make
2013-03-15 22:00:49.524 UTCDEBUG: exit(1)
2013-03-15 22:00:49.524 UTCDEBUG: shmem_exit(-1): 0 callbacks to make
2013-03-15 22:00:49.524 UTCDEBUG: proc_exit(-1): 0 callbacks to make
2013-03-15 22:00:49.526 UTCDEBUG: logger shutting down
2013-03-15 22:00:49.526 UTCDEBUG: shmem_exit(0): 0 callbacks to make
2013-03-15 22:00:49.526 UTCDEBUG: proc_exit(0): 0 callbacks to make
2013-03-15 22:00:49.527 UTCDEBUG: exit(0)
2013-03-15 22:00:49.527 UTCDEBUG: shmem_exit(-1): 0 callbacks to make
2013-03-15 22:00:49.527 UTCDEBUG: proc_exit(-1): 0 callbacks to make
postgresql-2013-03-15_220049.log (END)
postgresql.conf
listen_addresses =3D '0.0.0.0' # what IP address(es) to listen on;
port =3D 5432 # (change requires restart)
max_connections =3D 100 # (change requires restart)
shared_buffers =3D 32MB # min 128kB
wal_level =3D hot_standby # minimal, archive, or hot_standby
fsync =3D on # turns forced synchronization on or off
synchronous_commit =3D remote_write
full_page_writes =3D off # recover from partial page writes
max_wal_senders =3D 15 # max number of walsender processes
wal_keep_segments =3D 1000 # in logfile segments, 16MB each; 0 disables
synchronous_standby_names =3D '' # standby servers that provide sync rep
hot_standby =3D on # "on" allows queries during recovery
max_standby_archive_delay =3D 30s # max delay before canceling queries
max_standby_streaming_delay =3D 30s # max delay before canceling queries
wal_receiver_status_interval =3D 10s # send replies at least this often
hot_standby_feedback =3D off # send info from standby to prevent
log_destination =3D 'stderr' # Valid values are combinations of
logging_collector =3D on # Enable capturing of stderr and csvlog
log_directory =3D '/var/pg/' # directory where log files are written,
log_filename =3D 'postgresql-%Y-%m-%d_%H%M%S.log' # log file name patter=
n,
log_file_mode =3D 0600 # creation mode for log files,
log_rotation_age =3D 0 # Automatic rotation of logfiles will
log_rotation_size =3D 0 # Automatic rotation of logfiles will
log_min_messages =3D debug5 # values in order of decreasing detail:
log_line_prefix =3D '%m' # special values:
log_timezone =3D 'UTC'
datestyle =3D 'iso, mdy'
timezone =3D 'UTC'
lc_messages =3D 'C' # locale for system error message
lc_monetary =3D 'C' # locale for monetary formatting
lc_numeric =3D 'C' # locale for number formatting
lc_time =3D 'C' # locale for time formatting
default_text_search_config =3D 'pg_catalog.english'