028_pitr_timelines.pl might fail when cp interrupted and backup includes required segment
Hackorum builds and tests every patch posted to the lists, not only commitfest submissions. This is Hackorum's own CI rather than the PostgreSQL project's, and it is still under testing - please report anything that looks wrong.
You can run a PostgreSQL built from this patch straight from Docker, with no checkout and no build:
docker run --rm -p 5432:5432 ghcr.io/hackorum-dev/postgres-patch:t253520psql -h localhost -U postgresBuilt from patchset v5 (message #5), October 23, 2026 at 05:03 AM.
Every patchset is also pushed to a branch of our PostgreSQL fork, so you can check out the same tree CI built. Without a PostgreSQL checkout:
git clone --branch t253520_5 https://github.com/hackorum-dev/postgres.gitIn a checkout you already have, add the fork once:
git remote add hackorum https://github.com/hackorum-dev/postgres.gitthen, for this patchset and every later one:
git fetch hackorum t253520_5 && git checkout t253520_5Patchset v5 (message #5) is on t253520_5
Hello hackers,
I took a look at an interesting failure of 028_pitr_timelines olingo
produced a month ago [1]https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=olingo&dt=2026-07-16%2006%3A14%3A41:
regress_log_028_pitr_timelines
### Starting node "node_pitr"
# Running: pg_ctl --wait --pgdata
/home/bf/bf-build/olingo/HEAD/pgsql.build/testrun/recovery/028_pitr_timelines/data/t_028_pitr_timelines_node_pitr_data/pgdata
--log /home/bf/bf-build/olingo/HEAD/pgsql.build/testrun/recovery/028_pitr_timelines/log/028_pitr_timelines_node_pitr.log
--options --cluster-name=node_pitr start
waiting for server to start.... stopped waiting
pg_ctl: could not start server
Examine the log output.
# pg_ctl start failed; see logfile for details:
/home/bf/bf-build/olingo/HEAD/pgsql.build/testrun/recovery/028_pitr_timelines/log/028_pitr_timelines_node_pitr.log
---
028_pitr_timelines_node_pitr.log
2026-07-16 08:17:47.326 CEST [1690808][startup][:0] LOG: restored log file "00000002.history" from archive
cp: cannot stat
'/home/bf/bf-build/olingo/HEAD/pgsql.build/testrun/recovery/028_pitr_timelines/data/t_028_pitr_timelines_primary_data/archives/00000003.history':
No such file or directory
2026-07-16 08:17:47.357 CEST [1690808][startup][:0] LOG: starting backup recovery with redo LSN 0/02000028, checkpoint
LSN 0/02000088, on timeline ID 1
2026-07-16 08:17:47.364 CEST [1690808][startup][:0] LOG: restored log file "00000002.history" from archive
2026-07-16 08:17:47.411 CEST [1690808][startup][:0] FATAL: archive file "000000010000000000000002" has wrong size:
15269888 instead of 16777216
2026-07-16 08:17:47.419 CEST [1690729][postmaster][:0] LOG: startup process (PID 1690808) exited with exit code 1
2026-07-16 08:17:47.425 CEST [1690729][postmaster][:0] LOG: terminating any other active server processes
---
028_pitr_timelines_primary.log
2026-07-16 08:17:45.671 CEST [1690459][client backend][:0] LOG: disconnection: session time: 0:00:00.009 user=bf
database=postgres host=[local]
2026-07-16 08:17:45.717 CEST [1689729][postmaster][:0] LOG: received immediate shutdown request
2026-07-16 08:17:45.721 CEST [1689796][archiver][:0] FATAL: archive command was terminated by signal 3: Quit
2026-07-16 08:17:45.721 CEST [1689796][archiver][:0] DETAIL: The failed archive command was: cp
"pg_wal/000000010000000000000002"
"/home/bf/bf-build/olingo/HEAD/pgsql.build/testrun/recovery/028_pitr_timelines/data/t_028_pitr_timelines_primary_data/archives/000000010000000000000002"
2026-07-16 08:17:45.725 CEST [1689729][postmaster][:0] LOG: database system is shut down
That is, cp was interrupted mid-flight, probably due to slow IO at that
moment. However, I could not reproduce this failure with the slow io
emulator (attached):
SLOWIO_TARGET=archives/000000010000000000000002 LD_PRELOAD=`pwd`/slowio.so PROVE_TESTS="t/028*" make -s check -s -C
src/test/recovery
despite:
src/test/recovery/tmp_check/log/028_pitr_timelines_primary.log
2026-08-22 14:55:44.673 EEST [74335][archiver][:0] FATAL: archive command was terminated by signal 3: Quit
2026-08-22 14:55:44.673 EEST [74335][archiver][:0] DETAIL: The failed archive command was: cp
"pg_wal/000000010000000000000002"
".../src/test/recovery/tmp_check/t_028_pitr_timelines_primary_data/archives/000000010000000000000002"
As it turned out, under normal conditions, the standby instance overwrites
segment 0002 in the archive on $node_standby->stop:
2026-08-22 14:55:44.901 EEST [74358][archiver][:0] DEBUG: executing archive command "cp
"pg_wal/000000010000000000000002"
".../src/test/recovery/tmp_check/t_028_pitr_timelines_primary_data/archives/000000010000000000000002""
Thus, node_pitr can see the incomplete segment from primary only if
standby doesn't copy over the full 0002 segment it has, and this is
possible if standby recycles the segment instead, that is, standby should
find .done for it/get it with basebackup.
I've managed to re-create the condition needed with:
--- a/src/bin/pg_basebackup/pg_basebackup.c
+++ b/src/bin/pg_basebackup/pg_basebackup.c
@@ -2219,2 +2219,3 @@ BaseBackup(char *compression_algorithm, char *compression_detail,
#ifndef WIN32
+pg_usleep(100000);
if (write(bgpipe[1], xlogend, strlen(xlogend)) != strlen(xlogend))This makes the test fail exactly as on olingo:
SLOWIO_TARGET=archives/000000010000000000000002 LD_PRELOAD=`pwd`/slowio.so PROVE_TESTS="t/028*" make -s check -s -C
src/test/recovery
# +++ tap check in src/test/recovery +++
t/028_pitr_timelines.pl .. 1/? Bailout called. Further testing stopped: pg_ctl start failed
2026-08-22 15:25:18.141 EEST startup[252021] LOG: restored log file "00000002.history" from archive
cp: cannot stat '.../src/test/recovery/tmp_check/t_028_pitr_timelines_primary_data/archives/00000003.history': No such
file or directory
2026-08-22 15:25:18.143 EEST startup[252021] LOG: starting backup recovery with redo LSN 0/02000028, checkpoint LSN
0/02000088, on timeline ID 1
2026-08-22 15:25:18.145 EEST startup[252021] LOG: restored log file "00000002.history" from archive
2026-08-22 15:25:18.151 EEST startup[252021] FATAL: archive file "000000010000000000000002" has wrong size: 5046272
instead of 16777216
2026-08-22 15:25:18.152 EEST postmaster[252016] LOG: startup process (PID 252021) exited with exit code 1
[1]: https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=olingo&dt=2026-07-16%2006%3A14%3A41
Best regards,
Alexander
Attachments:
slowio.ctext/x-csrc; charset=UTF-8; name=slowio.cDownload
Hi Alexander,
On Sat, Aug 22, 2026, Alexander Lakhin wrote:
That is, cp was interrupted mid-flight, probably due to slow IO at
that moment.As it turned out, under normal conditions, the standby instance
overwrites segment 0002 in the archive on $node_standby->stop:
Thanks for tracking this down. I think this points to a general issue in
Test::Cluster rather than another race specific to 028_pitr_timelines.
The archive command publishes the final file name while cp is still
writing it. The test then happens to rely on the standby overwriting a
partial file left by the immediate shutdown.
I propose making archive publication more atomic. The attached patch makes
the archive command follow this sequence:
copy source temporary
mv temporary archive-file
Test::Cluster generates a random component for the temporary name, and
the shell PID further distinguishes concurrent Unix commands. The move
publishes the completed file atomically and retains the existing overwrite
behavior. On both platforms, a failed copy remains invisible to
restore_command.
On Unix we could instead use ln followed by cmp to avoid replacing an
existing archive file with different contents. I did not do that here because
it would change the semantics of Test::Cluster's archive command. WAL-G also
overwrites WAL by default. With WALG_PREVENT_WAL_OVERWRITE enabled, it first
downloads an existing object and compares it with the local WAL, although
there is still a race between that check and the upload. As a maintainer of a
backup tool, I would prefer more PostgreSQL tests to exercise the default
overwrite semantics used by such tools. For end user it is twice cheaper in
calls to S3 (PUT vs GET+PUT).
WDYT?
Thank you!
Best regards, Andrey Borodin.
Attachments:
v1-0001-Make-test-WAL-archiving-publish-files-atomically.patchapplication/octet-stream; name=v1-0001-Make-test-WAL-archiving-publish-files-atomically.patch; x-unix-mode=0644Download+19-5
Hi Alexander,
On Sat, Aug 22, 2026, Alexander Lakhin wrote:
That is, cp was interrupted mid-flight, probably due to slow IO at
that moment.As it turned out, under normal conditions, the standby instance
overwrites segment 0002 in the archive on $node_standby->stop:
Thanks for tracking this down. I think this points to a general issue in
Test::Cluster rather than another race specific to 028_pitr_timelines.
The archive command publishes the final file name while cp is still
writing it. The test then happens to rely on the standby overwriting a
partial file left by the immediate shutdown.
I propose making archive publication more atomic. The attached patch makes
the archive command follow this sequence:
copy source temporary
mv temporary archive-file
Test::Cluster generates a random component for the temporary name, and
the shell PID further distinguishes concurrent Unix commands. The move
publishes the completed file atomically and retains the existing overwrite
behavior. On both platforms, a failed copy remains invisible to
restore_command.
On Unix we could instead use ln followed by cmp to avoid replacing an
existing archive file with different contents. I did not do that here because
it would change the semantics of Test::Cluster's archive command. WAL-G also
overwrites WAL by default. With WALG_PREVENT_WAL_OVERWRITE enabled, it first
downloads an existing object and compares it with the local WAL, although
there is still a race between that check and the upload. As a maintainer of a
backup tool, I would prefer more PostgreSQL tests to exercise the default
overwrite semantics used by such tools. For end user it is twice cheaper in
calls to S3 (PUT vs GET+PUT).
WDYT?
Thank you!
Best regards, Andrey Borodin.
The following review has been posted through the commitfest application:
make installcheck-world: tested, passed
Implements feature: tested, passed
Spec compliant: tested, passed
Documentation: tested, failed
Hi!
This looks like a reasonable improvement.
However, i have some questions about realization.
1. In general case we use $$ to add pid to temp_path, whereas on windows we do not use this.
I believe, this can cause name collision, which is not great.
2. In documentation [1]https://www.postgresql.org/docs/current/continuous-archiving.html#BACKUP-ARCHIVING-WAL Best regards, Stepan Filippov. we do not specify that archive command needs to be atomic. Furthermore, we use actual cp as an example.
This can lead to similar problems not only in tests.
Thank you!
[1]: https://www.postgresql.org/docs/current/continuous-archiving.html#BACKUP-ARCHIVING-WAL Best regards, Stepan Filippov.
Best regards, Stepan Filippov.
The new status of this patch is: Waiting on Author
Hi Stepan,
On Mon, Aug 31, 2026 at 10:21 AM Stepan Filippov wrote:
In general case we use $$ to add pid to temp_path, whereas on windows
we do not use this. I believe, this can cause name collision, which is
not great.In documentation we do not specify that archive command needs to be
atomic. Furthermore, we use actual cp as an example. This can lead to
similar problems not only in tests.
Thank you for the review. Both points make sense.
In v2, both platforms use the test process PID and the node port. The
PID distinguishes parallel tests, and the port distinguishes nodes in
one test. There is only one archiver per node, so retries can safely
reuse the same temporary path.
I also documented that archive commands with concurrent readers should
publish complete files atomically, and warned that the simple cp example
does not. I did not present the helper's mv -f as a production recipe,
because that would contradict the existing requirement not to overwrite
a different pre-existing segment.
There is a trade-off: every archive command now performs an additional
rename. I expect the same-directory rename to be a less frequent source
of failures than partial files from an interrupted copy, but only
buildfarm experience can confirm that we have not replaced a rare failure
mode with a more frequent one.
PFA v2.
Thank you!
Best regards, Andrey Borodin.
<div>+ pgsql-hackers@</div><div> </div><div> </div><div> </div><div>----------------</div><div>31.08.2026, 16:30, "Andrey Borodin" <x4mmm@yandex-team.ru>:</div><blockquote><p>In v2, both platforms use the test process PID and the node port. The<br />PID distinguishes parallel tests, and the port distinguishes nodes in<br />one test. There is only one archiver per node, so retries can safely<br />reuse the same temporary path.<br /><br />I also documented that archive commands with concurrent readers should<br />publish complete files atomically, and warned that the simple cp example<br />does not. I did not present the helper's mv -f as a production recipe,<br />because that would contradict the existing requirement not to overwrite<br />a different pre-existing segment.</p></blockquote><div> </div><div><div style="background-color:rgb( 255 , 255 , 255 );color:rgb( 26 , 26 , 26 );font-family:'ys text' , 'arial' , sans-serif;font-size:16px;font-style:normal;font-weight:400;text-align:start;text-decoration-color:initial;text-decoration-style:initial;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px">Thank you for your work. Checked code and documentation.<br />Now this patch looks great to me.<br /><br />As for frequency of failures, I believe that renaming will be more reliable.<br />As long as we expect it to be atomic on all systems.<br /> </div><div style="background-color:rgb( 255 , 255 , 255 );color:rgb( 26 , 26 , 26 );font-family:'ys text' , 'arial' , sans-serif;font-size:16px;font-style:normal;font-weight:400;text-align:start;text-decoration-color:initial;text-decoration-style:initial;text-indent:0px;text-transform:none;white-space:normal;word-spacing:0px"><div>Best regards, Stepan Filippov.</div></div></div>