BUG #7969: Postgres Recovery Fatal With: "incorrect local pin count: 2"

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'