Re: Online base backup from the hot-standby

On 11-09-26 10:56 PM, Fujii Masao wrote:
>
> Looks weired. Though the WAL record starting from 0/6000298 was read
> successfully, then re-fetch of the same record fails at the end of recovery.
> One possible cause is the corruption of archived WAL file. What
> restore_command on the standby and archive_command on the master
> are you using? Could you confirm that there is no chance to overwrite
> archive WAL files in your environment?
>
> I tried to reproduce this problem several times, but I could not. Could
> you provide the test case which reproduces the problem?
>

This is the test procedure I'm trying today, I wasn't able to reproduce 
the crash.  What I was doing the other day was similar but I can't speak 
to unintentional differences.


I have my master server
data
port=5439
wal_level=hot_standby
archive_mode=on
archive_command='cp -i %p /usr/local/pgsql92git/archive/%f'
hot_standby=on

I then run
select pg_start_backup('foo');
$ rm -r ../data2
$ cp -r ../data ../data2
$ rm ../data2/postmaster.pid
select pg_stop_backup();
I edit data2/postgresql.conf so
port=5438
I commented out archive_mode and archive_command (or at least today I did)
recovery.conf is

standby_mode='on'
primary_conninfo='host=127.0.0.1 port=5439 user=ssinger dbname=test'
restore_command='cp /usr/local/pgsql92git/archive/%f %p'

I then start up the second cluster. On it I run

select pg_start_backup('1');
$ rm -r ../data3
$ rm -r ../archive2
$ cp -r ../data2 ../data3
$ cp ../data2/global/pg_control ../data3/global

select pg_stop_backup();
I edit ../data2/postgresql.conf
port=5437
archive_mode=on                                # (change requires restart)
archive_command='cp -i %p /usr/local/pgsql92git/archive2/%f'

recovery.conf is

standby_mode='on'
primary_conninfo='host=127.0.0.1 port=5439 user=ssinger dbname=test'
restore_command='cp /usr/local/pgsql92git/archive/%f %p'
trigger_file='/tmp/3'

$ postgres -D ../data3

The first time I did this postgres came up quickly.

$ touch /tmp/3

worked fine.

I then stopped data3
$ rm -r ../data3
on data 2 I run
pg_start_backup('1')
$ cp -r ../data2 ../data3
$ cp ../data2/global/pg_control ../data3/global
select pg_stop_backup() # on data2
$ rm ../data3/postmaster.pid
vi ../data3/postgresql.conf # same changes as above for data3
vi ../data3/recovery.conf # same as above for data 3
postgres -D ../data3

This time I got
./postgres -D ../data3
LOG:  database system was interrupted while in recovery at log time 
2011-09-27 22:04:17 GMT
HINT:  If this has occurred more than once some data might be corrupted 
and you might need to choose an earlier recovery target.
LOG:  entering standby mode
cp: cannot stat 
`/usr/local/pgsql92git/archive/00000001000000000000000C': No such file 
or directory
LOG:  redo starts at 0/C000020
LOG:  record with incorrect prev-link 0/9000058 at 0/C0000B0
cp: cannot stat 
`/usr/local/pgsql92git/archive/00000001000000000000000C': No such file 
or directory
LOG:  streaming replication successfully connected to primary
FATAL:  the database system is starting up
FATAL:  the database system is starting up
LOG:  consistent recovery state reached at 0/C0000E8
LOG:  database system is ready to accept read only connections

In order to get the database to come in read only mode I manually issued 
a checkpoint on the master (data) shortly after the checkpoint command 
the data3 instance went to read only mode.

then

touch /tmp/3

trigger file found: /tmp/3
FATAL:  terminating walreceiver process due to administrator command
cp: cannot stat 
`/usr/local/pgsql92git/archive/00000001000000000000000C': No such file 
or directory
LOG:  record with incorrect prev-link 0/9000298 at 0/C0002F0
cp: cannot stat 
`/usr/local/pgsql92git/archive/00000001000000000000000C': No such file 
or directory
LOG:  redo done at 0/C000298
cp: cannot stat 
`/usr/local/pgsql92git/archive/00000001000000000000000C': No such file 
or directory
cp: cannot stat `/usr/local/pgsql92git/archive/00000002.history': No 
such file or directory
LOG:  selected new timeline ID: 2
cp: cannot stat `/usr/local/pgsql92git/archive/00000001.history': No 
such file or directory
LOG:  archive recovery complete
LOG:  database system is ready to accept connections
LOG:  autovacuum launcher started


It looks like data3 is still pulling files with the recovery command 
after it sees the touch file (is this expected behaviour?)
$ grep archive ../data3/postgresql.conf
#wal_level = minimal            # minimal, archive, or hot_standby
#archive_mode = off        # allows archiving to be done
archive_mode=on
archive_command='cp -i %p /usr/local/pgsql92git/archive2/%f'


I have NOT been able to make postgres crash during a recovery (today).  
It is *possible* that on some of my runs the other day I had skipped 
changing the archive command on data3 to write to archive2 instead of 
archive.

I have also today not been able to get it to attempt to restore the same 
WAL file twice.


>> If a base backup is in progress on a recovery database and that recovery
>> database is promoted to master, following the promotion (if you don't
>> restart the postmaster).  I see
>> select pg_stop_backup();
>> ERROR:  database system status mismatches between pg_start_backup() and
>> pg_stop_backup()
>>
>> If you restart the postmaster this goes away.  When the postmaster leaves
>> recovery mode I think it should abort an existing base backup so
>> pg_stop_backup() will say no backup in progress,
> I don't think that it's good idea to cancel the backup when promoting
> the standby.
> Because if we do so, we need to handle correctly the case where cancel of backup
> and pg_start_backup/pg_stop_backup are performed at the same time. We can
> simply do that by protecting those whole operations including pg_start_backup's
> checkpoint by the lwlock. But I don't think that it's worth
> introducing new lwlock
> only for that. And it's not good to take a lwlock through
> time-consuming checkpoint
> operation. Of course we can avoid such a lwlock, but which would require more
> complicated code.
>
>> or give an error message on
>> pg_stop_backup() saying that the base backup won't be usable.  The above
>> error doesn't really tell the user why there is a mismatch.
> What about the following error message?
>
> ERROR:  pg_stop_backup() was executed during normal processing though
> pg_start_backup() was executed during recovery
> HINT:  The database backup will not be usable.
>
> Or, you have better idea?

I like that error message better.  It tells me what is going on versus 
complaining about a state mismatch.
>> In my testing a few times I got into a situation where a standby server
>> coming from a recovery target took a while to finish recovery (this is on a
>> database with no activity).  Then when i tried promoting that server to
>> master I got
>>
>> LOG:  trigger file found: /tmp/3
>> FATAL:  terminating walreceiver process due to administrator command
>> LOG:  restored log file "000000010000000000000009" from archive
>> LOG:  restored log file "000000010000000000000009" from archive
>> LOG:  redo done at 0/90000E8
>> LOG:  restored log file "000000010000000000000009" from archive
>> PANIC:  unexpected pageaddr 0/6000000 in log file 0, segment 9, offset 0
>> LOG:  startup process (PID 1804) was terminated by signal 6: Aborted
>> LOG:  terminating any other active server processes
>>
>> It is *possible* I mixed up the order of a step somewhere since my testing
>> isn't script based. A standby server that 'looks' okay but can't actually be
>> promoted is dangerous.
> Looks the same problem as the above. Another weired point is that
> the same archived WAL file is restored two times before redo is done.
> I'm not sure why this happens... Could you provide the test case which
> reproduces this problem? Will diagnose.
>
> Regards,
>