RE: BUG #17375: RECOVERY TARGET TIME RESTORE IS FAILING TO START SERVER

Hello,

The problem is that we are providing a time target that Postgres does not know how to reach. This is because there are no transactions in between the backups.
For example, if I take two backups but don't have any transactions in between them the restore will fail to any point in time between them.
However, if we add a transaction between the backups and restore to a time before that transaction then the restore is successful.

Prior to 13, a missed target would be ignored, and recovery would play to the end of the WAL. So, this issue was not seen with earlier versions.
Please suggest how can we achieve a successful restore in this case.

Thanks and Regards,
Ganesh Kishan

-----Original Message-----
From: PG Bug reporting form <noreply(at)postgresql(dot)org>
Sent: 20 January 2022 20:06
To: pgsql-bugs(at)lists(dot)postgresql(dot)org
Cc: B Ganesh Kishan <bkishan(at)commvault(dot)com>
Subject: BUG #17375: RECOVERY TARGET TIME RESTORE IS FAILING TO START SERVER

External email. Inspect before opening.

The following bug has been logged on the website:

Bug reference: 17375
Logged by: Ganesh Kishan
Email address: bkishan(at)commvault(dot)com
PostgreSQL version: 13.5
Operating system: RHEL 7.6
Description:

Hi Team,

I am trying to restore a PG13 server to a particular point in time.

These are the recovery settings in postgresql.conf:
restore_command = 'cp /var/lib/pgsql/13/wal/%f %p'
recovery_end_command = 'touch
/var/lib/pgsql/13/data_small/recovery.done.cv'
recovery_target_time = '2022-01-20 07:22:00GMT'
recovery_target_action = promote

I see the server fails to start with below error in :

-bash-4.2$ tail -f postgresql-Thu.log
2022-01-20 19:57:10.937 IST [34742] LOG: starting PostgreSQL 13.5 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bit
2022-01-20 19:57:10.938 IST [34742] LOG: listening on IPv4 address "0.0.0.0", port 5432
2022-01-20 19:57:10.938 IST [34742] LOG: listening on IPv6 address "::", port 5432
2022-01-20 19:57:10.938 IST [34742] LOG: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-01-20 19:57:10.939 IST [34742] LOG: listening on Unix socket "/tmp/.s.PGSQL.5432"
2022-01-20 19:57:10.942 IST [34744] LOG: database system was interrupted; last known up at 2022-01-20 12:10:21 IST
cp: cannot stat ‘/var/lib/pgsql/13/wal/00000003.history’: No such file or directory
2022-01-20 19:57:10.967 IST [34744] LOG: starting point-in-time recovery to
2022-01-20 12:52:00+05:30
2022-01-20 19:57:10.970 IST [34744] LOG: restored log file "00000002.history" from archive
2022-01-20 19:57:10.988 IST [34744] LOG: restored log file "000000020000000000000011" from archive
2022-01-20 19:57:11.190 IST [34744] LOG: redo starts at 0/11000060
2022-01-20 19:57:11.190 IST [34744] LOG: consistent recovery state reached at 0/11000170
2022-01-20 19:57:11.191 IST [34742] LOG: database system is ready to accept read only connections
2022-01-20 19:57:11.208 IST [34744] LOG: restored log file "000000020000000000000012" from archive
2022-01-20 19:57:11.350 IST [34744] LOG: restored log file "000000020000000000000013" from archive
2022-01-20 19:57:11.500 IST [34744] LOG: restored log file "000000020000000000000014" from archive
2022-01-20 19:57:11.626 IST [34744] LOG: restored log file "000000020000000000000015" from archive
2022-01-20 19:57:11.795 IST [34744] LOG: restored log file "000000020000000000000016" from archive
2022-01-20 19:57:11.890 IST [34744] LOG: restored log file "000000020000000000000017" from archive
2022-01-20 19:57:12.041 IST [34744] LOG: restored log file "000000020000000000000018" from archive
2022-01-20 19:57:12.089 IST [34744] LOG: restored log file "000000020000000000000019" from archive
2022-01-20 19:57:12.126 IST [34744] LOG: restored log file "00000002000000000000001A" from archive
2022-01-20 19:57:12.165 IST [34744] LOG: restored log file "00000002000000000000001B" from archive
2022-01-20 19:57:12.196 IST [34744] LOG: restored log file "00000002000000000000001C" from archive
2022-01-20 19:57:12.244 IST [34744] LOG: restored log file "00000002000000000000001D" from archive
cp: cannot stat ‘/var/lib/pgsql/13/wal/00000002000000000000001E’: No such file or directory
2022-01-20 19:57:12.320 IST [34744] LOG: redo done at 0/1D000148
2022-01-20 19:57:12.320 IST [34744] FATAL: recovery ended before configured recovery target was reached
2022-01-20 19:57:12.322 IST [34742] LOG: startup process (PID 34744) exited with exit code 1
2022-01-20 19:57:12.322 IST [34742] LOG: terminating any other active server processes
2022-01-20 19:57:12.325 IST [34742] LOG: database system is shut down

For restoring till the specified time we need 000000020000000000000016 log which is already present.
Still its failing with: FATAL: recovery ended before configured recovery target was reached.
Same steps are working with PostgreSQL 12 but failing for PostgreSQL13. Did anything change in this part?