SEO

I am trying to learn/practice the administrative steps that would need
to be taken in a 'fat finger' scenario, and I am running into problems.
I am trying to use 'recovery.conf' to set the database state to about 15
minutes ago in order to recover from accidentally deleting important
data. However, each time I restart the database in recovery mode, it
seems to always return me to the state it was in when I shut it down,
ignoring my 'recovery_target_time' setting.

For example:

1. I have a production 8.2.4 database running with WAL archiving enabled.
2. Thinking I am logged into a development database I issue the commands:

start transaction;
delete from billing_info;
delete from customer_account;
commit;

3. I suddenly realize I was logged into the production database.
4. I fall out of my chair, then regain consciousness 10 minutes later.
5. I shutdown the database, and create a 'recovery.conf' file as follows:

# pretend that 2007-07-01 20:50:00 PDT was 15 minutes ago.
recovery_target_time = '2007-07-01 20:50:00 PDT'
restore_command = 'cp /pgdata/archive_logs/%f %p'
recovery_target_inclusive = 'false'

6. I start the database, and I see the following log messages:

LOG: starting archive recovery
LOG: recovery_target_time = 2007-07-01 20:50:00-07
LOG: restore_command = "cp /pgdata/archive_logs/%f %p"
LOG: recovery_target_inclusive = false
LOG: checkpoint record is at F/7E0DD5A4
LOG: redo record is at F/7E0DD5A4; undo record is at 0/0; shutdown TRUE
LOG: next transaction ID: 0/693577; next OID: 35828734
LOG: next MultiXactId: 28; next MultiXactOffset: 55
LOG: automatic recovery in progress
LOG: record with zero length at F/7E0DD5EC
LOG: redo is not required
LOG: archive recovery complete
LOG: database system is ready

7. I log back in to the database, expecting to see all of my
billing_info an customer_account records in place. But instead, the
tables are empty - just as they were when the db was shutdown.

What have I don't wrong? Or is there some other procedure to use in
these situations?

Thanks,
jason

---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

On Sun, 2007-07-01 at 21:41 -0700, Jason L. Buberel wrote:
> I am trying to learn/practice the administrative steps that would need
> to be taken in a 'fat finger' scenario, and I am running into problems.
> I am trying to use 'recovery.conf' to set the database state to about 15
> minutes ago in order to recover from accidentally deleting important
> data. However, each time I restart the database in recovery mode, it
> seems to always return me to the state it was in when I shut it down,
> ignoring my 'recovery_target_time' setting.
>
> For example:
>
> 1. I have a production 8.2.4 database running with WAL archiving enabled.
> 2. Thinking I am logged into a development database I issue the commands:
>
> start transaction;
> delete from billing_info;
> delete from customer_account;
> commit;
>
> 3. I suddenly realize I was logged into the production database.
> 4. I fall out of my chair, then regain consciousness 10 minutes later.
> 5. I shutdown the database, and create a 'recovery.conf' file as follows:
>
> # pretend that 2007-07-01 20:50:00 PDT was 15 minutes ago.
> recovery_target_time = '2007-07-01 20:50:00 PDT'
> restore_command = 'cp /pgdata/archive_logs/%f %p'
> recovery_target_inclusive = 'false'
>
> 6. I start the database, and I see the following log messages:
>
> LOG: starting archive recovery
> LOG: recovery_target_time = 2007-07-01 20:50:00-07
> LOG: restore_command = "cp /pgdata/archive_logs/%f %p"
> LOG: recovery_target_inclusive = false
> LOG: checkpoint record is at F/7E0DD5A4
> LOG: redo record is at F/7E0DD5A4; undo record is at 0/0; shutdown TRUE
> LOG: next transaction ID: 0/693577; next OID: 35828734
> LOG: next MultiXactId: 28; next MultiXactOffset: 55
> LOG: automatic recovery in progress
> LOG: record with zero length at F/7E0DD5EC
> LOG: redo is not required
> LOG: archive recovery complete
> LOG: database system is ready
>
> 7. I log back in to the database, expecting to see all of my
> billing_info an customer_account records in place. But instead, the
> tables are empty - just as they were when the db was shutdown.
>
> What have I don't wrong? Or is there some other procedure to use in
> these situations?

Your example transactions are so large that going back 15 minutes is not
enough. You'll need to go back further.

recovery_target_time can only stop on a COMMIT or ABORT record. This is
because it makes no sense to recover half a transaction, only whole
transactions have meaning for recovery. So if the transactions are very
large, you need to go back further.

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com



---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

Simon,

