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

Minor correction to the output below - the final table dump actually
contained the following - my apologies for the copy/paste error:

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 | foobing
441835 | 552 | 258459 |
2006-02-16 | foobing
2540171 | 2540085 | 258460 |
2006-09-16 | foobing
9999999 | 552 | 258460 |
2007-06-29 | foobing
9999999 | 552 | 258460 |
2007-06-29 | foobing
9999999 | 552 | 258460 |
2007-06-29 | foobing
9999999 | 552 | 258460 |
2007-06-29 | foobing
9999999 | 552 | 258460 |
2007-06-29 | foobing

Which is the most recent transaction update.

-jason

Jason L. Buberel wrote:
> 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.
>>
>>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 9: In versions below 8.0, the planner will ignore your desire to
> choose an index scan if your joining column's datatypes do not
> match