BUG #17218: Cluster recovery is not working properly. - Mailing list pgsql-bugs

The following bug has been logged on the website:

Bug reference:      17218
Logged by:          Reijo Suhonen
Email address:      reijo.suhonen@valtori.fi
PostgreSQL version: 14.0
Operating system:   Red Hat Enterprise Linux Server 7.9 (Maipo)
Description:

Restoring a cluster to a specific point in time does not work. The restore
ends with the error message "FATAL, XX000," recovery ended before configured
recovery target was reached " and the cluster goes down.
The same test with version 12 works normally.


PostgreSQL version:

postgres=# SELECT version();
                                                 version
---------------------------------------------------------------------------------------------------------
 PostgreSQL 14.0 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5
20150623 (Red Hat 4.8.5-44), 64-bit
(1 row)



Barman version:

-bash-4.2$ barman -v
2.14

Barman by EnterpriseDB (www.enterprisedb.com)


Barman backups:

-bash-4.2$ barman list-backup testserver02-versio14
testserver02-versio14 20211011T092632 - Mon Oct 11 09:26:42 2021 - Size:
986.0 MiB - WAL Size: 46.8 MiB


Barman restore:

-bash-4.2$  barman recover --target-time "2021-10-11 09:28:01"
--remote-ssh-command "ssh postgres@testserver02" testserver02-versio14
20211011T092632 /var/lib/pgsql/14/versio14
Starting remote restore for server testserver02-versio14 using backup
20211011T092632
Destination directory: /var/lib/pgsql/14/versio14
Remote command: ssh postgres@testserver02
Doing PITR. Recovery target time: '2021-10-11 09:28:01+03:00'
Using safe horizon time for smart rsync copy: 2021-10-11
09:26:32.245735+03:00
Copying the base backup.
Copying required WAL segments.
Generating recovery configuration
Identify dangerous settings in destination directory.

WARNING
You are required to review the following options as potentially dangerous

postgresql.conf line 796: include_dir = 'conf.d'

Recovery completed (start time: 2021-10-11 12:32:34.069804, elapsed time: 7
seconds)

Your PostgreSQL server has been successfully prepared for recovery!


Cluster postgresql.auto.conf:

# Do not edit this file manually!
# It will be overwritten by the ALTER SYSTEM command.
restore_command = 'cp barman_wal/%f %p'
recovery_end_command = 'rm -fr barman_wal'
recovery_target_time = '2021-10-11 09:28:01'


Cluster start and recovery:


[root@testserver02 versio14]# tail -f postgres-Mon.csv
2021-10-11 12:33:17.918 EEST,,,18888,,616404dd.49c8,1,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"ending log output to stderr",,"Future log output will go
to log destination ""csvlog"".",,,,,,,"","postmaster",
                                                                    ,0
2021-10-11 12:33:17.918 EEST,,,18888,,616404dd.49c8,2,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"starting PostgreSQL 14.0 on x86_64-pc-linux-gnu, compiled
by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-44), 64-bi

