FATAL: cannot connect to invalid database

[Michał Giza]

Hello,

I am encountering a problem when restoring the database using Barman.

postgres=# \c testowa
connection to server on socket "/run/postgresql/.s.PGSQL.5432" failed: FATAL:  cannot connect to invalid database "testowa"
HINT:  Use DROP DATABASE to drop invalid databases.
Previous connection kept
postgres=#

I am using pgpool three node cluster. Barman is connected to the master node (db01).

For testing, I created database testowa with one table and one record. Then, I created two backups.

[barman@barman ~]$ barman list-backup db01
db01 20240904T195830 - F - Wed Sep  4 10:34:50 2024 - Size: 45.7 MiB - WAL Size: 16.0 MiB
db01 20240904T195621 - F - Wed Sep  4 10:32:53 2024 - Size: 61.7 MiB - WAL Size: 32.0 MiB

After that, I dropped my test_db database and stopped clustet (pgpool and postgresql-16 services) on all three nodes. Recovery command:

barman recover db01 20240904T195621 --target-time="2024-09-04 10:33:53" --remote-ssh-command="ssh post...@192.168.1.35" /var/lib/pgsql/16/data

There were no errors in output and PostgreSQL service started without problems. The previously removed database is visible on list, but I cannot connect.

PostgreSQL logs:

2024-09-05 07:41:25.030 CEST [1802] LOG:  starting PostgreSQL 16.4 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20231218 (Red Hat 11.4.1-3), 64-bit
2024-09-05 07:41:25.030 CEST [1802] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2024-09-05 07:41:25.030 CEST [1802] LOG:  listening on IPv6 address "::", port 5432
2024-09-05 07:41:25.036 CEST [1802] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
2024-09-05 07:41:25.046 CEST [1802] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2024-09-05 07:41:25.052 CEST [1806] LOG:  database system was interrupted; last known up at 2024-09-04 10:32:47 CEST
2024-09-05 07:41:25.052 CEST [1806] LOG:  creating missing WAL directory "pg_wal/archive_status"
cp: cannot stat 'barman_wal/00000002.history': No such file or directory
2024-09-05 07:41:26.432 CEST [1806] LOG:  starting point-in-time recovery to 2024-09-04 10:33:53+02
2024-09-05 07:41:26.432 CEST [1806] LOG:  starting backup recovery with redo LSN 0/10000110, checkpoint LSN 0/10000148, on timeline ID 1
2024-09-05 07:41:26.437 CEST [1806] LOG:  restored log file "000000010000000000000010" from archive
2024-09-05 07:41:26.458 CEST [1806] LOG:  redo starts at 0/10000110
2024-09-05 07:41:26.462 CEST [1806] LOG:  restored log file "000000010000000000000011" from archive
2024-09-05 07:41:26.476 CEST [1806] LOG:  restored log file "000000010000000000000012" from archive
2024-09-05 07:41:26.491 CEST [1806] LOG:  restored log file "000000010000000000000013" from archive
2024-09-05 07:41:26.504 CEST [1806] LOG:  restored log file "000000010000000000000014" from archive
cp: cannot stat 'barman_wal/000000010000000000000015': No such file or directory
2024-09-05 07:41:26.523 CEST [1806] LOG:  completed backup recovery with redo LSN 0/10000110 and end LSN 0/100001E8
2024-09-05 07:41:26.523 CEST [1806] LOG:  consistent recovery state reached at 0/100001E8
2024-09-05 07:41:26.523 CEST [1802] LOG:  database system is ready to accept read-only connections
2024-09-05 07:41:26.532 CEST [1806] LOG:  recovery stopping before commit of transaction 753, time 2024-09-04 10:36:05.956082+02
2024-09-05 07:41:26.532 CEST [1806] LOG:  pausing at the end of recovery
2024-09-05 07:41:26.532 CEST [1806] HINT:  Execute pg_wal_replay_resume() to promote.
2024-09-05 07:41:36.093 CEST [1822] FATAL:  cannot connect to invalid database "testowa"
2024-09-05 07:41:36.093 CEST [1822] HINT:  Use DROP DATABASE to drop invalid databases.
2024-09-05 07:42:02.831 CEST [1825] ERROR:  requested starting point 0/16000000 is ahead of the WAL flush position of this server 0/14000528
2024-09-05 07:42:02.831 CEST [1825] STATEMENT:  START_REPLICATION SLOT "db01_barman" 0/16000000 TIMELINE 1
2024-09-05 07:43:02.226 CEST [1828] ERROR:  requested starting point 0/16000000 is ahead of the WAL flush position of this server 0/14000528
2024-09-05 07:43:02.226 CEST [1828] STATEMENT:  START_REPLICATION SLOT "db01_barman" 0/16000000 TIMELINE 1
2024-09-05 07:44:02.876 CEST [1831] ERROR:  requested starting point 0/16000000 is ahead of the WAL flush position of this server 0/14000528
2024-09-05 07:44:02.876 CEST [1831] STATEMENT:  START_REPLICATION SLOT "db01_barman" 0/16000000 TIMELINE 1
2024-09-05 07:45:02.322 CEST [1834] ERROR:  requested starting point 0/16000000 is ahead of the WAL flush position of this server 0/14000528
2024-09-05 07:45:02.322 CEST [1834] STATEMENT:  START_REPLICATION SLOT "db01_barman" 0/16000000 TIMELINE 1

