BUG #19576: startup process hangs indefinitely replaying MultiXact/CREATE_ID record

The following bug has been logged on the website:

Bug reference: 19576
Logged by: Nicolas Payart
Email address: npayart(at)gmail(dot)com
PostgreSQL version: 14.23
Operating system: Debian 11.11
Description:

Hello,

We are hitting what appears to be a regression introduced in 14.23: the
startup process hangs indefinitely during archive recovery when replaying a
MultiXact/CREATE_ID record that requires initializing a new multixact
offsets page. The exact same data directory recovers fine in a few seconds
with 14.22 binaries.

Environment:
- PostgreSQL 14.23 (Debian 14.23-1.pgdg11+1), x86_64, Debian 11 (PGDG
packages)
- Standby data directory restored from a ZFS snapshot of a cleanly shut down
standby (Patroni-managed cluster)
- Started standalone for backup verification: standby.signal present,
restore_command = 'exit 1' (no archive), no primary_conninfo, all required
WAL segments present in pg_wal (segments 0000000E0000DB74000000AB through
D2)
- pg_controldata: REDO location DB74/ABB108C0, minimum recovery ending
location DB74/BB62D2B8

Symptom on 14.23:
- Redo starts at DB74/ABB108C0 and progresses normally through segment B0.
- After reading segment 0000000E0000DB74000000B1 from pg_wal, the startup
process goes silent and never makes progress again (verified with
log_min_messages = debug2: no further messages from the startup process for
20+ minutes, only checkpointer 'skipping restartpoint' messages).
- The startup process sleeps at 0% CPU (state S) and does NOT respond to a
fast shutdown request (SIGTERM): a shutdown requested at 07:47 was still
incomplete at 08:08, and the postmaster had to be killed.
- Consistency (DB74/BB62D2B8) is never reached, so the instance never
accepts connections.

Behavior on 14.22 (same host, same untouched data directory, only the
binaries differ):
- The first record in segment B1 after the stall point is:
WAL redo at DB74/B10C4AA8 for MultiXact/CREATE_ID: 1675472895 offset
114144768 nmembers 3: 2152577239 (sh) 2152577240 (sh) 2152577245 (sh)
accompanied by:
DEBUG: next offsets page is not initialized, initializing it now
(RecordNewMultiXact, multixact.c:904)
DEBUG: skipping initialization of offsets page 818102 because it was
already initialized on multixid creation (WAL redo at DB74/B10C4C60 for
MultiXact/ZERO_OFF_PAGE: 818102)
- Two more such page-boundary crossings follow (pages 818103 and 818104),
consistency is reached at DB74/BB62D2B8 about 4 seconds after redo start,
and recovery completes normally.

So on 14.23 the startup process hangs exactly on the first
MultiXact/CREATE_ID record whose replay must initialize a new offsets SLRU
page (DB74/B10C4AA8). The debug2 logs of both runs are identical up to that
point.

