PITR potentially broken in 9.2

From: Jeff Janes <jeff(dot)janes(at)gmail(dot)com>
To: pgsql-bugs(at)postgresql(dot)org
Subject: PITR potentially broken in 9.2
Date: 2012-11-27 18:08:12
Message-ID: CAMkU=1wpvYJVEDo6Qvq4QbosZ+AV6BMVCf+XVCG=mJqFRjQ8Pg@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs pgsql-hackers

Doing PITR in 9.2.1, the system claims that it reached a consistent
recovery state immediately after redo starts.
This leads to it various mysterious failures, when it should instead
throw a "requested recovery stop point is before consistent recovery
point" error.
(If you are unlucky, I think it might even silently start up in a
corrupt state.)

This seems to have been introduced in:
commit 8366c7803ec3d0591cf2d1226fea1fee947d56c3
Author: Simon Riggs <simon(at)2ndQuadrant(dot)com>
Date: Wed Jan 25 18:02:04 2012 +0000

Allow pg_basebackup from standby node with safety checking.
Base backup follows recommended procedure, plus goes to great
lengths to ensure that partial page writes are avoided.

Jun Ishizuka and Fujii Masao, with minor modifications

the backup file:

START WAL LOCATION: 1/CD89E48 (file 00000001000000010000000C)
STOP WAL LOCATION: 1/1AFA11A0 (file 00000001000000010000001A)
CHECKPOINT LOCATION: 1/188D8120
BACKUP METHOD: pg_start_backup
BACKUP FROM: master
START TIME: 2012-11-27 09:40:13 PST
LABEL: label
STOP TIME: 2012-11-27 09:42:10 PST

(The file 00000001000000010000000C was archived at 9:37.)

recovery.conf:
restore_command = 'cp /tmp/archivedir/%f %p'
recovery_target_time = '2012-11-27 09:38:00 PST'

Log file:

22110 2012-11-27 09:49:15.220 PST LOG: database system was
interrupted; last known up at 2012-11-27 09:40:13 PST
22110 2012-11-27 09:49:15.235 PST LOG: starting point-in-time
recovery to 2012-11-27 09:38:00-08
22110 2012-11-27 09:49:15.271 PST LOG: restored log file
"000000010000000100000018" from archive
22110 2012-11-27 09:49:15.367 PST LOG: restored log file
"00000001000000010000000C" from archive
22110 2012-11-27 09:49:15.372 PST LOG: redo starts at 1/CD89E48
22110 2012-11-27 09:49:15.374 PST LOG: consistent recovery state
reached at 1/CD8B7F0
22110 2012-11-27 09:49:15.490 PST LOG: restored log file
"00000001000000010000000D" from archive
22110 2012-11-27 09:49:15.775 PST LOG: restored log file
"00000001000000010000000E" from archive
22110 2012-11-27 09:49:16.078 PST LOG: restored log file
"00000001000000010000000F" from archive
22110 2012-11-27 09:49:16.345 PST LOG: restored log file
"000000010000000100000010" from archive
22110 2012-11-27 09:49:16.533 PST LOG: recovery stopping before
commit of transaction 951967, time 2012-11-27 09:38:00.000689-08
22110 2012-11-27 09:49:16.533 PST LOG: redo done at 1/10F41900
22110 2012-11-27 09:49:16.533 PST LOG: last completed transaction
was at log time 2012-11-27 09:37:59.998496-08
22110 2012-11-27 09:49:16.537 PST LOG: selected new timeline ID: 2
22110 2012-11-27 09:49:16.584 PST LOG: archive recovery complete
22113 2012-11-27 09:49:16.599 PST LOG: checkpoint starting:
end-of-recovery immediate wait
22113 2012-11-27 09:49:17.815 PST LOG: checkpoint complete: wrote
8336 buffers (12.7%); 0 transaction log file(s) added, 0 removed, 0
recycled; write=0.097 s, sync=1.115 s, total=1.230 s; sync files=14,
longest=0.578 s, average=0.079 s
22110 2012-11-27 09:49:17.929 PST FATAL: could not access status of
transaction 1014015
22110 2012-11-27 09:49:17.929 PST DETAIL: Could not read from file
"pg_clog/0000" at offset 245760: Success.
22109 2012-11-27 09:49:17.932 PST LOG: startup process (PID 22110)
exited with exit code 1
22109 2012-11-27 09:49:17.932 PST LOG: terminating any other active
server processes

Cheers,

Jeff

Responses

Browse pgsql-bugs by date

  From Date Subject
Next Message tarvip 2012-11-27 19:52:09 BUG #7710: Xid epoch is not updated properly during checkpoint
Previous Message Tom Lane 2012-11-27 17:33:44 Re: BUG #7709: psql \copy csv terminates with \. in quoted region

Browse pgsql-hackers by date

  From Date Subject
Next Message Tom Lane 2012-11-27 18:45:08 Re: Bugs in CREATE/DROP INDEX CONCURRENTLY
Previous Message Andres Freund 2012-11-27 17:55:09 Re: Problem Observed in behavior of Create Index Concurrently and Hot Update