PostgreSQL configuration is based on https://www.pgpool.net/docs/45/en/html/example-cluster.html. I created superuser barman in PostgreSQL and added pg_hba.conf entries:

CREATE ROLE barman WITH LOGIN SUPERUSER PASSWORD '<password>';

host    all             barman          192.168.1.45/32         trust
host    replication     barman          192.168.1.45/32         trust

Barman config:

[db01]
description = "master"
conninfo = host=192.168.1.35 user=barman port=5432 dbname=postgres
streaming_conninfo = host=192.168.1.35 user=barman port=5432
streaming_archiver = on
backup_method = postgres
slot_name = db01_barman
create_slot = auto
path_prefix = /usr/pgsql-16/bin

[Luca Ferrari]

On Thu, Sep 5, 2024 at 11:58 AM 'Michał Giza' via Barman, Backup and
Recovery Manager for PostgreSQL <pgba...@googlegroups.com> wrote:
> barman recover db01 20240904T195621 --target-time="2024-09-04 10:33:53" --remote-ssh-command="ssh post...@192.168.1.35" /var/lib/pgsql/16/data
>

> 2024-09-05 07:41:26.532 CEST [1806] LOG: recovery stopping before commit of transaction 753, time 2024-09-04 10:36:05.956082+02

It seems to me this is not the time you are expecting, hence it is not
the status you are expecting.

Luca

[Michał Giza]

Another example.

[barman@barman ~]$ barman list-backup db01

db01 20240905T205916 - F - Wed Sep  4 10:07:10 2024 - Size: 45.7 MiB - WAL Size: 0 B
db01 20240905T205714 - F - Wed Sep  4 10:06:35 2024 - Size: 45.7 MiB - WAL Size: 32.0 MiB

[barman@barman ~]$ barman recover db01 20240905T205714 --target-time="10:06:35" --remote-ssh-command="ssh postgres@192.1
68.1.35" /var/lib/pgsql/16/data
Starting remote restore for server db01 using backup 20240905T205714
Destination directory: /var/lib/pgsql/16/data
Remote command: ssh post...@192.168.1.35
WARNING: No time zone has been specified through '--target-time' command-line option. Barman assumed the same time zone from the Barman host.
Doing PITR. Recovery target time: '2024-09-05 10:06:35+02:00'
Copying the base backup.
Copying required WAL segments.
Generating recovery configuration
Identify dangerous settings in destination directory.

IMPORTANT
These settings have been modified to prevent data losses

postgresql.conf line 262: archive_command = false

Recovery completed (start time: 2024-09-05 21:00:45.771363+02:00, elapsed time: 5 seconds)
Your PostgreSQL server has been successfully prepared for recovery!
[barman@barman ~]$

