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
/*-------------------------------------------------------------------------
*
* slowio.c
* LD_PRELOAD library to slow down destination writes during cp.
*
* Environment variables:
* SLOWIO_TARGET - if set, only slow writes to fds whose path contains
* this substring (e.g. "archives")
*
* Delays are applied only when the process name is "cp", so the library can
* be inherited broadly without slowing unrelated children.
*
* Example:
* LD_PRELOAD=./slowio.so SLOWIO_TARGET=archives/000000010000000000000002 \
* cp src dst
*
*-------------------------------------------------------------------------
*/
#define _GNU_SOURCE
#include <dlfcn.h>
#include <errno.h>
#include <fcntl.h>
#include <stdbool.h>
#include <stdint.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include <time.h>
#ifdef __linux__
#include <sys/sendfile.h>
#endif
static ssize_t (*next_write)(int fd, const void *buf, size_t count);
static ssize_t (*next_pwrite)(int fd, const void *buf, size_t count, off_t offset);
#ifdef __linux__
static ssize_t (*next_copy_file_range)(int fd_in, loff_t *off_in,
int fd_out, loff_t *off_out,
size_t len, unsigned int flags);
static ssize_t (*next_sendfile)(int out_fd, int in_fd, off_t *offset, size_t count);
#endif
static bool symbols_initialized;
static int is_cp_process = -1; /* tri-state cache for process_is_cp() */
static void
init_symbols(void)
{
if (symbols_initialized)
return;
next_write = (ssize_t (*)(int, const void *, size_t))
dlsym(RTLD_NEXT, "write");
next_pwrite = (ssize_t (*)(int, const void *, size_t, off_t))
dlsym(RTLD_NEXT, "pwrite");
#ifdef __linux__
next_copy_file_range = (ssize_t (*)(int, loff_t *, int, loff_t *, size_t, unsigned int))
dlsym(RTLD_NEXT, "copy_file_range");
next_sendfile = (ssize_t (*)(int, int, off_t *, size_t))
dlsym(RTLD_NEXT, "sendfile");
#endif
symbols_initialized = true;
srand(time(NULL));
}
static bool
name_is_cp(const char *name)
{
const char *base;
if (name == NULL || name[0] == '\0')
return false;
base = strrchr(name, '/');
base = base ? base + 1 : name;
return strcmp(base, "cp") == 0;
}
static bool
process_is_cp(void)
{
if (is_cp_process >= 0)
return is_cp_process;
#if defined(__APPLE__)
is_cp_process = name_is_cp(getprogname());
#elif defined(__linux__)
{
char comm[32];
FILE *file;
is_cp_process = 0;
file = fopen("/proc/self/comm", "r");
if (file != NULL)
{
if (fgets(comm, sizeof(comm), file) != NULL)
{
char *nl = strchr(comm, '\n');
if (nl != NULL)
*nl = '\0';
is_cp_process = name_is_cp(comm);
}
fclose(file);
}
if (!is_cp_process)
{
char cmdline[256];
ssize_t n;
int fd;
fd = open("/proc/self/cmdline", O_RDONLY);
if (fd >= 0)
{
n = read(fd, cmdline, sizeof(cmdline) - 1);
close(fd);
if (n > 0)
{
cmdline[n] = '\0';
is_cp_process = name_is_cp(cmdline);
}
}
}
}
#else
is_cp_process = 0;
#endif
return is_cp_process;
}
static bool
fd_is_target(int fd)
{
const char *needle = getenv("SLOWIO_TARGET");
char path[4096];
if (needle == NULL || needle[0] == '\0')
return true;
#if defined(__APPLE__)
if (fcntl(fd, F_GETPATH, path) == -1)
return false;
#elif defined(__linux__)
{
char linkpath[64];
ssize_t n;
snprintf(linkpath, sizeof(linkpath), "/proc/self/fd/%d", fd);
n = readlink(linkpath, path, sizeof(path) - 1);
if (n < 0)
return false;
path[n] = '\0';
}
#else
return true;
#endif
return strstr(path, needle) != NULL;
}
static void
maybe_delay(int fd)
{
if (process_is_cp() && fd_is_target(fd))
{
if (rand() % 10 == 0) usleep(50000);
}
}
ssize_t
write(int fd, const void *buf, size_t count)
{
ssize_t rc;
init_symbols();
if (next_write == NULL)
{
errno = ENOSYS;
return -1;
}
rc = next_write(fd, buf, count);
if (rc > 0)
maybe_delay(fd);
return rc;
}
ssize_t
pwrite(int fd, const void *buf, size_t count, off_t offset)
{
ssize_t rc;
init_symbols();
if (next_pwrite == NULL)
{
errno = ENOSYS;
return -1;
}
rc = next_pwrite(fd, buf, count, offset);
if (rc > 0)
maybe_delay(fd);
return rc;
}
#ifdef __linux__
ssize_t
copy_file_range(int fd_in, loff_t *off_in,
int fd_out, loff_t *off_out,
size_t len, unsigned int flags)
{
size_t chunk = 65536;
ssize_t total = 0;
init_symbols();
if (next_copy_file_range == NULL)
{
errno = ENOSYS;
return -1;
}
while (len > 0)
{
size_t n = len < chunk ? len : chunk;
ssize_t rc;
rc = next_copy_file_range(fd_in, off_in, fd_out, off_out, n, flags);
if (rc < 0)
return total > 0 ? total : -1;
if (rc == 0)
break;
total += rc;
len -= (size_t) rc;
maybe_delay(fd_out);
}
return total;
}
ssize_t
sendfile(int out_fd, int in_fd, off_t *offset, size_t count)
{
size_t chunk = 65536;
ssize_t total = 0;
init_symbols();
if (next_sendfile == NULL)
{
errno = ENOSYS;
return -1;
}
while (count > 0)
{
size_t n = count < chunk ? count : chunk;
ssize_t rc;
rc = next_sendfile(out_fd, in_fd, offset, n);
if (rc < 0)
return total > 0 ? total : -1;
if (rc == 0)
break;
total += rc;
count -= (size_t) rc;
maybe_delay(out_fd);
}
return total;
}
#endif
