028_pitr_timelines.pl might fail when cp interrupted and backup includes required segment

From: Alexander Lakhin <exclusion(at)gmail(dot)com>
To: pgsql-hackers <pgsql-hackers(at)postgresql(dot)org>
Subject: 028_pitr_timelines.pl might fail when cp interrupted and backup includes required segment
Date: 2026-08-22 13:00:01
Message-ID: 8fd856ff-b37c-4731-a10b-202ef53a679d@gmail.com
Views: Whole Thread | Raw Message | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

Hello hackers,

I took a look at an interesting failure of 028_pitr_timelines olingo
produced a month ago [1]:
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

Attachment Content-Type Size
slowio.c text/x-csrc 5.2 KB

Browse pgsql-hackers by date

  From Date Subject
Previous Message Andrey Borodin 2026-08-22 11:42:47 Re: [POC] Implement async DNS with getaddrinfo_a