pg.ddx.io pgsql-admin@postgresql.org mailing list archive
help / color / mirror / Atom feedRecovery from WAL archives not advancing timeline?
12+ messages / 4 participants
[nested] [flat]
* Recovery from WAL archives not advancing timeline?
@ 2020-08-08 06:37 Don Seiler <don@seiler.us>
0 siblings, 1 reply; 12+ messages in thread
From: Don Seiler @ 2020-08-08 06:37 UTC (permalink / raw)
To: Pgsql-admin <pgsql-admin@lists.postgresql.org>
PostgreSQL 9.6
I shut down the primary and promoted the replica (timeline advanced from 1
to 2).
I then put a recovery.conf on the old primary so it would recover by WAL
restore (not streaming). However it seems to refuse to see the new
timeline. I do have recovery_target_timeline='latest', my full
recovery.conf looks like this:
standby_mode = 'on'
restore_command = 'envdir /etc/wal-g/environment /usr/local/bin/wal-g
wal-fetch %f %p'
recovery_target_timeline = 'latest'
However the new replica complains:
ERROR: 2020/08/08 06:28:34.876197 openpgp: invalid argument: no armored
data found
ERROR: 2020/08/08 06:28:39.621300 Archive '000000010000142E0000005B' does
not exist.
The new primary wrote that file but under timeline 2, I
see 000000020000142E0000005B in the archive, along with the
expected 00000002.history file.
So why doesn't the new replica see that there are no more TL1 WAL files and
advance to TL2? There are still some files in its pg_xlog dir on that
replica, would it be safe to shut it down and clear them out?
--
Don Seiler
www.seiler.us
^ permalink raw reply [nested|flat] 12+ messages in thread
* Re: Recovery from WAL archives not advancing timeline?
@ 2020-08-08 14:13 Ian Lawrence Barwick <barwick@gmail.com>
parent: Don Seiler <don@seiler.us>
0 siblings, 1 reply; 12+ messages in thread
From: Ian Lawrence Barwick @ 2020-08-08 14:13 UTC (permalink / raw)
To: Don Seiler <don@seiler.us>; +Cc: Pgsql-admin <pgsql-admin@lists.postgresql.org>
2020年8月8日(土) 15:37 Don Seiler <don@seiler.us>:
>
> PostgreSQL 9.6
>
> I shut down the primary and promoted the replica (timeline advanced from 1 to 2).
>
> I then put a recovery.conf on the old primary so it would recover by WAL restore (not streaming). However it seems to refuse to see the new timeline. I do have recovery_target_timeline='latest', my full recovery.conf looks like this:
>
> standby_mode = 'on'
> restore_command = 'envdir /etc/wal-g/environment /usr/local/bin/wal-g wal-fetch %f %p'
> recovery_target_timeline = 'latest'
>
> However the new replica complains:
> ERROR: 2020/08/08 06:28:34.876197 openpgp: invalid argument: no armored data found
> ERROR: 2020/08/08 06:28:39.621300 Archive '000000010000142E0000005B' does not exist.
>
> The new primary wrote that file but under timeline 2, I see 000000020000142E0000005B in the archive, along with the expected 00000002.history file.
After the failure to fetch the expected WAL file, the standby
(replica) should be
attempting to fetch the 00000002.history file; do you see any wal-g
error messages
about that?
Regards
Ian Barwick
--
Ian Barwick https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
^ permalink raw reply [nested|flat] 12+ messages in thread
* Re: Recovery from WAL archives not advancing timeline?
@ 2020-08-08 15:59 Don Seiler <don@seiler.us>
parent: Ian Lawrence Barwick <barwick@gmail.com>
0 siblings, 2 replies; 12+ messages in thread
From: Don Seiler @ 2020-08-08 15:59 UTC (permalink / raw)
To: Ian Lawrence Barwick <barwick@gmail.com>; +Cc: Pgsql-admin <pgsql-admin@lists.postgresql.org>
On Sat, Aug 8, 2020 at 10:34 AM Ian Lawrence Barwick <barwick@gmail.com>
wrote:
> 2020年8月9日(日) 0:12 Don Seiler <don@seiler.us>:
> >
> > There's no attempt to look for 00000002.history that I would normally
> expect when a replica doing WAL restore/recovery runs of out of files to
> restore.
>
> In that case are you
> a) absolutely sure recovery.conf contains "recovery_target_timeline =
> 'latest'"?
> b) the standby was restarted *after* the change was made?
>
> I ask because not attempting to fetch a history file would be a sign
> that "recovery_target_timeline"
> is not set (or set but not to "latest").
>
I'm 100% confident that it was set, as I did it via script that wrote the
recovery.conf to all while the DBs were still shut down. The file still has:
recovery_target_timeline = 'latest'
Can I set that parameter to a specific timeline (eg '2')? Or does it
just take 'latest'?
> From the timestamps, 000000010000142E0000005C and later are files
> which were "recycled"
> for future use and as such are perfectly normal.
>
Do you think it would be worth trying to delete (move/rename)
the 000000010000142E0000005B file and see if it changes things?
--
Don Seiler
www.seiler.us
^ permalink raw reply [nested|flat] 12+ messages in thread
* Re: Recovery from WAL archives not advancing timeline?
@ 2020-08-08 16:10 Don Seiler <don@seiler.us>
parent: Don Seiler <don@seiler.us>
1 sibling, 1 reply; 12+ messages in thread
From: Don Seiler @ 2020-08-08 16:10 UTC (permalink / raw)
To: Ian Lawrence Barwick <barwick@gmail.com>; +Cc: Pgsql-admin <pgsql-admin@lists.postgresql.org>
On Sat, Aug 8, 2020 at 10:59 AM Don Seiler <don@seiler.us> wrote:
>
> Do you think it would be worth trying to delete (move/rename)
> the 000000010000142E0000005B file and see if it changes things?
>
In my PG10 test cluster, I see a ".partial" file getting archived as well.
In this case I would expect to see a 000000010000142E0000005B.partial.lz4
file in the archive but I don't. Although my test cluster used streaming
replication where as this was done without streaming (just WAL
archive/restore/recovery), and this one is PG 9.6 (I have both 9.6 and 10
here). I'll re-run my tests without streaming and both 9.6 and 10.
Don.
--
Don Seiler
www.seiler.us
^ permalink raw reply [nested|flat] 12+ messages in thread
* Re: Recovery from WAL archives not advancing timeline?
@ 2020-08-08 19:24 Don Seiler <don@seiler.us>
parent: Don Seiler <don@seiler.us>
0 siblings, 1 reply; 12+ messages in thread
From: Don Seiler @ 2020-08-08 19:24 UTC (permalink / raw)
To: Ian Lawrence Barwick <barwick@gmail.com>; +Cc: Pgsql-admin <pgsql-admin@lists.postgresql.org>
On Sat, Aug 8, 2020 at 11:10 AM Don Seiler <don@seiler.us> wrote:
> On Sat, Aug 8, 2020 at 10:59 AM Don Seiler <don@seiler.us> wrote:
>
>>
>> Do you think it would be worth trying to delete (move/rename)
>> the 000000010000142E0000005B file and see if it changes things?
>>
>
> In my PG10 test cluster, I see a ".partial" file getting archived as well.
> In this case I would expect to see a 000000010000142E0000005B.partial.lz4
> file in the archive but I don't. Although my test cluster used streaming
> replication where as this was done without streaming (just WAL
> archive/restore/recovery), and this one is PG 9.6 (I have both 9.6 and 10
> here). I'll re-run my tests without streaming and both 9.6 and 10.
>
Doing some more testing and it seems to boil down to the fact that a
replica should create a .partial file when it is promoted. I tested both PG
9.6 and 10, with replicas streaming vs restoring WAL files. The sequence
was always this:
1. Stop primary (A)
2. Observe primary writes on final WAL file and it is archived
3. Promote replica (B)
4. Add recovery.conf to A for just WAL recovery and start.
In cases where the replica B was a streaming replica, upon promotion it
would create a .partial file in the old timeline and then a history file in
the new timeline and proceed. These files were then archived by wal-g and
the new replica (A) would recover them and continue replication.
If replica B was not streaming to begin with (so it was just restoring and
recovering WAL from archives), then upon promotion it would NOT create a
.partial file. It would just create the .history file and open up. When A
is then started in step 4, it would complain like this (in PG 9.6):
2020-08-08 19:13:43.337 UTC [17837] LOG: database system was shut down at
2020-08-08 19:09:24 UTC
2020-08-08 19:13:44.580 UTC [17837] LOG: restored log file
"00000002.history" from archive
ERROR: 2020/08/08 19:13:45.213175 Archive '00000003.history' does not exist.
2020-08-08 19:13:45.214 UTC [17837] LOG: entering standby mode
2020-08-08 19:13:45.676 UTC [17837] LOG: restored log file
"00000002.history" from archive
2020-08-08 19:13:46.327 UTC [17837] LOG: restored log file
"000000020000000000000006" from archive
2020-08-08 19:13:46.381 UTC [17837] LOG: invalid xl_info in primary
checkpoint record
2020-08-08 19:13:46.381 UTC [17837] PANIC: could not locate a valid
checkpoint record
2020-08-08 19:13:48.095 UTC [17836] LOG: startup process (PID 17837) was
terminated by signal 6: Aborted
2020-08-08 19:13:48.095 UTC [17836] LOG: aborting startup due to startup
process failure
2020-08-08 19:13:48.105 UTC [17836] LOG: database system is shut down
I even tested forcing an additional log switch from the new primary (which
is the example you see above) but it still doesn't jive.
I'm not sure if this is a bug or expected behavior with non-streaming
replicas but I believe it means that all of my old primaries need to be
restored from new backups as the new primaries were all
restore/recovery setup (due to VPN bandwidth limitations that made
streaming difficult). Unless someone has a way forward?
Don.
--
Don Seiler
www.seiler.us
^ permalink raw reply [nested|flat] 12+ messages in thread
* Re: Recovery from WAL archives not advancing timeline?
@ 2020-08-10 20:28 Don Seiler <don@seiler.us>
parent: Don Seiler <don@seiler.us>
0 siblings, 1 reply; 12+ messages in thread
From: Don Seiler @ 2020-08-10 20:28 UTC (permalink / raw)
To: Ian Lawrence Barwick <barwick@gmail.com>; +Cc: Pgsql-admin <pgsql-admin@lists.postgresql.org>
On Sat, Aug 8, 2020 at 2:24 PM Don Seiler <don@seiler.us> wrote:
>
> Doing some more testing and it seems to boil down to the fact that a
> replica should create a .partial file when it is promoted. I tested both PG
> 9.6 and 10, with replicas streaming vs restoring WAL files. The sequence
> was always this:
>
>
> 1. Stop primary (A)
> 2. Observe primary writes on final WAL file and it is archived
> 3. Promote replica (B)
> 4. Add recovery.conf to A for just WAL recovery and start.
>
> In cases where the replica B was a streaming replica, upon promotion it
> would create a .partial file in the old timeline and then a history file in
> the new timeline and proceed. These files were then archived by wal-g and
> the new replica (A) would recover them and continue replication.
>
> If replica B was not streaming to begin with (so it was just restoring and
> recovering WAL from archives), then upon promotion it would NOT create a
> .partial file. It would just create the .history file and open up. When A
> is then started in step 4, it would complain like this (in PG 9.6):
>
> 2020-08-08 19:13:43.337 UTC [17837] LOG: database system was shut down at
> 2020-08-08 19:09:24 UTC
>
> 2020-08-08 19:13:44.580 UTC [17837] LOG: restored log file
> "00000002.history" from archive
>
> ERROR: 2020/08/08 19:13:45.213175 Archive '00000003.history' does not
> exist.
> 2020-08-08 19:13:45.214 UTC [17837] LOG: entering standby mode
>
> 2020-08-08 19:13:45.676 UTC [17837] LOG: restored log file
> "00000002.history" from archive
> 2020-08-08 19:13:46.327 UTC [17837] LOG: restored log file
> "000000020000000000000006" from archive
>
> 2020-08-08 19:13:46.381 UTC [17837] LOG: invalid xl_info in primary
> checkpoint record
> 2020-08-08 19:13:46.381 UTC [17837] PANIC: could not locate a valid
> checkpoint record
>
> 2020-08-08 19:13:48.095 UTC [17836] LOG: startup process (PID 17837) was
> terminated by signal 6: Aborted
> 2020-08-08 19:13:48.095 UTC [17836] LOG: aborting startup due to startup
> process failure
> 2020-08-08 19:13:48.105 UTC [17836] LOG: database system is shut down
>
> I even tested forcing an additional log switch from the new primary (which
> is the example you see above) but it still doesn't jive.
>
> I'm not sure if this is a bug or expected behavior with non-streaming
> replicas but I believe it means that all of my old primaries need to be
> restored from new backups as the new primaries were all
> restore/recovery setup (due to VPN bandwidth limitations that made
> streaming difficult). Unless someone has a way forward?
>
I'm following up to see if anyone else would categorize this as a bug. It
renders my old primaries dead until I do a restore on them.
Don.
--
Don Seiler
www.seiler.us
^ permalink raw reply [nested|flat] 12+ messages in thread
* Re: Recovery from WAL archives not advancing timeline?
@ 2020-08-11 00:03 Rui DeSousa <rui@crazybean.net>
parent: Don Seiler <don@seiler.us>
0 siblings, 1 reply; 12+ messages in thread
From: Rui DeSousa @ 2020-08-11 00:03 UTC (permalink / raw)
To: Don Seiler <don@seiler.us>; +Cc: Ian Lawrence Barwick <barwick@gmail.com>; Pgsql-admin <pgsql-admin@lists.postgresql.org>
> On Aug 10, 2020, at 4:28 PM, Don Seiler <don@seiler.us> wrote:
>
> I'm following up to see if anyone else would categorize this as a bug. It renders my old primaries dead until I do a restore on them.
No, I don’t think so. When you promote a standby; the primary will have to be restored or rewinded using pg_rewind to turn it into a replica. Another approach is to cleanly shutdown the primary and then you can turn it into a replica without doing a restore or pg_rewind.
^ permalink raw reply [nested|flat] 12+ messages in thread
* Re: Recovery from WAL archives not advancing timeline?
@ 2020-08-11 00:23 Rui DeSousa <rui@crazybean.net>
parent: Rui DeSousa <rui@crazybean.net>
0 siblings, 1 reply; 12+ messages in thread
From: Rui DeSousa @ 2020-08-11 00:23 UTC (permalink / raw)
To: Don Seiler <don@seiler.us>; +Cc: Ian Lawrence Barwick <barwick@gmail.com>; Pgsql-admin <pgsql-admin@lists.postgresql.org>
> On Aug 10, 2020, at 8:03 PM, Rui DeSousa <rui@crazybean.net> wrote:
>
>
>
>> On Aug 10, 2020, at 4:28 PM, Don Seiler <don@seiler.us <mailto:don@seiler.us>> wrote:
>>
>> I'm following up to see if anyone else would categorize this as a bug. It renders my old primaries dead until I do a restore on them.
>
> No, I don’t think so. When you promote a standby; the primary will have to be restored or rewinded using pg_rewind to turn it into a replica. Another approach is to cleanly shutdown the primary and then you can turn it into a replica without doing a restore or pg_rewind.
>
Just to be clear if it wasn’t already self evident by my above statement: The primary needs to be clearly shutdown (all WALs archived), apply all WALs to replica, promote the replica and then the original primary can be turn into a replica without a restore or pg_rewind. =
^ permalink raw reply [nested|flat] 12+ messages in thread
* Re: Recovery from WAL archives not advancing timeline?
@ 2020-08-11 00:58 Don Seiler <don@seiler.us>
parent: Rui DeSousa <rui@crazybean.net>
0 siblings, 1 reply; 12+ messages in thread
From: Don Seiler @ 2020-08-11 00:58 UTC (permalink / raw)
To: Rui DeSousa <rui@crazybean.net>; +Cc: Ian Lawrence Barwick <barwick@gmail.com>; Pgsql-admin <pgsql-admin@lists.postgresql.org>
On Mon, Aug 10, 2020 at 7:23 PM Rui DeSousa <rui@crazybean.net> wrote:
>
>
> On Aug 10, 2020, at 8:03 PM, Rui DeSousa <rui@crazybean.net> wrote:
>
>
>
> On Aug 10, 2020, at 4:28 PM, Don Seiler <don@seiler.us> wrote:
>
> I'm following up to see if anyone else would categorize this as a bug. It
> renders my old primaries dead until I do a restore on them.
>
>
> No, I don’t think so. When you promote a standby; the primary will have
> to be restored or rewinded using pg_rewind to turn it into a replica.
> Another approach is to cleanly shutdown the primary and then you can turn
> it into a replica without doing a restore or pg_rewind.
>
>
> Just to be clear if it wasn’t already self evident by my above statement:
> The primary needs to be clearly shutdown (all WALs archived), apply all
> WALs to replica, promote the replica and then the original primary can be
> turn into a replica without a restore or pg_rewind.
>
But that was the process that I did. I cleanly shutdown the primary first.
The primary write one last WAL file as part of its shutdown. That WAL file
was archived and then restored and recovered on the replica. The replica
was them promoted.
This process was the same for both streaming and non-streaming replication.
However only the streaming replica wrote a .partial WAL file on promotion
(which was then archived and used by the former primary to start recovery).
The former primary doesn't even try to follow the timeline change in the
non-streaming scenario.
Don.
--
Don Seiler
www.seiler.us
^ permalink raw reply [nested|flat] 12+ messages in thread
* Re: Recovery from WAL archives not advancing timeline?
@ 2020-08-11 01:08 Ian Barwick <ian.barwick@2ndquadrant.com>
parent: Don Seiler <don@seiler.us>
1 sibling, 0 replies; 12+ messages in thread
From: Ian Barwick @ 2020-08-11 01:08 UTC (permalink / raw)
To: Don Seiler <don@seiler.us>; +Cc: Ian Lawrence Barwick <barwick@gmail.com>; Pgsql-admin <pgsql-admin@lists.postgresql.org>
On 2020/08/09 0:59, Don Seiler wrote:
> On Sat, Aug 8, 2020 at 10:34 AM Ian Lawrence Barwick <barwick@gmail.com <mailto:barwick@gmail.com>> wrote:
>
> 2020年8月9日(日) 0:12 Don Seiler <don@seiler.us <mailto:don@seiler.us>>:
> >
> > There's no attempt to look for 00000002.history that I would normally expect when a replica doing WAL restore/recovery runs of out of files to restore.
>
> In that case are you
> a) absolutely sure recovery.conf contains "recovery_target_timeline = 'latest'"?
> b) the standby was restarted *after* the change was made?
>
> I ask because not attempting to fetch a history file would be a sign
> that "recovery_target_timeline"
> is not set (or set but not to "latest").
>
>
> I'm 100% confident that it was set, as I did it via script that wrote the recovery.conf to all while the DBs were still shut down. The file still has:
>
> recovery_target_timeline = 'latest'
Unfortunately it's not practical to verify what setting the server has in Pg11
and earlier. Is restarting the server an option? I'm sure I'm not the only person who's
been in a situation where I'm sure I've done something and it turns out I hadn't.
The code path there should definitely attempt to fetch a history file if
"recovery_target_timeline = 'latest'", so it would be useful rule out the
possibility that the setting simply hasn't been applied before looking into
other potential causes.
> Can I set that parameter to a specific timeline (eg '2')? Or does it just take 'latest'?
Yes, you can explicitly specify the timeline, though as changing it would require a
server restart, I suggest restarting the server as-is to double-check whether
the "recovery_target_timeline = 'latest'" is being applied, and only if not
try setting it to "recovery_target_timeline = 2".
> From the timestamps, 000000010000142E0000005C and later are files
> which were "recycled"
> for future use and as such are perfectly normal.
> Do you think it would be worth trying to delete (move/rename) the 000000010000142E0000005B file and see if it changes things?
It probably wouldn't do any harm in this case, but in general nothing good
ever came of speculatively moving/deleting files in the WAL directory.
Regards
Ian Barwick
--
Ian Barwick https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
^ permalink raw reply [nested|flat] 12+ messages in thread
* Re: Recovery from WAL archives not advancing timeline?
@ 2020-08-11 01:30 Rui DeSousa <rui@crazybean.net>
parent: Don Seiler <don@seiler.us>
0 siblings, 0 replies; 12+ messages in thread
From: Rui DeSousa @ 2020-08-11 01:30 UTC (permalink / raw)
To: Don Seiler <don@seiler.us>; +Cc: Ian Lawrence Barwick <barwick@gmail.com>; Pgsql-admin <pgsql-admin@lists.postgresql.org>
> On Aug 10, 2020, at 8:58 PM, Don Seiler <don@seiler.us> wrote:
> This process was the same for both streaming and non-streaming replication. However only the streaming replica wrote a .partial WAL file on promotion (which was then archived and used by the former primary to start recovery). The former primary doesn't even try to follow the timeline change in the non-streaming scenario.
>
It would not create a partial WAL as it was not streaming thus is no partial data to archive.
^ permalink raw reply [nested|flat] 12+ messages in thread
end of thread, other threads:[~2020-08-11 01:30 UTC | newest]
Thread overview: 12+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2020-08-08 06:37 Recovery from WAL archives not advancing timeline? Don Seiler <don@seiler.us>
2020-08-08 14:13 ` Ian Lawrence Barwick <barwick@gmail.com>
2020-08-08 15:59 ` Don Seiler <don@seiler.us>
2020-08-08 16:10 ` Don Seiler <don@seiler.us>
2020-08-08 19:24 ` Don Seiler <don@seiler.us>
2020-08-10 20:28 ` Don Seiler <don@seiler.us>
2020-08-11 00:03 ` Rui DeSousa <rui@crazybean.net>
2020-08-11 00:23 ` Rui DeSousa <rui@crazybean.net>
2020-08-11 00:58 ` Don Seiler <don@seiler.us>
2020-08-11 01:30 ` Rui DeSousa <rui@crazybean.net>
2020-08-11 01:08 ` Ian Barwick <ian.barwick@2ndquadrant.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox