Re: BUG #7500: hot-standby replica crash after an initial rsync

On Tue, Aug 21, 2012 at 8:08 PM, Maxim Boguk <maxim(dot)boguk(at)gmail(dot)com> wrote:

>
> >
>> >
>> > I have kept all that database files for the future investigation.
>> >
>> > What I should look into first?
>> Could you reproduce the error with log_error_verbosity=verbose? Or even
>> better
>> provide a backtrace with gdb?
>>
>>
> There log with log_error_verbosity=verbose:
>
>
> 2012-08-21 14:04:18.973 MSK 33950 @ from [vxid: txid:0] []LOG: 00000:
> database system was interrupted while in recovery at log time 2012-08-21
> 08:21:42 MSK
> 2012-08-21 14:04:18.973 MSK 33950 @ from [vxid: txid:0] []HINT: If this
> has occurred more than once some data might be corrupted and you might need
> to choose an earlier recovery target.
> 2012-08-21 14:04:18.973 MSK 33950 @ from [vxid: txid:0] []LOCATION:
> StartupXLOG, xlog.c:5757
> 2012-08-21 14:04:18.973 MSK 33950 @ from [vxid: txid:0] []LOG: 00000:
> creating missing WAL directory "pg_xlog/archive_status"
> 2012-08-21 14:04:18.973 MSK 33950 @ from [vxid: txid:0] []LOCATION:
> ValidateXLOGDirectoryStructure, xlog.c:3452
> 2012-08-21 14:04:19.009 MSK 33950 @ from [vxid: txid:0] []LOG: 00000:
> entering standby mode
> 2012-08-21 14:04:19.009 MSK 33950 @ from [vxid: txid:0] []LOCATION:
> StartupXLOG, xlog.c:5827
> 2012-08-21 14:04:19.041 MSK 33951 @ from [vxid: txid:0] []LOG: 00000:
> streaming replication successfully connected to primary
> 2012-08-21 14:04:19.041 MSK 33951 @ from [vxid: txid:0] []LOCATION:
> libpqrcv_connect, libpqwalreceiver.c:169
> 2012-08-21 14:04:20.140 MSK 33950 @ from [vxid:1/0 txid:0] []LOG: 00000:
> redo starts at 925/2C0004C8
> 2012-08-21 14:04:20.140 MSK 33950 @ from [vxid:1/0 txid:0] []LOCATION:
> StartupXLOG, xlog.c:6199
> 2012-08-21 14:04:20.160 MSK 33950 @ from [vxid:1/0 txid:0] []FATAL:
> XX000: could not access status of transaction 361788644
> 2012-08-21 14:04:20.161 MSK 33950 @ from [vxid:1/0 txid:0] []DETAIL:
> Could not read from file "pg_multixact/offsets/1590" at offset 114688:
> Unknown error: 0.
> 2012-08-21 14:04:20.161 MSK 33950 @ from [vxid:1/0 txid:0] []CONTEXT:
> xlog redo create multixact 361788644 offset 822580965: 1768508061 1768508078
> 2012-08-21 14:04:20.161 MSK 33950 @ from [vxid:1/0 txid:0] []LOCATION:
> SlruReportIOError, slru.c:840
> 2012-08-21 14:04:20.169 MSK 33948 @ from [vxid: txid:0] []LOG: 00000:
> startup process (PID 33950) exited with exit code 1
> 2012-08-21 14:04:20.169 MSK 33948 @ from [vxid: txid:0] []LOCATION:
> LogChildExit, postmaster.c:2840
> 2012-08-21 14:04:20.169 MSK 33948 @ from [vxid: txid:0] []LOG: 00000:
> terminating any other active server processes
> 2012-08-21 14:04:20.169 MSK 33948 @ from [vxid: txid:0] []LOCATION:
> HandleChildCrash, postmaster.c:2674
>
>
I tried A bit play with more detailed debug info and got mode detailed log:

LOG: 00000: database system was interrupted while in recovery at log time
2012-08-21 08:21:42 MSK
HINT: If this has occurred more than once some data might be corrupted and
you might need to choose an earlier recovery target.
LOCATION: StartupXLOG, xlog.c:5757
DEBUG: 00000: standby_mode = 'on'
LOCATION: readRecoveryCommandFile, xlog.c:5269
DEBUG: 00000: primary_conninfo = 'host=10.12.22.19 port=5433 user=replica
password=acilper'
LOCATION: readRecoveryCommandFile, xlog.c:5276
DEBUG: 00000: trigger_file = '/db/data/failover'
LOCATION: readRecoveryCommandFile, xlog.c:5283
LOG: 00000: entering standby mode
LOCATION: StartupXLOG, xlog.c:5827
DEBUG: 00000: checkpoint record is at 925/2D41CAA0
LOCATION: StartupXLOG, xlog.c:5894
DEBUG: 00000: redo record is at 925/2C0004C8; shutdown FALSE
LOCATION: StartupXLOG, xlog.c:5929
DEBUG: 00000: next transaction ID: 0/1768511856; next OID: 59880938
LOCATION: StartupXLOG, xlog.c:5933
DEBUG: 00000: next MultiXactId: 361788644; next MultiXactOffset: 822580965
LOCATION: StartupXLOG, xlog.c:5936
DEBUG: 00000: oldest unfrozen transaction ID: 1569182525, in database 16424
LOCATION: StartupXLOG, xlog.c:5939
DEBUG: 00000: transaction ID wrap limit is 3716666172, limited by database
with OID 16424
LOCATION: SetTransactionIdLimit, varsup.c:334
DEBUG: 00000: initializing for hot standby
LOCATION: StartupXLOG, xlog.c:6070
DEBUG: 00000: my backend id is 1
LOCATION: SharedInvalBackendInit, sinvaladt.c:326
LOG: 00000: redo starts at 925/2C0004C8
LOCATION: StartupXLOG, xlog.c:6199
DEBUG: 00000: record known xact 1768508078 latestObservedXid 0
CONTEXT: xlog redo commit: 2012-08-21 08:21:42.079655+04
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508078 latestObservedXid 0
CONTEXT: xlog redo commit: 2012-08-21 08:21:42.079655+04
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: remove KnownAssignedXid 1768508078
CONTEXT: xlog redo commit: 2012-08-21 08:21:42.079655+04
LOCATION: KnownAssignedXidsRemove, procarray.c:2869
DEBUG: 00000: record known xact 1768508080 latestObservedXid 0
CONTEXT: xlog redo exclusive_lock: xid 1768508080 rel 1663/16424/17282;
tid 725829/8
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508080 latestObservedXid 0
CONTEXT: xlog redo update: rel 1663/16424/17282; tid 725829/8; new 726017/7
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508076 latestObservedXid 0
CONTEXT: xlog redo exclusive_lock: xid 1768508076 rel 1663/16424/47760635;
tid 3075/136
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508080 latestObservedXid 0
CONTEXT: xlog redo insert: rel 1663/16424/47747; tid 43866/197
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508080 latestObservedXid 0
CONTEXT: xlog redo insert: rel 1663/16424/52546872; tid 44700/276
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508061 latestObservedXid 0
CONTEXT: xlog redo log: rel 1663/16424/19211
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508082 latestObservedXid 0
CONTEXT: xlog redo exclusive_lock: xid 1768508082 rel 1663/16424/4759107;
tid 1098/7
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508076 latestObservedXid 0
CONTEXT: xlog redo hot_update: rel 1663/16424/47760635; tid 3075/136; new
3075/140
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508080 latestObservedXid 0
CONTEXT: xlog redo exclusive_lock: xid 1768508080 rel 1663/16424/17282;
tid 725918/2
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508082 latestObservedXid 0
CONTEXT: xlog redo hot_update: rel 1663/16424/4759107; tid 1098/7; new
1098/39
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508080 latestObservedXid 0
CONTEXT: xlog redo update: rel 1663/16424/17282; tid 725918/2; new 725918/6
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508080 latestObservedXid 0
CONTEXT: xlog redo insert: rel 1663/16424/47747; tid 43866/201
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508080 latestObservedXid 0
CONTEXT: xlog redo insert: rel 1663/16424/52546872; tid 44700/276
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508080 latestObservedXid 0
CONTEXT: xlog redo commit: 2012-08-21 08:21:42.082508+04
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508080 latestObservedXid 0
CONTEXT: xlog redo commit: 2012-08-21 08:21:42.082508+04
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: remove KnownAssignedXid 1768508080
CONTEXT: xlog redo commit: 2012-08-21 08:21:42.082508+04
LOCATION: KnownAssignedXidsRemove, procarray.c:2869
DEBUG: 00000: record known xact 1768508061 latestObservedXid 0
CONTEXT: xlog redo insert: rel 1663/16424/64654; tid 178183/44
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508061 latestObservedXid 0
CONTEXT: xlog redo insert: rel 1663/16424/95419; tid 38650/318
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
DEBUG: 00000: record known xact 1768508061 latestObservedXid 0

