Hi there,
We've found (what seems like) a race condition in a replica server which is receiving WAL from the archive. We are not 100% sure if it happens on streaming replicas as well.
Specifically, we occasionally see an error like this:
May 20 09:56:14 redacted[141]: [191806-1] sql_error_code = 58P01 ERROR: could not open file "pg_wal/00000002000072B50000003A": No such file or directory
Upon looking at logs around this, we can see that the recovery process had just restored that file:
May 20 09:56:14 redacted[9]: [2468859-1] sql_error_code = 00000 LOG: restored log file "00000002000072B50000003A" from archive
May 20 09:56:14 ip-10-0-92-26 redacted[141]: [191806-1] sql_error_code = 58P01 ERROR: could not open file "pg_wal/00000002000072B50000003A": No such file or directory
(on this particular server, pid 9 is the recovery process, and pid 141 is the checkpointer)
We've seen this across a range of server versions, including (in the last 30 days):
9.5.12
9.5.14
9.6.10
9.6.6
9.6.7
9.6.8
9.6.9
10.2
10.3
10.4
10.5
Upon digging into the code, we found (we think) the reason behind this race. The recovery process can call unlink() on the file, whilst the restartpoint attempts to recycle the segment. To quote from the docs:
In archive recovery or standby mode, the server periodically performs restartpoints, which are similar to checkpoints in normal operation: the server forces all its state to disk, updates the pg_control file to indicate that the already-processed WAL data need not be scanned again, and then recycles any old log segment files in the pg_wal directory.
Looking at the code, I think that the two racing functions are RestoreArchivedFile, and CreateRestartPoint.
The former calls unlink on the wal segment, CreateRestartPoint does attempt to do recycling on segments.
From our perspective this seems like a race condition - the recovery process unlinks the file as the checkpointer tries to recycle the wal segment. At this point the checkpointer panics and shuts down, causing a hit to availability.
As far as we have seen, starting the process up after the crash allows the server to continue making progress.
This seems like an extremely rare race - our data show it occurs once every few hundred thousand wal restores from archive that Heroku Postgres does.
Thanks
Tom Crayford
Heroku Postgres