We suspect commit e35e466f6 ("Fix race condition between WAL replay of
checkpoints and multixact ID creations"), which is the only
recovery/multixact change between 14.22 and 14.23. Consistent with that,
SetMultiXactIdLimit is reported at multixact.c:2370 in the 14.22 log and
multixact.c:2419 in the 14.23 log. It looks like the new synchronization
introduced by that fix can make the startup process wait forever when
replaying a multixact creation that crosses an offsets page boundary, at
least in a standalone standby with no walreceiver, and the wait is not
interruptible by SIGTERM.

Reproducibility:
- 100% reproducible with this data directory: 14.23 hangs at the same LSN on
every attempt, 14.22 always succeeds.
- We observe the same hang on several other clusters of our fleet when their
snapshot's WAL window happens to contain multixact creations; clusters
without multixact activity in the replayed window start fine on 14.23.
Starting once with 14.22 (clean shutdown after recovery), then restarting
with 14.23, also works, since there is nothing left to replay.

I can provide the full debug2 startup logs for both versions, pg_controldata
output, and pg_waldump output around DB74/B10C4AA8, and I can get a
backtrace of the hung startup process if useful. I can also keep the ZFS
snapshot around for further testing.

Regards,
Nicolas

#
# postgresql-14 14.22-1.pgdg11+1
#

# cat /tank/restore/postgresql/main/postgresql.log
2026-07-23 09:07:23.495 UTC postgres[156730]: [6a61d9cb.2643a-1]
db=,user=,app=,client= DEBUG: 00000: registering background worker "logical
replication launcher"
2026-07-23 09:07:23.495 UTC postgres[156730]: [6a61d9cb.2643a-2]
db=,user=,app=,client= LOCATION: RegisterBackgroundWorker, bgworker.c:895
2026-07-23 09:07:23.495 UTC postgres[156730]: [6a61d9cb.2643a-3]
db=,user=,app=,client= DEBUG: 00000: loaded library "pg_stat_statements"
2026-07-23 09:07:23.495 UTC postgres[156730]: [6a61d9cb.2643a-4]
db=,user=,app=,client= LOCATION: load_libraries, miscinit.c:1702
2026-07-23 09:07:23.496 UTC postgres[156730]: [6a61d9cb.2643a-5]
db=,user=,app=,client= DEBUG: 00000: mmap(82128666624) with MAP_HUGETLB
failed, huge pages disabled: Invalid argument
2026-07-23 09:07:23.496 UTC postgres[156730]: [6a61d9cb.2643a-6]
db=,user=,app=,client= LOCATION: CreateAnonymousSegment, pg_shmem.c:595
2026-07-23 09:07:24.318 UTC postgres[156730]: [6a61d9cb.2643a-7]
db=,user=,app=,client= DEBUG: 00000: dynamic shared memory system will
support 11419 segments
2026-07-23 09:07:24.318 UTC postgres[156730]: [6a61d9cb.2643a-8]
db=,user=,app=,client= LOCATION: dsm_postmaster_startup, dsm.c:169
2026-07-23 09:07:24.318 UTC postgres[156730]: [6a61d9cb.2643a-9]
db=,user=,app=,client= DEBUG: 00000: created dynamic shared memory control
segment 484581360 (456776 bytes)
2026-07-23 09:07:24.318 UTC postgres[156730]: [6a61d9cb.2643a-10]
db=,user=,app=,client= LOCATION: dsm_postmaster_startup, dsm.c:193
2026-07-23 09:07:24.320 UTC postgres[156730]: [6a61d9cb.2643a-11]
db=,user=,app=,client= DEBUG: 00000: max_safe_fds = 987, usable_fds = 1000,
already_open = 3
2026-07-23 09:07:24.320 UTC postgres[156730]: [6a61d9cb.2643a-12]
db=,user=,app=,client= LOCATION: set_max_safe_fds, fd.c:1023
2026-07-23 09:07:24.320 UTC postgres[156730]: [6a61d9cb.2643a-13]
db=,user=,app=,client= LOG: 00000: starting PostgreSQL 14.22 (Debian
14.22-1.pgdg11+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6)
10.2.1 20210110, 64-bit
2026-07-23 09:07:24.320 UTC postgres[156730]: [6a61d9cb.2643a-14]
db=,user=,app=,client= LOCATION: PostmasterMain, postmaster.c:1141
2026-07-23 09:07:24.320 UTC postgres[156730]: [6a61d9cb.2643a-15]
db=,user=,app=,client= LOG: 00000: listening on IPv4 address "127.0.0.1",
port 5433
2026-07-23 09:07:24.320 UTC postgres[156730]: [6a61d9cb.2643a-16]
db=,user=,app=,client= LOCATION: StreamServerPort, pqcomm.c:578
2026-07-23 09:07:24.321 UTC postgres[156730]: [6a61d9cb.2643a-17]
db=,user=,app=,client= LOG: 00000: listening on Unix socket
"/tank/restore/postgresql/main/.s.PGSQL.5433"
2026-07-23 09:07:24.321 UTC postgres[156730]: [6a61d9cb.2643a-18]
db=,user=,app=,client= LOCATION: StreamServerPort, pqcomm.c:573
2026-07-23 09:07:24.325 UTC postgres[156740]: [6a61d9cc.26444-1]
db=,user=,app=,client= LOG: 00000: database system was shut down in
recovery at 2026-07-23 00:00:04 UTC
2026-07-23 09:07:24.325 UTC postgres[156740]: [6a61d9cc.26444-2]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6586
2026-07-23 09:07:24.326 UTC postgres[156740]: [6a61d9cc.26444-3]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000F.history" from archive: child process exited with exit code 1
2026-07-23 09:07:24.326 UTC postgres[156740]: [6a61d9cc.26444-4]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.326 UTC postgres[156740]: [6a61d9cc.26444-5]
db=,user=,app=,client= LOG: 00000: entering standby mode
2026-07-23 09:07:24.326 UTC postgres[156740]: [6a61d9cc.26444-6]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6677
2026-07-23 09:07:24.326 UTC postgres[156740]: [6a61d9cc.26444-7]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E.history" from archive: child process exited with exit code 1
2026-07-23 09:07:24.326 UTC postgres[156740]: [6a61d9cc.26444-8]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.327 UTC postgres[156740]: [6a61d9cc.26444-9]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B6" from archive: child process exited with exit code
1
2026-07-23 09:07:24.327 UTC postgres[156740]: [6a61d9cc.26444-10]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.327 UTC postgres[156740]: [6a61d9cc.26444-11]
db=,user=,app=,client= DEBUG: 00000: checkpoint record is at DB74/B6D42948
2026-07-23 09:07:24.327 UTC postgres[156740]: [6a61d9cc.26444-12]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6891
2026-07-23 09:07:24.327 UTC postgres[156740]: [6a61d9cc.26444-13]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000AB" from archive: child process exited with exit code
1
2026-07-23 09:07:24.327 UTC postgres[156740]: [6a61d9cc.26444-14]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-15]
db=,user=,app=,client= DEBUG: 00000: redo record is at DB74/ABB108C0;
shutdown false
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-16]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6975
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-17]
db=,user=,app=,client= DEBUG: 00000: next transaction ID: 53692118865; next
OID: 1695415741
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-18]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6979
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-19]
db=,user=,app=,client= DEBUG: 00000: next MultiXactId: 1675471103; next
MultiXactOffset: 114139422
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-20]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6983
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-21]
db=,user=,app=,client= DEBUG: 00000: oldest unfrozen transaction ID:
2009689764, in database 25748
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-22]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6986
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-23]
db=,user=,app=,client= DEBUG: 00000: oldest MultiXactId: 1665611891, in
database 25748
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-24]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6989
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-25]
db=,user=,app=,client= DEBUG: 00000: commit timestamp Xid oldest/newest:
2009689764/2152511312
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-26]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6992
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-27]
db=,user=,app=,client= DEBUG: 00000: transaction ID wrap limit is
4157173411, limited by database with OID 25748
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-28]
db=,user=,app=,client= LOCATION: SetTransactionIdLimit, varsup.c:427
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-29]
db=,user=,app=,client= DEBUG: 00000: MultiXactId wrap limit is 3813095538,
limited by database with OID 25748
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-30]
db=,user=,app=,client= LOCATION: SetMultiXactIdLimit, multixact.c:2370
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-31]
db=,user=,app=,client= DEBUG: 00000: starting up replication slots
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-32]
db=,user=,app=,client= LOCATION: StartupReplicationSlots, slot.c:1454
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-33]
db=,user=,app=,client= DEBUG: 00000: xmin required by slots: data 0,
catalog 0
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-34]
db=,user=,app=,client= LOCATION: ProcArraySetReplicationSlotXmin,
procarray.c:3999
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-35]
db=,user=,app=,client= DEBUG: 00000: starting up replication origin
progress state
2026-07-23 09:07:24.330 UTC postgres[156740]: [6a61d9cc.26444-36]
db=,user=,app=,client= LOCATION: StartupReplicationOrigin, origin.c:706
2026-07-23 09:07:24.331 UTC postgres[156740]: [6a61d9cc.26444-37]
db=,user=,app=,client= DEBUG: 00000: resetting unlogged relations: cleanup
1 init 0
2026-07-23 09:07:24.331 UTC postgres[156740]: [6a61d9cc.26444-38]
db=,user=,app=,client= LOCATION: ResetUnloggedRelations, reinit.c:55
2026-07-23 09:07:24.332 UTC postgres[156740]: [6a61d9cc.26444-39]
db=,user=,app=,client= DEBUG: 00000: initializing for hot standby
2026-07-23 09:07:24.332 UTC postgres[156740]: [6a61d9cc.26444-40]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:7291
2026-07-23 09:07:24.332 UTC postgres[156740]: [6a61d9cc.26444-41]
db=,user=,app=,client= LOG: 00000: redo starts at DB74/ABB108C0
2026-07-23 09:07:24.332 UTC postgres[156740]: [6a61d9cc.26444-42]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:7427
2026-07-23 09:07:24.332 UTC postgres[156740]: [6a61d9cc.26444-43]
db=,user=,app=,client= DEBUG: 00000: could not forward fsync request
because request queue is full
2026-07-23 09:07:24.332 UTC postgres[156740]: [6a61d9cc.26444-44]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/ABB108C0 for Heap/LOCK:
off 44: xid 2152511311: flags 0x00 LOCK_ONLY EXCL_LOCK ; blkref #0: rel
1663/26159/27449, blk 134678 FPW
2026-07-23 09:07:24.332 UTC postgres[156740]: [6a61d9cc.26444-45]
db=,user=,app=,client= LOCATION: register_dirty_segment, md.c:994
2026-07-23 09:07:24.333 UTC postgres[156740]: [6a61d9cc.26444-46]
db=,user=,app=,client= DEBUG: 00000: could not forward fsync request
because request queue is full
2026-07-23 09:07:24.333 UTC postgres[156740]: [6a61d9cc.26444-47]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/ABB10FB8 for Heap/INSERT:
off 7 flags 0x18; blkref #0: rel 1663/26159/27465, blk 3873 FPW
2026-07-23 09:07:24.333 UTC postgres[156740]: [6a61d9cc.26444-48]
db=,user=,app=,client= LOCATION: register_dirty_segment, md.c:994
2026-07-23 09:07:24.333 UTC postgres[156740]: [6a61d9cc.26444-49]
db=,user=,app=,client= DEBUG: 00000: could not forward fsync request
because request queue is full
2026-07-23 09:07:24.333 UTC postgres[156740]: [6a61d9cc.26444-50]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/ABB13378 for Heap/LOCK:
off 5: xid 2152511313: flags 0x00 LOCK_ONLY EXCL_LOCK KEYS_UPDATED ; blkref
#0: rel 1663/25483/25534, blk 139240 FPW
2026-07-23 09:07:24.333 UTC postgres[156740]: [6a61d9cc.26444-51]
db=,user=,app=,client= LOCATION: register_dirty_segment, md.c:994
2026-07-23 09:07:24.333 UTC postgres[156745]: [6a61d9cc.26449-1]
db=,user=,app=,client= DEBUG: 00000: checkpointer updated shared memory
configuration values
2026-07-23 09:07:24.333 UTC postgres[156745]: [6a61d9cc.26449-2]
db=,user=,app=,client= LOCATION: UpdateSharedMemoryConfig,
checkpointer.c:1340
2026-07-23 09:07:24.335 UTC postgres[156740]: [6a61d9cc.26444-52]
db=,user=,app=,client= DEBUG: 00000: recovery snapshots are now enabled
2026-07-23 09:07:24.335 UTC postgres[156740]: [6a61d9cc.26444-53]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/ABB2CC00 for
Standby/RUNNING_XACTS: nextXid 2152511319 latestCompletedXid 2152511318
oldestRunningXid 2152511319
2026-07-23 09:07:24.335 UTC postgres[156740]: [6a61d9cc.26444-54]
db=,user=,app=,client= LOCATION: ProcArrayApplyRecoveryInfo,
procarray.c:1311
2026-07-23 09:07:24.358 UTC postgres[156740]: [6a61d9cc.26444-55]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000AC" from archive: child process exited with exit code
1
2026-07-23 09:07:24.358 UTC postgres[156740]: [6a61d9cc.26444-56]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.437 UTC postgres[156740]: [6a61d9cc.26444-57]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000AD" from archive: child process exited with exit code
1
2026-07-23 09:07:24.437 UTC postgres[156740]: [6a61d9cc.26444-58]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.539 UTC postgres[156740]: [6a61d9cc.26444-59]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000AE" from archive: child process exited with exit code
1
2026-07-23 09:07:24.539 UTC postgres[156740]: [6a61d9cc.26444-60]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.615 UTC postgres[156740]: [6a61d9cc.26444-61]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000AF" from archive: child process exited with exit code
1
2026-07-23 09:07:24.615 UTC postgres[156740]: [6a61d9cc.26444-62]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.691 UTC postgres[156740]: [6a61d9cc.26444-63]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B0" from archive: child process exited with exit code
1
2026-07-23 09:07:24.691 UTC postgres[156740]: [6a61d9cc.26444-64]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.788 UTC postgres[156740]: [6a61d9cc.26444-65]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B1" from archive: child process exited with exit code
1
2026-07-23 09:07:24.788 UTC postgres[156740]: [6a61d9cc.26444-66]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.792 UTC postgres[156740]: [6a61d9cc.26444-67]
db=,user=,app=,client= DEBUG: 00000: next offsets page is not initialized,
initializing it now
2026-07-23 09:07:24.792 UTC postgres[156740]: [6a61d9cc.26444-68]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/B10C4AA8 for
MultiXact/CREATE_ID: 1675472895 offset 114144768 nmembers 3: 2152577239 (sh)
2152577240 (sh) 2152577245 (sh)
2026-07-23 09:07:24.792 UTC postgres[156740]: [6a61d9cc.26444-69]
db=,user=,app=,client= LOCATION: RecordNewMultiXact, multixact.c:904
2026-07-23 09:07:24.792 UTC postgres[156740]: [6a61d9cc.26444-70]
db=,user=,app=,client= DEBUG: 00000: skipping initialization of offsets
page 818102 because it was already initialized on multixid creation
2026-07-23 09:07:24.792 UTC postgres[156740]: [6a61d9cc.26444-71]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/B10C4C60 for
MultiXact/ZERO_OFF_PAGE: 818102
2026-07-23 09:07:24.792 UTC postgres[156740]: [6a61d9cc.26444-72]
db=,user=,app=,client= LOCATION: multixact_redo, multixact.c:3375
2026-07-23 09:07:24.866 UTC postgres[156740]: [6a61d9cc.26444-73]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B2" from archive: child process exited with exit code
1
2026-07-23 09:07:24.866 UTC postgres[156740]: [6a61d9cc.26444-74]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:24.951 UTC postgres[156740]: [6a61d9cc.26444-75]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B3" from archive: child process exited with exit code
1
2026-07-23 09:07:24.951 UTC postgres[156740]: [6a61d9cc.26444-76]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.036 UTC postgres[156740]: [6a61d9cc.26444-77]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B4" from archive: child process exited with exit code
1
2026-07-23 09:07:25.036 UTC postgres[156740]: [6a61d9cc.26444-78]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.122 UTC postgres[156740]: [6a61d9cc.26444-79]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B5" from archive: child process exited with exit code
1
2026-07-23 09:07:25.122 UTC postgres[156740]: [6a61d9cc.26444-80]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.138 UTC postgres[156740]: [6a61d9cc.26444-81]
db=,user=,app=,client= DEBUG: 00000: next offsets page is not initialized,
initializing it now
2026-07-23 09:07:25.138 UTC postgres[156740]: [6a61d9cc.26444-82]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/B5374398 for
MultiXact/CREATE_ID: 1675474943 offset 114150579 nmembers 2: 2152673176 (sh)
2152673179 (sh)
2026-07-23 09:07:25.138 UTC postgres[156740]: [6a61d9cc.26444-83]
db=,user=,app=,client= LOCATION: RecordNewMultiXact, multixact.c:904
2026-07-23 09:07:25.138 UTC postgres[156740]: [6a61d9cc.26444-84]
db=,user=,app=,client= DEBUG: 00000: skipping initialization of offsets
page 818103 because it was already initialized on multixid creation
2026-07-23 09:07:25.138 UTC postgres[156740]: [6a61d9cc.26444-85]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/B5375E10 for
MultiXact/ZERO_OFF_PAGE: 818103
2026-07-23 09:07:25.138 UTC postgres[156740]: [6a61d9cc.26444-86]
db=,user=,app=,client= LOCATION: multixact_redo, multixact.c:3375
2026-07-23 09:07:25.198 UTC postgres[156740]: [6a61d9cc.26444-87]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B6" from archive: child process exited with exit code
1
2026-07-23 09:07:25.198 UTC postgres[156740]: [6a61d9cc.26444-88]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.277 UTC postgres[156740]: [6a61d9cc.26444-89]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B7" from archive: child process exited with exit code
1
2026-07-23 09:07:25.277 UTC postgres[156740]: [6a61d9cc.26444-90]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.350 UTC postgres[156740]: [6a61d9cc.26444-91]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B8" from archive: child process exited with exit code
1
2026-07-23 09:07:25.350 UTC postgres[156740]: [6a61d9cc.26444-92]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.419 UTC postgres[156740]: [6a61d9cc.26444-93]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B9" from archive: child process exited with exit code
1
2026-07-23 09:07:25.419 UTC postgres[156740]: [6a61d9cc.26444-94]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.483 UTC postgres[156740]: [6a61d9cc.26444-95]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000BA" from archive: child process exited with exit code
1
2026-07-23 09:07:25.483 UTC postgres[156740]: [6a61d9cc.26444-96]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.524 UTC postgres[156740]: [6a61d9cc.26444-97]
db=,user=,app=,client= DEBUG: 00000: next offsets page is not initialized,
initializing it now
2026-07-23 09:07:25.524 UTC postgres[156740]: [6a61d9cc.26444-98]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/BA9752F8 for
MultiXact/CREATE_ID: 1675476991 offset 114156274 nmembers 2: 2152791350 (sh)
2152791352 (sh)
2026-07-23 09:07:25.524 UTC postgres[156740]: [6a61d9cc.26444-99]
db=,user=,app=,client= LOCATION: RecordNewMultiXact, multixact.c:904
2026-07-23 09:07:25.524 UTC postgres[156740]: [6a61d9cc.26444-100]
db=,user=,app=,client= DEBUG: 00000: skipping initialization of offsets
page 818104 because it was already initialized on multixid creation
2026-07-23 09:07:25.524 UTC postgres[156740]: [6a61d9cc.26444-101]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/BA97B6A8 for
MultiXact/ZERO_OFF_PAGE: 818104
2026-07-23 09:07:25.524 UTC postgres[156740]: [6a61d9cc.26444-102]
db=,user=,app=,client= LOCATION: multixact_redo, multixact.c:3375
2026-07-23 09:07:25.553 UTC postgres[156740]: [6a61d9cc.26444-103]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000BB" from archive: child process exited with exit code
1
2026-07-23 09:07:25.553 UTC postgres[156740]: [6a61d9cc.26444-104]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.578 UTC postgres[156740]: [6a61d9cc.26444-105]
db=,user=,app=,client= LOG: 00000: consistent recovery state reached at
DB74/BB62D2B8
2026-07-23 09:07:25.578 UTC postgres[156740]: [6a61d9cc.26444-106]
db=,user=,app=,client= LOCATION: CheckRecoveryConsistency, xlog.c:8407
2026-07-23 09:07:25.578 UTC postgres[156740]: [6a61d9cc.26444-107]
db=,user=,app=,client= LOG: 00000: record with incorrect prev-link
200CC2A0/1CC2400C at DB74/BB62D2B8
2026-07-23 09:07:25.578 UTC postgres[156740]: [6a61d9cc.26444-108]
db=,user=,app=,client= LOCATION: ReadRecord, xlog.c:4479
2026-07-23 09:07:25.578 UTC postgres[156740]: [6a61d9cc.26444-109]
db=,user=,app=,client= DEBUG: 00000: switched WAL source from archive to
stream after failure
2026-07-23 09:07:25.578 UTC postgres[156740]: [6a61d9cc.26444-110]
db=,user=,app=,client= LOCATION: WaitForWALToBecomeAvailable, xlog.c:12952
2026-07-23 09:07:25.579 UTC postgres[156730]: [6a61d9cb.2643a-19]
db=,user=,app=,client= LOG: 00000: database system is ready to accept
read-only connections
2026-07-23 09:07:25.579 UTC postgres[156730]: [6a61d9cb.2643a-20]
db=,user=,app=,client= LOCATION: sigusr1_handler, postmaster.c:5236
2026-07-23 09:07:25.599 UTC postgres[156772]: [6a61d9cd.26464-1]
db=,user=,app=,client= FATAL: 08006: could not connect to the primary
server: connection to server at "10.205.19.34", port 5432 failed:
fe_sendauth: no password supplied
2026-07-23 09:07:25.599 UTC postgres[156772]: [6a61d9cd.26464-2]
db=,user=,app=,client= LOCATION: WalReceiverMain, walreceiver.c:287
2026-07-23 09:07:25.600 UTC postgres[156740]: [6a61d9cc.26444-111]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000F.history" from archive: child process exited with exit code 1
2026-07-23 09:07:25.600 UTC postgres[156740]: [6a61d9cc.26444-112]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.600 UTC postgres[156740]: [6a61d9cc.26444-113]
db=,user=,app=,client= DEBUG: 00000: switched WAL source from stream to
archive after failure
2026-07-23 09:07:25.600 UTC postgres[156740]: [6a61d9cc.26444-114]
db=,user=,app=,client= LOCATION: WaitForWALToBecomeAvailable, xlog.c:12952
2026-07-23 09:07:25.601 UTC postgres[156740]: [6a61d9cc.26444-115]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000BB" from archive: child process exited with exit code
1
2026-07-23 09:07:25.601 UTC postgres[156740]: [6a61d9cc.26444-116]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:25.601 UTC postgres[156740]: [6a61d9cc.26444-117]
db=,user=,app=,client= DEBUG: 00000: record with incorrect prev-link
200CC2A0/1CC2400C at DB74/BB62D2B8
2026-07-23 09:07:25.601 UTC postgres[156740]: [6a61d9cc.26444-118]
db=,user=,app=,client= LOCATION: ReadRecord, xlog.c:4479
2026-07-23 09:07:25.601 UTC postgres[156740]: [6a61d9cc.26444-119]
db=,user=,app=,client= DEBUG: 00000: switched WAL source from archive to
stream after failure
2026-07-23 09:07:25.601 UTC postgres[156740]: [6a61d9cc.26444-120]
db=,user=,app=,client= LOCATION: WaitForWALToBecomeAvailable, xlog.c:12952
2026-07-23 09:07:25.618 UTC postgres[156776]: [6a61d9cd.26468-1]
db=,user=,app=,client= FATAL: 08006: could not connect to the primary
server: connection to server at "10.205.19.34", port 5432 failed:
fe_sendauth: no password supplied
2026-07-23 09:07:25.618 UTC postgres[156776]: [6a61d9cd.26468-2]
db=,user=,app=,client= LOCATION: WalReceiverMain, walreceiver.c:287
2026-07-23 09:07:25.619 UTC postgres[156740]: [6a61d9cc.26444-121]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000F.history" from archive: child process exited with exit code 1
2026-07-23 09:07:25.619 UTC postgres[156740]: [6a61d9cc.26444-122]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:27.351 UTC postgres[156730]: [6a61d9cb.2643a-21]
db=,user=,app=,client= DEBUG: 00000: forked new backend, pid=156801
socket=8
2026-07-23 09:07:27.351 UTC postgres[156730]: [6a61d9cb.2643a-22]
db=,user=,app=,client= LOCATION: BackendStartup, postmaster.c:4285
2026-07-23 09:07:27.351 UTC postgres[156801]: [6a61d9cf.26481-1]
db=[unknown],user=[unknown],app=[unknown],client=127.0.0.1 LOG: 00000:
connection received: host=127.0.0.1 port=42388
2026-07-23 09:07:27.351 UTC postgres[156801]: [6a61d9cf.26481-2]
db=[unknown],user=[unknown],app=[unknown],client=127.0.0.1 LOCATION:
BackendInitialize, postmaster.c:4426
2026-07-23 09:07:27.356 UTC postgres[156801]: [6a61d9cf.26481-3]
db=[unknown],user=[unknown],app=[unknown],client=127.0.0.1 DEBUG: 00000:
SSL connection from DN:"(anonymous)" CN:"(anonymous)"
2026-07-23 09:07:27.356 UTC postgres[156801]: [6a61d9cf.26481-4]
db=[unknown],user=[unknown],app=[unknown],client=127.0.0.1 LOCATION:
secure_open_server, be-secure.c:122
2026-07-23 09:07:27.361 UTC postgres[156801]: [6a61d9cf.26481-5]
db=postgres,user=postgres,app=[unknown],client=127.0.0.1 LOG: 00000:
connection authenticated: identity="postgres" method=scram-sha-256
(/tank/restore/postgresql/main/pg_hba.conf:8)
2026-07-23 09:07:27.361 UTC postgres[156801]: [6a61d9cf.26481-6]
db=postgres,user=postgres,app=[unknown],client=127.0.0.1 LOCATION:
set_authn_id, auth.c:388
2026-07-23 09:07:27.361 UTC postgres[156801]: [6a61d9cf.26481-7]
db=postgres,user=postgres,app=[unknown],client=127.0.0.1 LOG: 00000:
connection authorized: user=postgres database=postgres
application_name=pg_isready SSL enabled (protocol=TLSv1.3,
cipher=TLS_AES_256_GCM_SHA384, bits=256)
2026-07-23 09:07:27.361 UTC postgres[156801]: [6a61d9cf.26481-8]
db=postgres,user=postgres,app=[unknown],client=127.0.0.1 LOCATION:
PerformAuthentication, postinit.c:292
2026-07-23 09:07:27.366 UTC postgres[156801]: [6a61d9cf.26481-9]
db=postgres,user=postgres,app=pg_isready,client=127.0.0.1 LOG: 00000:
disconnection: session time: 0:00:00.014 user=postgres database=postgres
host=127.0.0.1 port=42388
2026-07-23 09:07:27.366 UTC postgres[156801]: [6a61d9cf.26481-10]
db=postgres,user=postgres,app=pg_isready,client=127.0.0.1 LOCATION:
log_disconnections, postgres.c:5002
2026-07-23 09:07:27.367 UTC postgres[156730]: [6a61d9cb.2643a-23]
db=,user=,app=,client= DEBUG: 00000: server process (PID 156801) exited
with exit code 0
2026-07-23 09:07:27.367 UTC postgres[156730]: [6a61d9cb.2643a-24]
db=,user=,app=,client= LOCATION: LogChildExit, postmaster.c:3743
2026-07-23 09:07:29.122 UTC postgres[156740]: [6a61d9cc.26444-123]
db=,user=,app=,client= DEBUG: 00000: switched WAL source from stream to
archive after failure
2026-07-23 09:07:29.122 UTC postgres[156740]: [6a61d9cc.26444-124]
db=,user=,app=,client= LOCATION: WaitForWALToBecomeAvailable, xlog.c:12952
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-125]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000BB" from archive: child process exited with exit code
1
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-126]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-127]
db=,user=,app=,client= DEBUG: 00000: record with incorrect prev-link
200CC2A0/1CC2400C at DB74/BB62D2B8
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-128]
db=,user=,app=,client= LOCATION: ReadRecord, xlog.c:4479
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-129]
db=,user=,app=,client= LOG: 00000: received promote request
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-130]
db=,user=,app=,client= LOCATION: CheckForStandbyTrigger, xlog.c:13345
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-131]
db=,user=,app=,client= LOG: 00000: redo done at DB74/BB62D288 system usage:
CPU: user: 0.79 s, system: 0.41 s, elapsed: 4.79 s
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-132]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:7690
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-133]
db=,user=,app=,client= LOG: 00000: last completed transaction was at log
time 2026-07-23 02:00:01.823438+02
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-134]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:7696
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-135]
db=,user=,app=,client= DEBUG: 00000: resetting unlogged relations: cleanup
0 init 1
2026-07-23 09:07:29.123 UTC postgres[156740]: [6a61d9cc.26444-136]
db=,user=,app=,client= LOCATION: ResetUnloggedRelations, reinit.c:55
2026-07-23 09:07:29.126 UTC postgres[156740]: [6a61d9cc.26444-137]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000BB" from archive: child process exited with exit code
1
2026-07-23 09:07:29.126 UTC postgres[156740]: [6a61d9cc.26444-138]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:29.127 UTC postgres[156740]: [6a61d9cc.26444-139]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000F.history" from archive: child process exited with exit code 1
2026-07-23 09:07:29.127 UTC postgres[156740]: [6a61d9cc.26444-140]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:29.127 UTC postgres[156740]: [6a61d9cc.26444-141]
db=,user=,app=,client= LOG: 00000: selected new timeline ID: 15
2026-07-23 09:07:29.127 UTC postgres[156740]: [6a61d9cc.26444-142]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:7852
2026-07-23 09:07:29.155 UTC postgres[156740]: [6a61d9cc.26444-143]
db=,user=,app=,client= DEBUG: 58P01: could not remove file
"pg_wal/0000000F0000DB74000000BB": No such file or directory
2026-07-23 09:07:29.155 UTC postgres[156740]: [6a61d9cc.26444-144]
db=,user=,app=,client= LOCATION: durable_unlink, fd.c:783
2026-07-23 09:07:29.156 UTC postgres[156740]: [6a61d9cc.26444-145]
db=,user=,app=,client= LOG: 00000: archive recovery complete
2026-07-23 09:07:29.156 UTC postgres[156740]: [6a61d9cc.26444-146]
db=,user=,app=,client= LOCATION: exitArchiveRecovery, xlog.c:5762
2026-07-23 09:07:29.157 UTC postgres[156740]: [6a61d9cc.26444-147]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E.history" from archive: child process exited with exit code 1
2026-07-23 09:07:29.157 UTC postgres[156740]: [6a61d9cc.26444-148]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:07:29.158 UTC postgres[156740]: [6a61d9cc.26444-149]
db=,user=,app=,client= DEBUG: 00000: MultiXactId wrap limit is 3813095538,
limited by database with OID 25748
2026-07-23 09:07:29.158 UTC postgres[156740]: [6a61d9cc.26444-150]
db=,user=,app=,client= LOCATION: SetMultiXactIdLimit, multixact.c:2370
2026-07-23 09:07:29.158 UTC postgres[156740]: [6a61d9cc.26444-151]
db=,user=,app=,client= DEBUG: 00000: oldest MultiXactId member is at offset
85204015
2026-07-23 09:07:29.158 UTC postgres[156740]: [6a61d9cc.26444-152]
db=,user=,app=,client= LOCATION: SetOffsetVacuumLimit, multixact.c:2704
2026-07-23 09:07:29.158 UTC postgres[156740]: [6a61d9cc.26444-153]
db=,user=,app=,client= DEBUG: 00000: MultiXact member stop limit is now
85124352 based on MultiXact 1665611891
2026-07-23 09:07:29.158 UTC postgres[156740]: [6a61d9cc.26444-154]
db=,user=,app=,client= LOCATION: SetOffsetVacuumLimit, multixact.c:2733
2026-07-23 09:07:29.159 UTC postgres[156740]: [6a61d9cc.26444-155]
db=,user=,app=,client= DEBUG: 00000: attempting to remove WAL segments
newer than log file 0000000F0000DB74000000BB
2026-07-23 09:07:29.159 UTC postgres[156740]: [6a61d9cc.26444-156]
db=,user=,app=,client= LOCATION: RemoveNonParentXlogFiles, xlog.c:4215
2026-07-23 09:07:29.159 UTC postgres[156740]: [6a61d9cc.26444-157]
db=,user=,app=,client= DEBUG: 00000: recycled write-ahead log file
"0000000E0000DB74000000C3"
2026-07-23 09:07:29.159 UTC postgres[156740]: [6a61d9cc.26444-158]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4282
2026-07-23 09:07:29.159 UTC postgres[156740]: [6a61d9cc.26444-159]
db=,user=,app=,client= DEBUG: 00000: recycled write-ahead log file
"0000000E0000DB74000000C9"
2026-07-23 09:07:29.159 UTC postgres[156740]: [6a61d9cc.26444-160]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4282
2026-07-23 09:07:29.159 UTC postgres[156740]: [6a61d9cc.26444-161]
db=,user=,app=,client= DEBUG: 00000: recycled write-ahead log file
"0000000E0000DB74000000CA"
2026-07-23 09:07:29.159 UTC postgres[156740]: [6a61d9cc.26444-162]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4282
2026-07-23 09:07:29.160 UTC postgres[156740]: [6a61d9cc.26444-163]
db=,user=,app=,client= DEBUG: 00000: recycled write-ahead log file
"0000000E0000DB74000000CF"
2026-07-23 09:07:29.160 UTC postgres[156740]: [6a61d9cc.26444-164]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4282
2026-07-23 09:07:29.160 UTC postgres[156740]: [6a61d9cc.26444-165]
db=,user=,app=,client= DEBUG: 00000: recycled write-ahead log file
"0000000E0000DB74000000C4"
2026-07-23 09:07:29.160 UTC postgres[156740]: [6a61d9cc.26444-166]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4282
2026-07-23 09:07:29.160 UTC postgres[156740]: [6a61d9cc.26444-167]
db=,user=,app=,client= DEBUG: 00000: recycled write-ahead log file
"0000000E0000DB74000000BE"
2026-07-23 09:07:29.160 UTC postgres[156740]: [6a61d9cc.26444-168]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4282
2026-07-23 09:07:29.160 UTC postgres[156740]: [6a61d9cc.26444-169]
db=,user=,app=,client= DEBUG: 00000: recycled write-ahead log file
"0000000E0000DB74000000C0"
2026-07-23 09:07:29.160 UTC postgres[156740]: [6a61d9cc.26444-170]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4282
2026-07-23 09:07:29.161 UTC postgres[156740]: [6a61d9cc.26444-171]
db=,user=,app=,client= DEBUG: 00000: recycled write-ahead log file
"0000000E0000DB74000000CB"
2026-07-23 09:07:29.161 UTC postgres[156740]: [6a61d9cc.26444-172]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4282
2026-07-23 09:07:29.161 UTC postgres[156740]: [6a61d9cc.26444-173]
db=,user=,app=,client= DEBUG: 00000: recycled write-ahead log file
"0000000E0000DB74000000CE"
2026-07-23 09:07:29.161 UTC postgres[156740]: [6a61d9cc.26444-174]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4282
2026-07-23 09:07:29.161 UTC postgres[156740]: [6a61d9cc.26444-175]
db=,user=,app=,client= DEBUG: 00000: recycled write-ahead log file
"0000000E0000DB74000000BF"
2026-07-23 09:07:29.161 UTC postgres[156740]: [6a61d9cc.26444-176]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4282
2026-07-23 09:07:29.161 UTC postgres[156740]: [6a61d9cc.26444-177]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000D0"
2026-07-23 09:07:29.161 UTC postgres[156740]: [6a61d9cc.26444-178]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.162 UTC postgres[156740]: [6a61d9cc.26444-179]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000C7"
2026-07-23 09:07:29.162 UTC postgres[156740]: [6a61d9cc.26444-180]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.163 UTC postgres[156740]: [6a61d9cc.26444-181]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000D2"
2026-07-23 09:07:29.163 UTC postgres[156740]: [6a61d9cc.26444-182]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.164 UTC postgres[156740]: [6a61d9cc.26444-183]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000C5"
2026-07-23 09:07:29.164 UTC postgres[156740]: [6a61d9cc.26444-184]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.164 UTC postgres[156740]: [6a61d9cc.26444-185]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000BD"
2026-07-23 09:07:29.164 UTC postgres[156740]: [6a61d9cc.26444-186]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.165 UTC postgres[156740]: [6a61d9cc.26444-187]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000BC"
2026-07-23 09:07:29.165 UTC postgres[156740]: [6a61d9cc.26444-188]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.166 UTC postgres[156740]: [6a61d9cc.26444-189]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000C8"
2026-07-23 09:07:29.166 UTC postgres[156740]: [6a61d9cc.26444-190]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.167 UTC postgres[156740]: [6a61d9cc.26444-191]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000C2"
2026-07-23 09:07:29.167 UTC postgres[156740]: [6a61d9cc.26444-192]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.167 UTC postgres[156740]: [6a61d9cc.26444-193]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000C6"
2026-07-23 09:07:29.167 UTC postgres[156740]: [6a61d9cc.26444-194]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.168 UTC postgres[156740]: [6a61d9cc.26444-195]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000D1"
2026-07-23 09:07:29.168 UTC postgres[156740]: [6a61d9cc.26444-196]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.169 UTC postgres[156740]: [6a61d9cc.26444-197]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000CD"
2026-07-23 09:07:29.169 UTC postgres[156740]: [6a61d9cc.26444-198]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.170 UTC postgres[156740]: [6a61d9cc.26444-199]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000CC"
2026-07-23 09:07:29.170 UTC postgres[156740]: [6a61d9cc.26444-200]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.171 UTC postgres[156740]: [6a61d9cc.26444-201]
db=,user=,app=,client= DEBUG: 00000: removing write-ahead log file
"0000000E0000DB74000000C1"
2026-07-23 09:07:29.171 UTC postgres[156740]: [6a61d9cc.26444-202]
db=,user=,app=,client= LOCATION: RemoveXlogFile, xlog.c:4294
2026-07-23 09:07:29.173 UTC postgres[156740]: [6a61d9cc.26444-203]
db=,user=,app=,client= DEBUG: 00000: release all standby locks
2026-07-23 09:07:29.173 UTC postgres[156740]: [6a61d9cc.26444-204]
db=,user=,app=,client= LOCATION: StandbyReleaseAllLocks, standby.c:1056
2026-07-23 09:07:29.173 UTC postgres[156745]: [6a61d9cc.26449-3]
db=,user=,app=,client= LOG: 00000: checkpoint starting: force
2026-07-23 09:07:29.173 UTC postgres[156745]: [6a61d9cc.26449-4]
db=,user=,app=,client= LOCATION: LogCheckpointStart, xlog.c:8920
2026-07-23 09:07:29.173 UTC postgres[156745]: [6a61d9cc.26449-5]
db=,user=,app=,client= DEBUG: 00000: performing replication slot checkpoint
2026-07-23 09:07:29.173 UTC postgres[156745]: [6a61d9cc.26449-6]
db=,user=,app=,client= LOCATION: CheckPointReplicationSlots, slot.c:1418
2026-07-23 09:07:29.193 UTC postgres[156983]: [6a61d9d1.26537-1]
db=,user=,app=,client= DEBUG: 00000: autovacuum launcher started
2026-07-23 09:07:29.193 UTC postgres[156983]: [6a61d9d1.26537-2]
db=,user=,app=,client= LOCATION: AutoVacLauncherMain, autovacuum.c:446
2026-07-23 09:07:29.193 UTC postgres[156730]: [6a61d9cb.2643a-25]
db=,user=,app=,client= DEBUG: 00000: starting background worker process
"logical replication launcher"
2026-07-23 09:07:29.193 UTC postgres[156730]: [6a61d9cb.2643a-26]
db=,user=,app=,client= LOCATION: do_start_bgworker, postmaster.c:5828
2026-07-23 09:07:29.193 UTC postgres[156730]: [6a61d9cb.2643a-27]
db=,user=,app=,client= LOG: 00000: database system is ready to accept
connections
2026-07-23 09:07:29.193 UTC postgres[156730]: [6a61d9cb.2643a-28]
db=,user=,app=,client= LOCATION: reaper, postmaster.c:3079
2026-07-23 09:07:29.194 UTC postgres[156771]: [6a61d9cd.26463-1]
db=,user=,app=,client= DEBUG: 00000: received inquiry for database 0
2026-07-23 09:07:29.194 UTC postgres[156771]: [6a61d9cd.26463-2]
db=,user=,app=,client= LOCATION: pgstat_recv_inquiry, pgstat.c:4730
2026-07-23 09:07:29.194 UTC postgres[156771]: [6a61d9cd.26463-3]
db=,user=,app=,client= DEBUG: 00000: writing stats file
"pg_stat_tmp/global.stat"
2026-07-23 09:07:29.194 UTC postgres[156771]: [6a61d9cd.26463-4]
db=,user=,app=,client= LOCATION: pgstat_write_statsfiles, pgstat.c:3624
2026-07-23 09:07:29.194 UTC postgres[156771]: [6a61d9cd.26463-5]
db=,user=,app=,client= DEBUG: 00000: writing stats file
"pg_stat_tmp/db_0.stat"
2026-07-23 09:07:29.194 UTC postgres[156771]: [6a61d9cd.26463-6]
db=,user=,app=,client= LOCATION: pgstat_write_db_statsfile, pgstat.c:3809
2026-07-23 09:07:29.194 UTC postgres[156985]: [6a61d9d1.26539-1]
db=,user=,app=,client= DEBUG: 00000: logical replication launcher started
2026-07-23 09:07:29.194 UTC postgres[156985]: [6a61d9d1.26539-2]
db=,user=,app=,client= LOCATION: ApplyLauncherMain, launcher.c:801
2026-07-23 09:07:29.194 UTC postgres[156984]: [6a61d9d1.26538-1]
db=,user=,app=,client= DEBUG: 00000: archived write-ahead log file
"0000000F.history"
2026-07-23 09:07:29.194 UTC postgres[156984]: [6a61d9d1.26538-2]
db=,user=,app=,client= LOCATION: pgarch_archiveXlog, pgarch.c:622
2026-07-23 09:07:29.195 UTC postgres[156984]: [6a61d9d1.26538-3]
db=,user=,app=,client= DEBUG: 00000: archived write-ahead log file
"0000000E0000DB74000000BB.partial"
2026-07-23 09:07:29.195 UTC postgres[156984]: [6a61d9d1.26538-4]
db=,user=,app=,client= LOCATION: pgarch_archiveXlog, pgarch.c:622