CONTEXT: xlog redo create multixact 361788644 offset 822580965: 1768508061
1768508078
LOCATION: RecordKnownAssignedTransactionIds, procarray.c:2375
FATAL: XX000: could not access status of transaction 361788644
DETAIL: Could not read from file "pg_multixact/offsets/1590" at offset
114688: Unknown error: 0.
CONTEXT: xlog redo create multixact 361788644 offset 822580965: 1768508061
1768508078
LOCATION: SlruReportIOError, slru.c:840

DEBUG: 00000: shmem_exit(1): 5 callbacks to make

I have some problems with debug startup process with gdb...
I following next sequence of commands (and got no useful results):

[pgsql(at)db1 ~/tmp/postgresql-9.0.8]$ /usr/local/bin/gdb
/usr/local/bin/postgres
...
Reading symbols from /usr/local/bin/postgres...done.
(gdb) b exit
Breakpoint 1 at 0x44d38c
(gdb) run -D /db/data_back/
Starting program: /usr/local/bin/postgres -D /db/data_back/

Program received signal SIGUSR1, User defined signal 1.
0x00000008018ddadc in select () from /lib/libc.so.7
(gdb) bt
#0 0x00000008018ddadc in select () from /lib/libc.so.7
#1 0x000000000065641c in ServerLoop () at postmaster.c:1396
#2 0x0000000000655d05 in PostmasterMain (argc=3, argv=0x7fffffffead0) at
postmaster.c:1097
#3 0x00000000005d974a in main (argc=3, argv=0x7fffffffead0) at main.c:188
(gdb) cont
Continuing.

Breakpoint 1, 0x000000080186bab0 in exit () from /lib/libc.so.7
(gdb) bt
#0 0x000000080186bab0 in exit () from /lib/libc.so.7
#1 0x000000000067d0a6 in proc_exit (code=1) at ipc.c:137
#2 0x0000000000659933 in ExitPostmaster (status=1) at postmaster.c:4172
#3 0x0000000000657d2d in reaper (postgres_signal_arg=20) at
postmaster.c:2354
#4 <signal handler called>
#5 <signal handler called>
#6 0x00000008018ddadc in select () from /lib/libc.so.7
#7 0x000000000065641c in ServerLoop () at postmaster.c:1396
#8 0x0000000000655d05 in PostmasterMain (argc=3, argv=0x7fffffffead0) at
postmaster.c:1097
#9 0x00000000005d974a in main (argc=3, argv=0x7fffffffead0) at main.c:188
(gdb) cont
Continuing.
[Inferior 1 (process 98857) exited with code 01]
(gdb) quit