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 v2 (message #3), August 23, 2026 at 10:47 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_2 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_2 && git checkout t253520_2Patchset v2 (message #3) is on t253520_2
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.