#
# postgresql-14 14.23-1.pgdg11+1
#

# cat /tank/restore/postgresql/main/postgresql.log
2026-07-23 08:58:52.746 UTC postgres[146671]: [6a61d7cc.23cef-1]
db=,user=,app=,client= DEBUG: 00000: registering background worker "logical
replication launcher"
2026-07-23 08:58:52.746 UTC postgres[146671]: [6a61d7cc.23cef-2]
db=,user=,app=,client= LOCATION: RegisterBackgroundWorker, bgworker.c:895
2026-07-23 08:58:52.746 UTC postgres[146671]: [6a61d7cc.23cef-3]
db=,user=,app=,client= DEBUG: 00000: loaded library "pg_stat_statements"
2026-07-23 08:58:52.746 UTC postgres[146671]: [6a61d7cc.23cef-4]
db=,user=,app=,client= LOCATION: load_libraries, miscinit.c:1702
2026-07-23 08:58:52.748 UTC postgres[146671]: [6a61d7cc.23cef-5]
db=,user=,app=,client= DEBUG: 00000: mmap(82128666624) with MAP_HUGETLB
failed, huge pages disabled: Invalid argument
2026-07-23 08:58:52.748 UTC postgres[146671]: [6a61d7cc.23cef-6]
db=,user=,app=,client= LOCATION: CreateAnonymousSegment, pg_shmem.c:595
2026-07-23 08:58:53.558 UTC postgres[146671]: [6a61d7cc.23cef-7]
db=,user=,app=,client= DEBUG: 00000: dynamic shared memory system will
support 11419 segments
2026-07-23 08:58:53.558 UTC postgres[146671]: [6a61d7cc.23cef-8]
db=,user=,app=,client= LOCATION: dsm_postmaster_startup, dsm.c:169
2026-07-23 08:58:53.558 UTC postgres[146671]: [6a61d7cc.23cef-9]
db=,user=,app=,client= DEBUG: 00000: created dynamic shared memory control
segment 1483882450 (456776 bytes)
2026-07-23 08:58:53.558 UTC postgres[146671]: [6a61d7cc.23cef-10]
db=,user=,app=,client= LOCATION: dsm_postmaster_startup, dsm.c:193
2026-07-23 08:58:53.560 UTC postgres[146671]: [6a61d7cc.23cef-11]
db=,user=,app=,client= DEBUG: 00000: max_safe_fds = 987, usable_fds = 1000,
already_open = 3
2026-07-23 08:58:53.560 UTC postgres[146671]: [6a61d7cc.23cef-12]
db=,user=,app=,client= LOCATION: set_max_safe_fds, fd.c:1023
2026-07-23 08:58:53.561 UTC postgres[146671]: [6a61d7cc.23cef-13]
db=,user=,app=,client= LOG: 00000: starting PostgreSQL 14.23 (Debian
14.23-1.pgdg11+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6)
10.2.1 20210110, 64-bit
2026-07-23 08:58:53.561 UTC postgres[146671]: [6a61d7cc.23cef-14]
db=,user=,app=,client= LOCATION: PostmasterMain, postmaster.c:1141
2026-07-23 08:58:53.561 UTC postgres[146671]: [6a61d7cc.23cef-15]
db=,user=,app=,client= LOG: 00000: listening on IPv4 address "127.0.0.1",
port 5433
2026-07-23 08:58:53.561 UTC postgres[146671]: [6a61d7cc.23cef-16]
db=,user=,app=,client= LOCATION: StreamServerPort, pqcomm.c:578
2026-07-23 08:58:53.561 UTC postgres[146671]: [6a61d7cc.23cef-17]
db=,user=,app=,client= LOG: 00000: listening on Unix socket
"/tank/restore/postgresql/main/.s.PGSQL.5433"
2026-07-23 08:58:53.561 UTC postgres[146671]: [6a61d7cc.23cef-18]
db=,user=,app=,client= LOCATION: StreamServerPort, pqcomm.c:573
2026-07-23 08:58:53.566 UTC postgres[146674]: [6a61d7cd.23cf2-1]
db=,user=,app=,client= LOG: 00000: database system was shut down in
recovery at 2026-07-23 00:00:04 UTC
2026-07-23 08:58:53.566 UTC postgres[146674]: [6a61d7cd.23cf2-2]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6586
2026-07-23 08:58:53.566 UTC postgres[146674]: [6a61d7cd.23cf2-3]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000F.history" from archive: child process exited with exit code 1
2026-07-23 08:58:53.566 UTC postgres[146674]: [6a61d7cd.23cf2-4]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 08:58:53.566 UTC postgres[146674]: [6a61d7cd.23cf2-5]
db=,user=,app=,client= LOG: 00000: entering standby mode
2026-07-23 08:58:53.566 UTC postgres[146674]: [6a61d7cd.23cf2-6]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6677
2026-07-23 08:58:53.567 UTC postgres[146674]: [6a61d7cd.23cf2-7]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E.history" from archive: child process exited with exit code 1
2026-07-23 08:58:53.567 UTC postgres[146674]: [6a61d7cd.23cf2-8]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 08:58:53.567 UTC postgres[146674]: [6a61d7cd.23cf2-9]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B6" from archive: child process exited with exit code
1
2026-07-23 08:58:53.567 UTC postgres[146674]: [6a61d7cd.23cf2-10]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 08:58:53.568 UTC postgres[146674]: [6a61d7cd.23cf2-11]
db=,user=,app=,client= DEBUG: 00000: checkpoint record is at DB74/B6D42948
2026-07-23 08:58:53.568 UTC postgres[146674]: [6a61d7cd.23cf2-12]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6891
2026-07-23 08:58:53.568 UTC postgres[146674]: [6a61d7cd.23cf2-13]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000AB" from archive: child process exited with exit code
1
2026-07-23 08:58:53.568 UTC postgres[146674]: [6a61d7cd.23cf2-14]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-15]
db=,user=,app=,client= DEBUG: 00000: redo record is at DB74/ABB108C0;
shutdown false
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-16]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6975
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-17]
db=,user=,app=,client= DEBUG: 00000: next transaction ID: 53692118865; next
OID: 1695415741
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-18]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6979
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-19]
db=,user=,app=,client= DEBUG: 00000: next MultiXactId: 1675471103; next
MultiXactOffset: 114139422
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-20]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6983
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-21]
db=,user=,app=,client= DEBUG: 00000: oldest unfrozen transaction ID:
2009689764, in database 25748
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-22]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6986
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-23]
db=,user=,app=,client= DEBUG: 00000: oldest MultiXactId: 1665611891, in
database 25748
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-24]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6989
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-25]
db=,user=,app=,client= DEBUG: 00000: commit timestamp Xid oldest/newest:
2009689764/2152511312
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-26]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:6992
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-27]
db=,user=,app=,client= DEBUG: 00000: transaction ID wrap limit is
4157173411, limited by database with OID 25748
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-28]
db=,user=,app=,client= LOCATION: SetTransactionIdLimit, varsup.c:427
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-29]
db=,user=,app=,client= DEBUG: 00000: MultiXactId wrap limit is 3813095538,
limited by database with OID 25748
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-30]
db=,user=,app=,client= LOCATION: SetMultiXactIdLimit, multixact.c:2419
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-31]
db=,user=,app=,client= DEBUG: 00000: starting up replication slots
2026-07-23 08:58:53.570 UTC postgres[146674]: [6a61d7cd.23cf2-32]
db=,user=,app=,client= LOCATION: StartupReplicationSlots, slot.c:1454
2026-07-23 08:58:53.571 UTC postgres[146674]: [6a61d7cd.23cf2-33]
db=,user=,app=,client= DEBUG: 00000: xmin required by slots: data 0,
catalog 0
2026-07-23 08:58:53.571 UTC postgres[146674]: [6a61d7cd.23cf2-34]
db=,user=,app=,client= LOCATION: ProcArraySetReplicationSlotXmin,
procarray.c:3999
2026-07-23 08:58:53.571 UTC postgres[146674]: [6a61d7cd.23cf2-35]
db=,user=,app=,client= DEBUG: 00000: starting up replication origin
progress state
2026-07-23 08:58:53.571 UTC postgres[146674]: [6a61d7cd.23cf2-36]
db=,user=,app=,client= LOCATION: StartupReplicationOrigin, origin.c:706
2026-07-23 08:58:53.572 UTC postgres[146674]: [6a61d7cd.23cf2-37]
db=,user=,app=,client= DEBUG: 00000: resetting unlogged relations: cleanup
1 init 0
2026-07-23 08:58:53.572 UTC postgres[146674]: [6a61d7cd.23cf2-38]
db=,user=,app=,client= LOCATION: ResetUnloggedRelations, reinit.c:55
2026-07-23 08:58:53.573 UTC postgres[146674]: [6a61d7cd.23cf2-39]
db=,user=,app=,client= DEBUG: 00000: initializing for hot standby
2026-07-23 08:58:53.573 UTC postgres[146674]: [6a61d7cd.23cf2-40]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:7291
2026-07-23 08:58:53.573 UTC postgres[146674]: [6a61d7cd.23cf2-41]
db=,user=,app=,client= LOG: 00000: redo starts at DB74/ABB108C0
2026-07-23 08:58:53.573 UTC postgres[146674]: [6a61d7cd.23cf2-42]
db=,user=,app=,client= LOCATION: StartupXLOG, xlog.c:7427
2026-07-23 08:58:53.573 UTC postgres[146674]: [6a61d7cd.23cf2-43]
db=,user=,app=,client= DEBUG: 00000: could not forward fsync request
because request queue is full
2026-07-23 08:58:53.573 UTC postgres[146674]: [6a61d7cd.23cf2-44]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/ABB108C0 for Heap/LOCK:
off 44: xid 2152511311: flags 0x00 LOCK_ONLY EXCL_LOCK ; blkref #0: rel
1663/26159/27449, blk 134678 FPW
2026-07-23 08:58:53.573 UTC postgres[146674]: [6a61d7cd.23cf2-45]
db=,user=,app=,client= LOCATION: register_dirty_segment, md.c:994
2026-07-23 08:58:53.574 UTC postgres[146674]: [6a61d7cd.23cf2-46]
db=,user=,app=,client= DEBUG: 00000: could not forward fsync request
because request queue is full
2026-07-23 08:58:53.574 UTC postgres[146674]: [6a61d7cd.23cf2-47]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/ABB10FB8 for Heap/INSERT:
off 7 flags 0x18; blkref #0: rel 1663/26159/27465, blk 3873 FPW
2026-07-23 08:58:53.574 UTC postgres[146674]: [6a61d7cd.23cf2-48]
db=,user=,app=,client= LOCATION: register_dirty_segment, md.c:994
2026-07-23 08:58:53.574 UTC postgres[146674]: [6a61d7cd.23cf2-49]
db=,user=,app=,client= DEBUG: 00000: could not forward fsync request
because request queue is full
2026-07-23 08:58:53.574 UTC postgres[146674]: [6a61d7cd.23cf2-50]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/ABB13378 for Heap/LOCK:
off 5: xid 2152511313: flags 0x00 LOCK_ONLY EXCL_LOCK KEYS_UPDATED ; blkref
#0: rel 1663/25483/25534, blk 139240 FPW
2026-07-23 08:58:53.574 UTC postgres[146674]: [6a61d7cd.23cf2-51]
db=,user=,app=,client= LOCATION: register_dirty_segment, md.c:994
2026-07-23 08:58:53.574 UTC postgres[146679]: [6a61d7cd.23cf7-1]
db=,user=,app=,client= DEBUG: 00000: checkpointer updated shared memory
configuration values
2026-07-23 08:58:53.574 UTC postgres[146679]: [6a61d7cd.23cf7-2]
db=,user=,app=,client= LOCATION: UpdateSharedMemoryConfig,
checkpointer.c:1340
2026-07-23 08:58:53.576 UTC postgres[146674]: [6a61d7cd.23cf2-52]
db=,user=,app=,client= DEBUG: 00000: recovery snapshots are now enabled
2026-07-23 08:58:53.576 UTC postgres[146674]: [6a61d7cd.23cf2-53]
db=,user=,app=,client= CONTEXT: WAL redo at DB74/ABB2CC00 for
Standby/RUNNING_XACTS: nextXid 2152511319 latestCompletedXid 2152511318
oldestRunningXid 2152511319
2026-07-23 08:58:53.576 UTC postgres[146674]: [6a61d7cd.23cf2-54]
db=,user=,app=,client= LOCATION: ProcArrayApplyRecoveryInfo,
procarray.c:1311
2026-07-23 08:58:53.601 UTC postgres[146674]: [6a61d7cd.23cf2-55]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000AC" from archive: child process exited with exit code
1
2026-07-23 08:58:53.601 UTC postgres[146674]: [6a61d7cd.23cf2-56]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 08:58:53.683 UTC postgres[146674]: [6a61d7cd.23cf2-57]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000AD" from archive: child process exited with exit code
1
2026-07-23 08:58:53.683 UTC postgres[146674]: [6a61d7cd.23cf2-58]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 08:58:53.783 UTC postgres[146674]: [6a61d7cd.23cf2-59]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000AE" from archive: child process exited with exit code
1
2026-07-23 08:58:53.783 UTC postgres[146674]: [6a61d7cd.23cf2-60]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 08:58:53.862 UTC postgres[146674]: [6a61d7cd.23cf2-61]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000AF" from archive: child process exited with exit code
1
2026-07-23 08:58:53.862 UTC postgres[146674]: [6a61d7cd.23cf2-62]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 08:58:53.941 UTC postgres[146674]: [6a61d7cd.23cf2-63]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B0" from archive: child process exited with exit code
1
2026-07-23 08:58:53.941 UTC postgres[146674]: [6a61d7cd.23cf2-64]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 08:58:54.040 UTC postgres[146674]: [6a61d7cd.23cf2-65]
db=,user=,app=,client= DEBUG: 00000: could not restore file
"0000000E0000DB74000000B1" from archive: child process exited with exit code
1
2026-07-23 08:58:54.040 UTC postgres[146674]: [6a61d7cd.23cf2-66]
db=,user=,app=,client= LOCATION: RestoreArchivedFile, xlogarchive.c:259
2026-07-23 09:03:53.674 UTC postgres[146679]: [6a61d7cd.23cf7-3]
db=,user=,app=,client= DEBUG: 00000: skipping restartpoint, already
performed at 0/0
2026-07-23 09:03:53.674 UTC postgres[146679]: [6a61d7cd.23cf7-4]
db=,user=,app=,client= LOCATION: CreateRestartPoint, xlog.c:9823
2026-07-23 09:04:08.687 UTC postgres[146679]: [6a61d7cd.23cf7-5]
db=,user=,app=,client= DEBUG: 00000: skipping restartpoint, already
performed at 0/0
2026-07-23 09:04:08.687 UTC postgres[146679]: [6a61d7cd.23cf7-6]
db=,user=,app=,client= LOCATION: CreateRestartPoint, xlog.c:9823
2026-07-23 09:04:23.699 UTC postgres[146679]: [6a61d7cd.23cf7-7]
db=,user=,app=,client= DEBUG: 00000: skipping restartpoint, already
performed at 0/0
2026-07-23 09:04:23.699 UTC postgres[146679]: [6a61d7cd.23cf7-8]
db=,user=,app=,client= LOCATION: CreateRestartPoint, xlog.c:9823
2026-07-23 09:04:38.714 UTC postgres[146679]: [6a61d7cd.23cf7-9]
db=,user=,app=,client= DEBUG: 00000: skipping restartpoint, already
performed at 0/0
2026-07-23 09:04:38.714 UTC postgres[146679]: [6a61d7cd.23cf7-10]
db=,user=,app=,client= LOCATION: CreateRestartPoint, xlog.c:9823

#
# Stack trace of a PG 14.23 hang
#

# ps -edf | grep postgre | grep restore
ovh 578794 1 0 15:38 ? 00:00:00
/usr/lib/postgresql/14/bin/postgres -D /tank/restore/postgresql/main
ovh 578798 578794 0 15:38 ? 00:00:00 postgres:
cluster30_restore: startup recovering 0000000E0000DB74000000B1
ovh 578803 578794 0 15:38 ? 00:00:00 postgres:
cluster30_restore: checkpointer
ovh 578804 578794 0 15:38 ? 00:00:00 postgres:
cluster30_restore: background writer

# eu-stack -p 578794
PID 578794 - process
TID 578794:
#0 0x00007fbb13e89e96 __select
#1 0x0000555a17054436 ServerLoop
#2 0x0000555a17056974 PostmasterMain
#3 0x0000555a16dc7944 main
#4 0x00007fbb13dbbd7a __libc_start_main
#5 0x0000555a16dc79ea _start