Thread: BUG #13644: 2xRecovery without new writes, causes archiving failure
The following bug has been logged on the website: Bug reference: 13644 Logged by: Amir Rohan Email address: amir.rohan@mail.com PostgreSQL version: 9.5alpha2 Operating system: Linux Description: Summary: recovering from backup, when the archive directory is shared between primary/new primary/newnew primary, each shutting down before the next is started, causes the last primary to fail during archiving, because it tries to overwrite existing files. Walkthrough: 1. create a server, with wal_level=archive and archive_command copying files to ARCHIVE_DIR 2. load some data 3. create a tar backup with pg_basebackup --format=t -x 4. shut down server with `pg_ctl stop` 5. delete the PGDATA directory, and replace it by untarring the backup file place a recovery.conf with only "recovery_target_timeline='latest'" and a restore_command set to copy from ARCHIVE_DIR. 6. use the same postgresql.conf file, archiving to ARCHIVE_DIR again. 7. start the server, recovery completes. 8. a new timeline is created: # ls -l archive/ -rw-------. 1 postgres postgres 16777216 Sep 26 06:07 /var/lib/pgsql/archive/000000010000000000000001 -rw-------. 1 postgres postgres 16777216 Sep 26 06:07 /var/lib/pgsql/archive/000000010000000000000002 -rw-------. 1 postgres postgres 302 Sep 26 06:07 /var/lib/pgsql/archive/000000010000000000000002.00000028.backup -rw-------. 1 postgres postgres 41 Sep 26 06:07 /var/lib/pgsql/archive/00000002.history 8. without writing any data, shut down the server and repeat 5-7 9. no new timeline appears in ARCHIVE_DIR: # ls -l archive/ -rw-------. 1 postgres postgres 16777216 Sep 26 06:10 000000010000000000000001 -rw-------. 1 postgres postgres 16777216 Sep 26 06:10 000000010000000000000002 -rw-------. 1 postgres postgres 302 Sep 26 06:10 000000010000000000000002.00000028.backup -rw-------. 1 postgres postgres 16777216 Sep 26 06:10 000000020000000000000002 -rw-------. 1 postgres postgres 16777216 Sep 26 06:10 000000020000000000000003 -rw-------. 1 postgres postgres 41 Sep 26 06:10 00000002.history and the log fills up with: DETAIL: The failed archive command was: test ! -f /var/lib/pgsql/archive/00000002.history && cp pg_xlog/00000002.history /var/lib/pgsql/archive/00000002.history I expected the last server to create timeline 3, but it looks as if it thinks it's timeline2. While in terms of data it's at the same WAL point, in terms of events, it should be at timeline 3. That's what I make of it anyway. I happen to be testing with 9.5, but I have no reason to think this is particular to it. Amir
On Sat, Sep 26, 2015 at 12:22 PM, Amir Rohan wrote: > DETAIL: The failed archive command was: test ! -f > /var/lib/pgsql/archive/00000002.history && cp pg_xlog/00000002.history > /var/lib/pgsql/archive/00000002.history That's a symptom that the second node already selected timeline 2, my first guess is that the restore_command for the second node recovered failed to get 00000002.history because it may have been set incorrectly. > I expected the last server to create timeline 3, but it looks as if it > thinks it's timeline2. While in terms of data it's at the same WAL point, > in terms of events, it should be at timeline 3. That's what I make > of it anyway. I am not able to see any problems with neither 9.5 nor HEAD, when recovering the second node in your scenario, it fetches correctly 00000002.history from the archive in my case and the node is able to select the timeline 3 when recovery is pointing to select the latest timeline. -- Michael
On 09/26/2015 02:39 PM, Michael Paquier wrote: > On Sat, Sep 26, 2015 at 12:22 PM, Amir Rohan wrote: >> DETAIL: The failed archive command was: test ! -f >> /var/lib/pgsql/archive/00000002.history && cp pg_xlog/00000002.history >> /var/lib/pgsql/archive/00000002.history > > That's a symptom that the second node already selected timeline 2, my > first guess is that the restore_command for the second node recovered > failed to get 00000002.history because it may have been set > incorrectly. > I guess you mean the 3rd node here, which is the 2nd recovery. You seem to agree that the 3rd node (2nd recovery) picked timeline 2 instead of starting a 3rd. So, at least I have that right. What does "Set incorrectly" mean in this case? the 2nd node (1st recovery) creates 00000002.history, I checked. >> I expected the last server to create timeline 3, but it looks as if it >> thinks it's timeline2. While in terms of data it's at the same WAL point, >> in terms of events, it should be at timeline 3. That's what I make >> of it anyway. > > I am not able to see any problems with neither 9.5 nor HEAD, when > recovering the second node in your scenario, it fetches correctly > 00000002.history from the archive in my case and the node is able to > select the timeline 3 when recovery is pointing to select the latest > timeline. > I can reproduced this 100% of the time with HEAD from the last few days, and haven't tried with anything else. See attached log+shell-script I used to reproduce. The log shows the contents of the archive directory at various points in the process I described in the initial post. Amir
Attachment
On Sun, Sep 27, 2015 at 6:03 AM, Amir Rohan wrote: > On 09/26/2015 02:39 PM, Michael Paquier wrote: > I can reproduced this 100% of the time with HEAD from the last few days, > and haven't tried with anything else. > > See attached log+shell-script I used to reproduce. > The log shows the contents of the archive directory at various points > in the process I described in the initial post. If there is a bug, that's in your script, not in the backend code. restore_command should point to ARCHIVE_DIR instead of BACKUP_DIR. That's the reason why the third node (2nd recovery) cannot switch to timeline 3: it cannot find the history file of timeline 2 properly. -- Michael
On 09/28/2015 10:14 AM, Michael Paquier wrote: > On Sun, Sep 27, 2015 at 6:03 AM, Amir Rohan wrote: >> On 09/26/2015 02:39 PM, Michael Paquier wrote: >> I can reproduced this 100% of the time with HEAD from the last few days, >> and haven't tried with anything else. >> >> See attached log+shell-script I used to reproduce. >> The log shows the contents of the archive directory at various points >> in the process I described in the initial post. > > If there is a bug, that's in your script, not in the backend code. > restore_command should point to ARCHIVE_DIR instead of BACKUP_DIR. > That's the reason why the third node (2nd recovery) cannot switch to > timeline 3: it cannot find the history file of timeline 2 properly. > Of course! I'm embarrassed to have missed that, thank you.