PostgreSQL cannot start properly... Logs:

[postgres@db01 ~]$ cat 16/data/log/postgresql-Wed.log
2024-09-04 10:14:13.629 CEST [4634] LOG:  starting PostgreSQL 16.4 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20231218 (Red Hat 11.4.1-3), 64-bit
2024-09-04 10:14:13.629 CEST [4634] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2024-09-04 10:14:13.629 CEST [4634] LOG:  listening on IPv6 address "::", port 5432
2024-09-04 10:14:13.637 CEST [4634] LOG:  listening on Unix socket "/run/postgresql/.s.PGSQL.5432"
2024-09-04 10:14:13.651 CEST [4634] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2024-09-04 10:14:13.657 CEST [4638] LOG:  database system was interrupted; last known up at 2024-09-04 10:06:30 CEST
2024-09-04 10:14:13.657 CEST [4638] LOG:  creating missing WAL directory "pg_wal/archive_status"

cp: cannot stat 'barman_wal/00000002.history': No such file or directory

2024-09-04 10:14:16.041 CEST [4638] LOG:  starting point-in-time recovery to 2024-09-05 10:06:35+02
2024-09-04 10:14:16.041 CEST [4638] LOG:  starting backup recovery with redo LSN 0/10000028, checkpoint LSN 0/10000098, on timeline ID 1
2024-09-04 10:14:16.051 CEST [4638] LOG:  restored log file "000000010000000000000010" from archive
2024-09-04 10:14:16.091 CEST [4638] LOG:  redo starts at 0/10000028
2024-09-04 10:14:16.099 CEST [4638] LOG:  restored log file "000000010000000000000011" from archive
2024-09-04 10:14:16.122 CEST [4638] LOG:  restored log file "000000010000000000000012" from archive
2024-09-04 10:14:16.146 CEST [4638] LOG:  restored log file "000000010000000000000013" from archive
cp: cannot stat 'barman_wal/000000010000000000000014': No such file or directory
2024-09-04 10:14:16.175 CEST [4638] LOG:  completed backup recovery with redo LSN 0/10000028 and end LSN 0/10000138
2024-09-04 10:14:16.175 CEST [4638] LOG:  consistent recovery state reached at 0/10000138
2024-09-04 10:14:16.175 CEST [4634] LOG:  database system is ready to accept read-only connections
cp: cannot stat 'barman_wal/000000010000000000000014': No such file or directory
2024-09-04 10:14:16.213 CEST [4638] LOG:  redo done at 0/130008E0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.12 s
2024-09-04 10:14:16.213 CEST [4638] LOG:  last completed transaction was at log time 2024-09-04 10:07:52.502001+02
2024-09-04 10:14:16.213 CEST [4638] FATAL:  recovery ended before configured recovery target was reached
2024-09-04 10:14:16.214 CEST [4634] LOG:  startup process (PID 4638) exited with exit code 1
2024-09-04 10:14:16.214 CEST [4634] LOG:  terminating any other active server processes
[postgres@db01 ~]$

[Martin Marques]

A few things to note here:

On Thu, 5 Sept 2024 at 21:07, 'Michał Giza' via Barman, Backup and

You should always use a full timestamp with timezone when specifying a
recovery target. It's best practice.

In any case, given the list of backups and their start time, it's very
unlikely that you'll be able to recover to that point in time. You
need to look at the "End time" field from the output of `show-backup
backup_id`. That field will tell you which is the earliest time you
can recovery to with that backup.

> cp: cannot stat 'barman_wal/000000010000000000000014': No such file or directory
> 2024-09-04 10:14:16.213 CEST [4638] LOG: redo done at 0/130008E0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.12 s
> 2024-09-04 10:14:16.213 CEST [4638] LOG: last completed transaction was at log time 2024-09-04 10:07:52.502001+02
> 2024-09-04 10:14:16.213 CEST [4638] FATAL: recovery ended before configured recovery target was reached

Change the target time and it will recover. But Postgres can't recover
to a point in the past