t",,,,,,,,,"","postmaster",,0
2021-10-11 12:33:17.919 EEST,,,18888,,616404dd.49c8,3,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"listening on IPv4 address ""0.0.0.0"", port
5632",,,,,,,,,"","postmaster",,0
2021-10-11 12:33:17.919 EEST,,,18888,,616404dd.49c8,4,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"listening on IPv6 address ""::"", port
5632",,,,,,,,,"","postmaster",,0
2021-10-11 12:33:17.921 EEST,,,18888,,616404dd.49c8,5,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"listening on Unix socket
""/var/run/postgresql/.s.PGSQL.5632""",,,,,,,,,"","postmaster",,0
2021-10-11 12:33:17.923 EEST,,,18888,,616404dd.49c8,6,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"listening on Unix socket
""/tmp/.s.PGSQL.5632""",,,,,,,,,"","postmaster",,0
2021-10-11 12:33:17.926 EEST,,,18891,,616404dd.49cb,1,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"database system was interrupted; last known up at
2021-10-11 09:26:32 EEST",,,,,,,,,"","startup",,0
2021-10-11 12:33:17.926 EEST,,,18891,,616404dd.49cb,2,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"creating missing WAL directory
""pg_wal/archive_status""",,,,,,,,,"","startup",,0
2021-10-11 12:33:17.941 EEST,,,18891,,616404dd.49cb,3,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"starting point-in-time recovery to 2021-10-11
09:28:01+03",,,,,,,,,"","startup",,0
2021-10-11 12:33:17.954 EEST,,,18891,,616404dd.49cb,4,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"restored log file ""000000010000000000000072"" from
archive",,,,,,,,,"","startup",,0
2021-10-11 12:33:17.979 EEST,,,18891,,616404dd.49cb,5,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"redo starts at 0/72000028",,,,,,,,,"","startup",,0
2021-10-11 12:33:17.981 EEST,,,18891,,616404dd.49cb,6,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"consistent recovery state reached at
0/72000138",,,,,,,,,"","startup",,0
2021-10-11 12:33:17.981 EEST,,,18888,,616404dd.49c8,7,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"database system is ready to accept read-only
connections",,,,,,,,,"","postmaster",,0
2021-10-11 12:33:17.995 EEST,,,18891,,616404dd.49cb,7,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"restored log file ""000000010000000000000073"" from
archive",,,,,,,,,"","startup",,0
2021-10-11 12:33:18.139 EEST,,,18891,,616404dd.49cb,8,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"restored log file ""000000010000000000000074"" from
archive",,,,,,,,,"","startup",,0
2021-10-11 12:33:18.282 EEST,,,18891,,616404dd.49cb,9,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"restored log file ""000000010000000000000075"" from
archive",,,,,,,,,"","startup",,0
2021-10-11 12:33:18.428 EEST,,,18891,,616404dd.49cb,10,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"restored log file ""000000010000000000000076"" from
archive",,,,,,,,,"","startup",,0
2021-10-11 12:33:18.576 EEST,,,18891,,616404dd.49cb,11,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"restored log file ""000000010000000000000077"" from
archive",,,,,,,,,"","startup",,0
2021-10-11 12:33:18.727 EEST,,,18891,,616404dd.49cb,12,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"restored log file ""000000010000000000000078"" from
archive",,,,,,,,,"","startup",,0
2021-10-11 12:33:18.877 EEST,,,18891,,616404dd.49cb,13,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"restored log file ""000000010000000000000079"" from
archive",,,,,,,,,"","startup",,0
2021-10-11 12:33:19.024 EEST,,,18891,,616404dd.49cb,14,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"restored log file ""00000001000000000000007A"" from
archive",,,,,,,,,"","startup",,0
2021-10-11 12:33:19.171 EEST,,,18891,,616404dd.49cb,15,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"restored log file ""00000001000000000000007B"" from
archive",,,,,,,,,"","startup",,0
2021-10-11 12:33:19.311 EEST,,,18891,,616404dd.49cb,16,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"redo done at 0/7BFFFF88 system usage: CPU: user: 0.82
s, system: 0.16 s, elapsed: 1.33 s",,,,,,,,,"","start
                                                                   up",,0
2021-10-11 12:33:19.311 EEST,,,18891,,616404dd.49cb,17,,2021-10-11 12:33:17
EEST,1/0,0,LOG,00000,"last completed transaction was at log time 2021-10-11
09:27:20.351213+03",,,,,,,,,"","startup",,0
2021-10-11 12:33:19.311 EEST,,,18891,,616404dd.49cb,18,,2021-10-11 12:33:17
EEST,1/0,0,FATAL,XX000,"recovery ended before configured recovery target was
reached",,,,,,,,,"","startup",,0
2021-10-11 12:33:19.316 EEST,,,18888,,616404dd.49c8,8,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"startup process (PID 18891) exited with exit code
1",,,,,,,,,"","postmaster",,0
2021-10-11 12:33:19.316 EEST,,,18888,,616404dd.49c8,9,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"terminating any other active server
processes",,,,,,,,,"","postmaster",,0
2021-10-11 12:33:19.318 EEST,,,18888,,616404dd.49c8,10,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"shutting down due to startup process
failure",,,,,,,,,"","postmaster",,0
2021-10-11 12:33:19.339 EEST,,,18888,,616404dd.49c8,11,,2021-10-11 12:33:17
EEST,,0,LOG,00000,"database system is shut down",,,,,,,,,"","postmaster",,0