0

I have a 2 node postresql(12.9) cluster with streaming replication enabled. I have also set the archive and restore commands which I verified is working as expected. No replication slots or wal_keep_segments configured.

archive_command ='test ! -f /archive_location/%f && cp %p /archive_location/%f'
restore_command = 'cp /archive_location/%f %p'

In this setup, I notice that if the standby disconnects after receiving a partial WAL file and if the same WAL gets archived and recycled from pg_wal on the primary node, then on reconnection, this standby never catches up with primary.

The error seen on standby is - ERROR:  requested WAL segment 0000000100000000000000XX has already been removed.

Debugging revealed the following -

1- Issue only seen when partial WAL file written on standby at time of disconnection. Since streaming replication is enabled, postgres doesn't wait for the 16MB WAL segment to fill up before shipping WAL to standby. So there could be partially written WAL on standby at any point. Confirmed by file compare of same WAL on primary and standby -

cmp 0000000100000000000000XX /tmp/0000000100000000000000XX
0000000100000000000000XX /tmp/0000000100000000000000XX differ: byte 15722105, line 68077

On reconnection, postgres first tries restoring WAL from archive but on failure, falls on streaming the same WAL from publisher over TCP connection. Since wal_keep_segments is not set, this WAL is recycled from pg_wal on publisher and standby is now stuck in this loop

628ed196.bd8bf 0DEBUG:  00000: switched WAL source from stream to archive after failure
2
628ed196.bd8bf 0DEBUG:  00000: record with incorrect prev-link 1/FDFF2008 at 0/EDEFE678
2022-05-26 06:32:19 IST   776383 628ed196.bd8bf 0LOCATION:  ReadRecord, xlog.c:4348
2022-05-26 06:32:19 IST   776383 628ed196.bd8bf 0DEBUG:  00000: switched WAL source from archive to stream after failure
2022-05-26 06:32:19 IST   776629 628ed19b.bd9b5 0FATAL:  XX000: could not receive data from WAL stream: ERROR:  requested WAL segment 0000000100000000000000XX has already been removed

Given this info looks like wal_keep_segments is needed even when archive + restore is set for streaming replication. Is this true? Am I missing something?

Edit - Adding necessary log info here for improved readability -

628ed196.bd8bf 0DEBUG:  00000: switched WAL source from stream to archive after failure
2022-05-26 06:32:19 IST   776383 628ed196.bd8bf 0LOCATION:  WaitForWALToBecomeAvailable, xlog.c:12208
2022-05-26 06:32:19 IST   776383 628ed196.bd8bf 0DEBUG:  00000: record with incorrect prev-link 1/FDFF2008 at 0/EDEFE678
2022-05-26 06:32:19 IST   776383 628ed196.bd8bf 0LOCATION:  ReadRecord, xlog.c:4348 2022-05-26 06:32:19 IST   776383 628ed196.bd8bf 0DEBUG:  00000: switched WAL source from archive to stream after failure
2022-05-26 06:32:19 IST   776381 628ed196.bd8bd 0LOCATION:  LogChildExit, postmaster.c:3697
2022-05-26 06:32:19 IST   776629 628ed19b.bd9b5 0LOG:  00000: started streaming WAL from primary at 0/ED000000 on timeline 1
2022-05-26 06:32:19 IST   776629 628ed19b.bd9b5 0LOCATION:  WalReceiverMain, walreceiver.c:372 2022-05-26 06:32:19 IST   776629 628ed19b.bd9b5 0FATAL:  XX000: could not receive data from WAL stream: ERROR:  requested WAL segment 0000000100000000000000ED has already been removed
Improve this question
8
  • The current release of 12 is 12.11, which contains a bugfix which might be relevant to this.
    – jjanes
    May 26, 2022 at 14:47
  • Can you reproduce this at will by setting up new master and replica, or is it just a one time occurrence? Can you go back farther in the log file to see why did it "switched WAL source from stream to archive" in the first place?
    – jjanes
    May 26, 2022 at 15:11
  • I am able to reproduce this as follows - 1. Have a series of writes on primary and wait for WAL to be shipped to standby. On Standby verify the WAL file(say X) is not filled to 16 MB segment limit and now disconnect standby. 2. Continue writes on publisher till the WAL file X is recycled from pg_wal directory. 3. Reconnect standby. At this point standby errors on restoring WAL file X from archive - error seen - incorrect prev-link then falls on streaming same WAL file from primary
    – maquebex
    May 27, 2022 at 0:45
  • From log dump - 628ed196.bd8bf 0DEBUG:  00000: switched WAL source from stream to archive after failure 2022-05-26 06:32:19 IST   776383 628ed196.bd8bf 0LOCATION:  WaitForWALToBecomeAvailable, xlog.c:12208 2022-05-26 06:32:19 IST   776383 628ed196.bd8bf 0DEBUG:  00000: record with incorrect prev-link 1/FDFF2008 at 0/EDEFE678 2022-05-26 06:32:19 IST   776383 628ed196.bd8bf 0LOCATION:  ReadRecord, xlog.c:4348 2022-05-26 06:32:19 IST   776383 628ed196.bd8bf 0DEBUG:  00000: switched WAL source from archive to stream after failure
    – maquebex
    May 27, 2022 at 1:00
  • 2022-05-26 06:32:19 IST   776381 628ed196.bd8bd 0LOCATION:  LogChildExit, postmaster.c:3697 2022-05-26 06:32:19 IST   776629 628ed19b.bd9b5 0LOG:  00000: started streaming WAL from primary at 0/ED000000 on timeline 1 2022-05-26 06:32:19 IST   776629 628ed19b.bd9b5 0LOCATION:  WalReceiverMain, walreceiver.c:372 2022-05-26 06:32:19 IST   776629 628ed19b.bd9b5 0FATAL:  XX000: could not receive data from WAL stream: ERROR:  requested WAL segment 0000000100000000000000ED has already been removed
    – maquebex
    May 27, 2022 at 1:01

