Обсуждение: PostgreSQL archiving last replayed WAL after recovery

Hello,


I'm wondering about PostgreSQL always archiving the last replayed WAL
after getting out of recovery. This does not seem to be documented
anywhere, and this part of code is quite tricky to understand.
IMHO, PostgreSQL should not try to archive again WAL files coming from
the restore_command.
Is this a wanted behaviour ?

It's quite easy to reproduce by making a pg_basebackup of a test cluster
and configuring the second cluster in recovery mode. In my example, I
didn't produce some activity to add some WAL between the hotbackup and
the recovery, but PostgreSQL is only trying to archive the last replayed
WAL. Test is done with 9.2.4.

Here's the log file of the recovered cluster :
LOG:  database system was interrupted; last known up at 2013-04-22
11:17:33 CEST
LOG:  creating missing WAL directory "pg_xlog/archive_status"
LOG:  starting archive recovery
LOG:  restored log file "000000010000000000000036" from archive
LOG:  redo starts at 0/36000020
LOG:  consistent recovery state reached at 0/360000E0
LOG:  database system is ready to accept read only connections
cp: impossible d'?valuer
<</home/thomas/postgresql/v92/archives/000000010000000000000037>>: Aucun
fichier ou dossier de ce type
LOG:  could not open file "pg_xlog/000000010000000000000037" (log file
0, segment 55): Aucun fichier ou dossier de ce type
LOG:  redo done at 0/360000E0
LOG:  restored log file "000000010000000000000036" from archive
cp: impossible d'?valuer
<</home/thomas/postgresql/v92/archives/00000002.history>>: Aucun fichier
ou dossier de ce type
LOG:  selected new timeline ID: 2
cp: impossible d'?valuer
<</home/thomas/postgresql/v92/archives/00000001.history>>: Aucun fichier
ou dossier de ce type
LOG:  archive recovery complete
LOG:  checkpoint starting: end-of-recovery immediate wait
LOG:  checkpoint complete: wrote 0 buffers (0.0%); 0 transaction log
file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.000 s,
total=0.329 s; sync files=0, longest=0.000 s, average=0.000 s
LOG:  database system is ready to accept connections
LOG:  autovacuum launcher started
-- WAL 000000010000000000000036 archived --
-- WAL 00000002.history archived --
LOG:  received smart shutdown request
LOG:  autovacuum launcher shutting down
LOG:  shutting down
-- WAL 000000020000000000000037 archived --

Btw, my archive_command was archive_command = 'cp -i %p
/home/thomas/postgresql/v92/archives2/%f </dev/null && echo "-- WAL %f
archived --"', thus the "-- WAL ... archived --" messages.

Also, the archives2 directory contains the following files - the
directory was empty before :
thomas@laptop:~/postgresql/v92/archives2$ ls
000000010000000000000036  00000002.history  000000020000000000000037

Also, I wonder why the message "restored log file
"000000010000000000000036" from archive" appears two time during the
recovery. Is this WAL really replayed twice ?


Thanks,
Thomas

I'm having the same problem. In my case, and as recommended in the official documentation, my archive command checks that the file exists first, before archiving it:

archive_command = 'test ! -f /ORA/dbs02/PGTEST/archive/%f && cp %p /ORA/dbs02/PGTEST/archive/%f'

After a successful recovery, the last WAL file replayed from the base archive is still in the pg_xlog directory, so when it tries to archive it, it fails:

LOG:  database system was interrupted; last known up at 2013-07-02 14:53:37 CEST
LOG:  creating missing WAL directory "pg_xlog/archive_status"
LOG:  starting point-in-time recovery to 2013-07-02 15:20:12+02
LOG:  restored log file "000000010000000000000002" from archive
LOG:  redo starts at 0/2000020
LOG:  consistent recovery state reached at 0/20023D0
LOG:  restored log file "000000010000000000000003" from archive
LOG:  recovery stopping before commit of transaction 4063, time 2013-07-02 15:20:12.211559+02
LOG:  redo done at 0/306D8B8
LOG:  last completed transaction was at log time 2013-07-02 15:20:11.189978+02
cp: cannot stat `/ORA/dbs02/PGTEST/archive/00000002.history': No such file or directory
LOG:  selected new timeline ID: 2
cp: cannot stat `/ORA/dbs02/PGTEST/archive/00000001.history': No such file or directory
LOG:  archive recovery complete
LOG:  autovacuum launcher started
LOG:  database system is ready to accept connections
LOG:  archive command failed with exit code 1
DETAIL:  The failed archive command was: test ! -f /ORA/dbs02/PGTEST/archive/000000010000000000000003 && cp pg_xlog/000000010000000000000003 /ORA/dbs02/PGTEST/archive/000000010000000000000003
LOG:  archive command failed with exit code 1
DETAIL:  The failed archive command was: test ! -f /ORA/dbs02/PGTEST/archive/000000010000000000000003 && cp pg_xlog/000000010000000000000003 /ORA/dbs02/PGTEST/archive/000000010000000000000003
LOG:  archive command failed with exit code 1
DETAIL:  The failed archive command was: test ! -f /ORA/dbs02/PGTEST/archive/000000010000000000000003 && cp pg_xlog/000000010000000000000003 /ORA/dbs02/PGTEST/archive/000000010000000000000003
WARNING:  transaction log file "000000010000000000000003" could not be archived: too many failures

Is this a expected behaviour? Or should the px_log directory be cleaned-up again on recovery_end_command ? Cheers

---

View this message in context: Re: PostgreSQL archiving last replayed WAL after recovery
Sent from the PostgreSQL - general mailing list archive at Nabble.com.