Re: recovery_target_time ignored or recovery always recovers to end of WAL

I now have a working xlogdump, which has allowed me to put together the
following steps which I believe demonstrate that the recovery process
insists on recovering to the most recent state.

Here is the sequence of events shown below:

1. Display contents of 'account_note' table
2. Update note field to be 'foobar'.
3. Dump trxnlog, note the new xid
4. Update note fied to be 'foobaz'.
5. Dump trxnlog, note the new xid
6. Update note field to be 'foobing'
7. Dump trxnlog, note the new xid
8. Create recovery.conf file with xid corresponding to 'foobar' update.
9. Stop/start database.
10. Display contents of 'account_note' table
11. Gasp in surpise at seeing 'note' field with value 'foobing'.
12. Expected to see original value 'foobar' (xid 696493, inclusive = true)
13. Scratch head in puzzlement.

altos_research=# select * from account_note;
account_note_id | customer_account_id | user_id_of_author |
creation_date | note
-----------------+---------------------+-------------------+---------------+-------------------------------
410805 | 410795 | 258460 |
2006-02-03 | Ratel Investments
441835 | 552 | 258459 |
2006-02-16 | testing new account note fix.
2540171 | 2540085 | 258460 |
2006-09-16 | requested to be removed
9999999 | 552 | 258460 |
2007-06-29 | help me
9999999 | 552 | 258460 |
2007-06-29 | help me
9999999 | 552 | 258460 |
2007-06-29 | help me
9999999 | 552 | 258460 |
2007-06-29 | help me
9999999 | 552 | 258460 |
2007-06-29 | help me

altos_research=# begin transaction; update account_note set note =
'foobar'; commit transaction;

##xlogdump of most recent file in pg_xlog:
xid: 695073 total length: 466 status: COMMITED
xid: 695081 total length: 131 status: COMMITED
xid: 695082 total length: 131 status: COMMITED
xid: 695083 total length: 131 status: COMMITED
xid: 695084 total length: 131 status: COMMITED
xid: 696493 total length: 1520 status: COMMITED - foobar trxn.

altos_research=# begin transaction; update account_note set note =
'foobaz'; commit transaction;

##xlogdump of most recent file in pg_xlog:
xid: 695073 total length: 466 status: COMMITED
xid: 695081 total length: 131 status: COMMITED
xid: 695082 total length: 131 status: COMMITED
xid: 695083 total length: 131 status: COMMITED
xid: 695084 total length: 131 status: COMMITED
xid: 696493 total length: 1520 status: COMMITED - foobar trxn.
xid: 696498 total length: 824 status: COMMITED - foobaz trxn

altos_research=# begin transaction; update account_note set note =
'foobing'; commit transaction;

##xlogdump of most recent file in pg_xlog:
xid: 695073 total length: 466 status: COMMITED
xid: 695081 total length: 131 status: COMMITED
xid: 695082 total length: 131 status: COMMITED
xid: 695083 total length: 131 status: COMMITED
xid: 695084 total length: 131 status: COMMITED
xid: 696493 total length: 1520 status: COMMITED - foobar trxn.
xid: 696498 total length: 824 status: COMMITED - foobaz trxn
xid: 696502 total length: 2672 status: COMMITED - foobing trxn

## created recovery.conf file:
recovery_target_xid = '696493'
restore_command = 'cp /pgdata/archive_logs/%f %p'
recovery_target_inclusive = 'true'

## stopped and started postgres, following syslog output:
Jul 2 20:51:10 localhost postgres-8.2[9125]: [3-1] LOG: starting
archive recovery
Jul 2 20:51:10 localhost postgres-8.2[9125]: [4-1] LOG:
recovery_target_xid = 696493
Jul 2 20:51:10 localhost postgres-8.2[9125]: [5-1] LOG:
restore_command = "cp /pgdata/archive_logs/%f %p"
Jul 2 20:51:10 localhost postgres-8.2[9125]: [6-1] LOG:
recovery_target_inclusive = true
Jul 2 20:51:10 localhost postgres-8.2[9125]: [7-1] LOG: checkpoint
record is at F/7E0DF258
Jul 2 20:51:10 localhost postgres-8.2[9125]: [8-1] LOG: redo record is
at F/7E0DF258; undo record is at 0/0; shutdown TRUE
Jul 2 20:51:10 localhost postgres-8.2[9125]: [9-1] LOG: next
transaction ID: 0/696512; next OID: 35828734
Jul 2 20:51:10 localhost postgres-8.2[9125]: [10-1] LOG: next
MultiXactId: 28; next MultiXactOffset: 55
Jul 2 20:51:10 localhost postgres-8.2[9125]: [11-1] LOG: automatic
recovery in progress
Jul 2 20:51:10 localhost postgres-8.2[9125]: [12-1] LOG: record with
zero length at F/7E0DF2A0
Jul 2 20:51:10 localhost postgres-8.2[9125]: [13-1] LOG: redo is not
required
Jul 2 20:51:10 localhost postgres-8.2[9125]: [14-1] LOG: archive
recovery complete
Jul 2 20:51:10 localhost postgres-8.2[9125]: [15-1] LOG: database
system is ready

altos_research=# select * from account_note;
account_note_id | customer_account_id | user_id_of_author |
creation_date | note
-----------------+---------------------+-------------------+---------------+-------------------------------
410805 | 410795 | 258460 |
2006-02-03 | Ratel Investments
441835 | 552 | 258459 |
2006-02-16 | testing new account note fix.
2540171 | 2540085 | 258460 |
2006-09-16 | requested to be removed
9999999 | 552 | 258460 |
2007-06-29 | help me
9999999 | 552 | 258460 |
2007-06-29 | help me
9999999 | 552 | 258460 |
2007-06-29 | help me
9999999 | 552 | 258460 |
2007-06-29 | help me
9999999 | 552 | 258460 |
2007-06-29 | help me

So now can someone tell me what I'm doing incorrectly :) ?

-jason

Simon Riggs wrote:
> On Mon, 2007-07-02 at 16:32 -0400, Tom Lane wrote:
>
>> "Simon Riggs" <simon(at)2ndquadrant(dot)com> writes:
>>
>>> On Mon, 2007-07-02 at 09:21 -0700, Jason L. Buberel wrote:
>>>
>>>> I downloaded the latest xlogdump source, and built/installed it against
>>>> my 8.2.4 source tree. When I execute it however, I am informed that all
>>>> of my WAL files (either the 'active' copies in pg_xlog or the 'archived'
>>>> copies in my /pgdata/archive_logs dir) appear to be malformed:
>>>> Bogus page magic number D05E at offset 0
>>>>
>>> For now, remove these lines from xlogdump.c, l.82-86
>>> if (((XLogPageHeader) pageBuffer)->xlp_magic != XLOG_PAGE_MAGIC)
>>>
>> I don't think that's a very good solution; the reason the magic number
>> changed is that some of the record formats changed. Jason needs a copy
>> that's actually appropriate to 8.2.
>>
>
> That was the hack for Jason, not the longterm solution. I've said I'll
> work on that once other core software is done.
>
>