1 Answer 1

Reset to default
0

No, if you have restore_command defined properly on the standby server, you don't need wal_keep_segments (wal_keep_size in later versions) on the primary.

If you define restore_command on the standby, it will restore the WAL segment from there. You say that the WAL segment gets archived and recycled on the primary, so the standby must be able to get it from there.

The standby should try to fetch the WAL segment from archive, even if it already has a partially filled local WAL segment with the same name. I would consider anything else a bug.

Are you sure that restore_command is set on the standby? Don't you get any messages about "restoring WAL segment from archive"?

Improve this answer
10
  • Logs from standby. WAL is getting restored from local archive directory on standby 2022-05-27 17:00:43 IST 3676726 6290b65d.381a36 0LOG: restored log file "0000000100000016000000A9" from archive 2022-05-27 17:00:44 IST 3676726 6290b65d.381a36 0LOG: restored log file "0000000100000016000000AA" from archive 2022-05-27 17:00:44 IST 3676726 6290b65d.381a36 0LOG: consistent recovery state reached at 16/AA8624F0 2022-05-27 17:00:44 IST 3676726 6290b65d.381a36 0LOG: invalid resource manager ID 249 at 16/AA8624F0
    – maquebex
    May 27, 2022 at 23:50
  • 2022-05-27 17:00:44 IST 3676724 6290b65c.381a34 0LOG: database system is ready to accept read only connections 2022-05-27 17:00:44 IST 3676776 6290b664.381a68 0LOG: started streaming WAL from primary at 16/AA000000 on timeline 1 2022-05-27 17:00:44 IST 3676776 6290b664.381a68 0FATAL: could not receive data from WAL stream: ERROR: requested WAL segment 0000000100000016000000AA has already been removed
    – maquebex
    May 27, 2022 at 23:50
  • 1
    I'm assuming you meant wal_keep_segments instead of wal_keep_size in your comment, correct me if I'm wrong. From above logs it looks like restore command is working on standby. But any error restoring a WAL log (incorrect prev-link, invalid resource manager etc) causes it to stream log from primary's pg_wal. Is this not expected? In your response, you mentioned WAL segment gets archived and recycled on the primary, so the standby must be able to get it from there. Does this mean restore command should fetch WAL from primary's archive directory if restore fails ?
    – maquebex
    May 28, 2022 at 0:03
  • From those logs it looks like the WAL segment got archived, but the restored WAL segment contains an error. So there is either a software bug in PostgreSQL that wrote bad WAL, or the archived WAL segment got messed up somehow, PostgreSQL should never archive a partial WAL segment. A partial WAL segment on the standby would be no problem, because it gets overwritten from the archive. Unfortunately it is probably hard to reproduce the problem, but analyzing the broken archived WAL segment would certainly be interesting.
    – Laurenz Albe
    May 28, 2022 at 15:39
  • Thanks. Few more questions - 1. From documentation here -link - it states - The standby connects to the primary, which streams WAL records to the standby as they're generated, without waiting for the WAL file to be filled. So when standby streams a WAL record, is it stored on standby's pg_wal(or archive) directory? 2. My restore command is in postgres.conf instead of postgres.auto.conf. Does that have an impact? 3. Recco on how to move forward to confirm if this is a bug. Posted on postgres slack channel for now.
    – maquebex
    May 31, 2022 at 19:52

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.