Thanks for the tip. I had assumed that so long as I set
'recovery_target_time' to a value that occurred before the 'fatal
commit' and set the 'inclusive' flag to false that I would be able to
return to just before the deletion occurred.

I'll play with it a bit more and see. I just want to know what to do in
the future should a real emergency like this occur.

Thanks,
jason

Simon Riggs wrote:
> On Sun, 2007-07-01 at 21:41 -0700, Jason L. Buberel wrote:
>
> Your example transactions are so large that going back 15 minutes is not
> enough. You'll need to go back further.
>
> recovery_target_time can only stop on a COMMIT or ABORT record. This is
> because it makes no sense to recover half a transaction, only whole
> transactions have meaning for recovery. So if the transactions are very
> large, you need to go back further.
>
>

---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

"Simon Riggs" <simon@2ndquadrant.com> writes:
> On Sun, 2007-07-01 at 21:41 -0700, Jason L. Buberel wrote:
>> I am trying to learn/practice the administrative steps that would need
>> to be taken in a 'fat finger' scenario, and I am running into problems.

> Your example transactions are so large that going back 15 minutes is not
> enough. You'll need to go back further.
> recovery_target_time can only stop on a COMMIT or ABORT record. This is
> because it makes no sense to recover half a transaction, only whole
> transactions have meaning for recovery. So if the transactions are very
> large, you need to go back further.

No, that doesn't explain it. As long as he set the stop time before the
commit of the unwanted transaction, it should do what he's expecting.
It might uselessly replay a lot of the actions of a long-running
transaction, but it will stop before the COMMIT xlog record when it
reaches it, and thus the transaction will not be committed.

What's actually happening according to the log output is that it's
running all the way to the end of WAL. I can't really think of an
explanation for that other than a mistake in choosing the stop time,
ie, it's later than the commit of the unwanted transaction. Or maybe
the WAL file is a stale copy that doesn't even contain the unwanted
commit?

Jason, if you can't figure it out you might grab xlogviewer
http://pgfoundry.org/projects/xlogviewer/
and see what it says the timestamps of the commit records in your WAL
files are.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

Harrumph -

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:

$ /opt/postgres-8.2.4/bin/xlogdump --port 54824 --host 127.0.0.1 --user
postgres ../../../archive_logs/*
.../../../archive_logs/000000010000000F0000007C:
Bogus page magic number D05E at offset 0
invalid record length at F/7C00001C
.../../../archive_logs/000000010000000F0000007C.00550700.backup:
Partial page of 241 bytes ignored
.../../../archive_logs/000000010000000F0000007D:
Bogus page magic number D05E at offset 0
invalid record length at F/7D00001C
.../../../archive_logs/000000010000000F0000007D.0006C01C.backup:
Partial page of 241 bytes ignored

Which does not help particularly much

I'll keep plugging away at this - perhaps my problem in setting the
database state to a PITR is related to timezones or timestamp formatting?

-jason

Tom Lane wrote:
> Jason, if you can't figure it out you might grab xlogviewer
> http://pgfoundry.org/projects/xlogviewer/
> and see what it says the timestamps of the commit records in your WAL
> files are.
>

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org/

Some more bits on this:

And playing with the date format does not seem to change the outcome
(the db is always recovered to the most current state). In this case, I
removed the timezone designation 'PDT' from my timestamp, and the db
properly figured out that it is running in GMT-7 (pacific) time (see
syslog ouptput below).

What worries me is the 'record with zero length', combined with my
issues (in previous email) with the xlogdump not finding the right magic
bits. Perhaps that (or problems related to it) are causing the recovery
process to ignore my PITR information leading it to simply recover the
database to the most recent state?

LOG: database system was shut down at 2007-07-02 10:12:06 PDT
LOG: starting archive recovery
LOG: recovery_target_time = 2007-06-29 00:00:00-07
LOG: restore_command = "cp /pgdata/archive_logs/%f %p"
LOG: recovery_target_inclusive = false
LOG: checkpoint record is at F/7E0DDA60
LOG: redo record is at F/7E0DDA60; undo record is at 0/0; shutdown TRUE
LOG: next transaction ID: 0/695227; next OID: 35828734
LOG: next MultiXactId: 28; next MultiXactOffset: 55
LOG: automatic recovery in progress
LOG: record with zero length at F/7E0DDAA8
LOG: redo is not required
LOG: archive recovery complete
LOG: database system is ready

-jason

Jason L. Buberel wrote:
> Harrumph -
>
> 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:
>
> $ /opt/postgres-8.2.4/bin/xlogdump --port 54824 --host 127.0.0.1
> --user postgres ../../../archive_logs/*
> ../../../archive_logs/000000010000000F0000007C:
> Bogus page magic number D05E at offset 0
> invalid record length at F/7C00001C
> ../../../archive_logs/000000010000000F0000007C.00550700.backup:
> Partial page of 241 bytes ignored
> ../../../archive_logs/000000010000000F0000007D:
> Bogus page magic number D05E at offset 0
> invalid record length at F/7D00001C
> ../../../archive_logs/000000010000000F0000007D.0006C01C.backup:
> Partial page of 241 bytes ignored
>
> Which does not help particularly much
>
> I'll keep plugging away at this - perhaps my problem in setting the
> database state to a PITR is related to timezones or timestamp formatting?
>
> -jason
>
> Tom Lane wrote:
>> Jason, if you can't figure it out you might grab xlogviewer
>> http://pgfoundry.org/projects/xlogviewer/
>> and see what it says the timestamps of the commit records in your WAL
>> files are.
>>
>
> ---------------------------(end of broadcast)---------------------------
> TIP 4: Have you searched our list archives?
>
> http://archives.postgresql.org/

---------------------------(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

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:
>
> $ /opt/postgres-8.2.4/bin/xlogdump --port 54824 --host 127.0.0.1 --user
> postgres ../../../archive_logs/*
> ../../../archive_logs/000000010000000F0000007C:
> Bogus page magic number D05E at offset 0
> invalid record length at F/7C00001C
> ../../../archive_logs/000000010000000F0000007C.00550700.backup:
> Partial page of 241 bytes ignored
> ../../../archive_logs/000000010000000F0000007D:
> Bogus page magic number D05E at offset 0
> invalid record length at F/7D00001C
> ../../../archive_logs/000000010000000F0000007D.0006C01C.backup:
> Partial page of 241 bytes ignored
>
> Which does not help particularly much
>
> I'll keep plugging away at this - perhaps my problem in setting the
> database state to a PITR is related to timezones or timestamp formatting?

For now, remove these lines from xlogdump.c, l.82-86
if (((XLogPageHeader) pageBuffer)->xlp_magic != XLOG_PAGE_MAGIC)
{
printf("Bogus page magic number %04X at offset %X\n",
((XLogPageHeader) pageBuffer)->xlp_magic, logPageOff);
}

The program is unfortunately release specific, which is not very useful
for you now. D05E is the correct magic number for 8.2.4.

I'll update that program once we have the main software done for 8.3. I
was hoping that Diogo would continue to support it.

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com



---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

On Mon, 2007-07-02 at 11:06 -0400, Tom Lane wrote:
> "Simon Riggs" <simon@2ndquadrant.com> writes:
> > On Sun, 2007-07-01 at 21:41 -0700, Jason L. Buberel wrote:
> >> I am trying to learn/practice the administrative steps that would need
> >> to be taken in a 'fat finger' scenario, and I am running into problems.
>
> > Your example transactions are so large that going back 15 minutes is not
> > enough. You'll need to go back further.
> > recovery_target_time can only stop on a COMMIT or ABORT record. This is
> > because it makes no sense to recover half a transaction, only whole
> > transactions have meaning for recovery. So if the transactions are very
> > large, you need to go back further.
>
> No, that doesn't explain it. As long as he set the stop time before the
> commit of the unwanted transaction, it should do what he's expecting.
> It might uselessly replay a lot of the actions of a long-running
> transaction, but it will stop before the COMMIT xlog record when it
> reaches it, and thus the transaction will not be committed.
>
> What's actually happening according to the log output is that it's
> running all the way to the end of WAL. I can't really think of an
> explanation for that other than a mistake in choosing the stop time,
> ie, it's later than the commit of the unwanted transaction. Or maybe
> the WAL file is a stale copy that doesn't even contain the unwanted
> commit?
>
> Jason, if you can't figure it out you might grab xlogviewer
> http://pgfoundry.org/projects/xlogviewer/
> and see what it says the timestamps of the commit records in your WAL
> files are.

There's a patch awaiting review that adds the time of the last committed
transaction into the LOG output. That should help in cases like this.

--
Simon Riggs
EnterpriseDB http://www.enterprisedb.com



---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

"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.

Howver there is something odd here, because the value of XLOG_PAGE_MAGIC
comes from src/include/access/xlog_internal.h and not from the text of
xlogdump.c itself. What it looks like to me is that Jason compiled it
against the wrong set of Postgres header files.

regards, tom lane

---------------------------(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

"Jason L. Buberel" <jason@buberel.org> writes:
> What worries me is the 'record with zero length',

That's just the normal way of detecting end of WAL.

regards, tom lane

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster