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@2ndquadrant.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