Thread: Recovery from WAL archives not advancing timeline?
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'
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.
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
www.seiler.us
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 refuseto 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 expected00000002.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
2020年8月9日(日) 0:12 Don Seiler <don@seiler.us>: > > On Sat, Aug 8, 2020 at 9:14 AM Ian Lawrence Barwick <barwick@gmail.com> wrote: >> >> >> 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? > > > No. I when I first start the new replica, it shows: > > 2020-08-08 06:16:47.536 GMT [30368] LOG: database system was shut down at 2020-08-08 05:29:12 GMT > 2020-08-08 06:16:47.768 GMT [30379] [unknown]@[unknown] - [unknown] LOG: connection received: host=[local] > 2020-08-08 06:16:47.768 GMT [30379] postgres@postgres - [unknown] FATAL: the database system is starting up > 2020-08-08 06:16:47.769 GMT [30380] [unknown]@[unknown] - [unknown] LOG: connection received: host=[local] > 2020-08-08 06:16:47.769 GMT [30380] postgres@banno_login - [unknown] FATAL: the database system is starting up > 2020-08-08 06:16:47.849 GMT [30381] [unknown]@[unknown] - [unknown] LOG: connection received: host=[local] > 2020-08-08 06:16:47.849 GMT [30381] [unknown]@[unknown] - [unknown] LOG: incomplete startup packet > WARNING: 2020/08/08 06:16:47.857808 You are using deprecated functionality that uses an external gpg library. > It will be removed in next major version. > Please set GPG key using environment variables WALG_PGP_KEY or WALG_PGP_KEY_PATH. > ERROR: 2020/08/08 06:16:48.041147 openpgp: invalid argument: no armored data found > 2020-08-08 06:16:48.042 GMT [30368] LOG: entering standby mode > ERROR: 2020/08/08 06:16:48.423220 Archive '000000010000142E0000005B' does not exist. > 2020-08-08 06:16:48.428 GMT [30368] LOG: consistent recovery state reached at 142E/5B000098 > 2020-08-08 06:16:48.428 GMT [30368] LOG: invalid record length at 142E/5B000098: wanted 24, got 0 > 2020-08-08 06:16:48.429 GMT [30366] LOG: database system is ready to accept read only connections > > From there I see these messages repeated: > > ERROR: 2020/08/08 06:16:49.029836 Archive '000000010000142E0000005B' does not exist. > WARNING: 2020/08/08 06:16:49.510460 You are using deprecated functionality that uses an external gpg library. > It will be removed in next major version. > Please set GPG key using environment variables WALG_PGP_KEY or WALG_PGP_KEY_PATH. > ERROR: 2020/08/08 06:16:49.513288 openpgp: invalid argument: no armored data found > > There's no attempt to look for 00000002.history that I would normally expect when a replica doing WAL restore/recoveryruns 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"). (...) > There are WAL files in that new replica from when it was still the old primary, would those be causing confusion?: > > postgres:~/9.6/main/pg_xlog$ ls -lh > total 273M > -rw------- 1 postgres postgres 340 Aug 7 22:21 000000010000142C000000AD.00000028.backup > -rw------- 1 postgres postgres 16M Aug 8 05:24 000000010000142E00000055 > -rw------- 1 postgres postgres 16M Aug 8 05:25 000000010000142E00000056 > -rw------- 1 postgres postgres 16M Aug 8 05:26 000000010000142E00000057 > -rw------- 1 postgres postgres 16M Aug 8 05:27 000000010000142E00000058 > -rw------- 1 postgres postgres 16M Aug 8 05:28 000000010000142E00000059 > -rw------- 1 postgres postgres 16M Aug 8 05:29 000000010000142E0000005A > -rw------- 1 postgres postgres 16M Aug 8 05:29 000000010000142E0000005B > -rw------- 1 postgres postgres 16M Aug 8 05:16 000000010000142E0000005C > -rw------- 1 postgres postgres 16M Aug 8 05:15 000000010000142E0000005D > -rw------- 1 postgres postgres 16M Aug 8 05:18 000000010000142E0000005E > -rw------- 1 postgres postgres 16M Aug 8 05:14 000000010000142E0000005F > -rw------- 1 postgres postgres 16M Aug 8 05:17 000000010000142E00000060 > -rw------- 1 postgres postgres 16M Aug 8 05:19 000000010000142E00000061 > -rw------- 1 postgres postgres 16M Aug 8 05:22 000000010000142E00000062 > -rw------- 1 postgres postgres 16M Aug 8 05:21 000000010000142E00000063 > -rw------- 1 postgres postgres 16M Aug 8 05:20 000000010000142E00000064 > -rw------- 1 postgres postgres 16M Aug 8 05:23 000000010000142E00000065 From the timestamps, 000000010000142E0000005C and later are files which were "recycled" for future use and as such are perfectly normal. Regards Ian Barwick -- Ian Barwick https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
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
www.seiler.us
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
www.seiler.us
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:
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):
- Stop primary (A)
- Observe primary writes on final WAL file and it is archived
- Promote replica (B)
- Add recovery.conf to A for just WAL recovery and start.
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: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
www.seiler.us
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: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.
- Stop primary (A)
- Observe primary writes on final WAL file and it is archived
- Promote replica (B)
- Add recovery.conf to A for just WAL recovery and start.
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 archive2020-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 failure2020-08-08 19:13:48.105 UTC [17836] LOG: database system is shut downI 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
www.seiler.us
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.
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.
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.
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.
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/recoveryruns 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 stillshut 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
> 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 primarydoesn'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.