Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

After PITR recovery, Postgres won't start and report missing WAL file #881

Open
PaganMuffin opened this issue Dec 18, 2023 · 4 comments
Open

Comments

@PaganMuffin
Copy link

After doing PITR recovery with specific time Postgres won't start.
Recovery command is reporting that postgres is successfully prepared for recovery, but after starting postgres instance it fail and log that WAL file, which is after target time according to timeline, is missing.
I can do a restore to the latest version of DB without a problem.

Command used to recovery

barman recover --target-time 20231215T162400 --remote-ssh-command 'ssh SERVER' remote 20231215T162003  /root/dev/pg-wal/pg-data/pgdata

Command log

Starting remote restore for server remote using backup 20231215T162003
Destination directory: /root/dev/pg-wal/pg-data/pgdata
Remote command: ssh SERVER
Doing PITR. Recovery target time: '2023-12-15 16:24:00+01:00'
Copying the base backup.
Copying required WAL segments.
Generating recovery configuration
Identify dangerous settings in destination directory.

Recovery completed (start time: 2023-12-18 08:39:26.886501+01:00, elapsed time: 33 seconds)
Your PostgreSQL server has been successfully prepared for recovery!

Postgres Logs

PostgreSQL Database directory appears to contain a database; Skipping initialization

2023-12-18 07:41:06.770 UTC [1] LOG:  starting PostgreSQL 14.10 on x86_64-pc-linux-musl, compiled by gcc (Alpine 13.2.1_git20231014) 13.2.1 20231014, 64-bit
2023-12-18 07:41:06.771 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2023-12-18 07:41:06.771 UTC [1] LOG:  listening on IPv6 address "::", port 5432
2023-12-18 07:41:06.786 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2023-12-18 07:41:06.807 UTC [21] LOG:  database system was interrupted while in recovery at log time 2023-12-15 15:20:03 UTC
2023-12-18 07:41:06.807 UTC [21] HINT:  If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
cp: can't stat 'barman_wal/00000002.history': No such file or directory
2023-12-18 07:41:06.887 UTC [21] LOG:  starting point-in-time recovery to 2023-12-15 16:24:00+00
2023-12-18 07:41:06.910 UTC [21] LOG:  restored log file "000000010000000000000003" from archive
2023-12-18 07:41:07.059 UTC [21] LOG:  redo starts at 0/3000028
2023-12-18 07:41:07.059 UTC [21] LOG:  consistent recovery state reached at 0/3000100
2023-12-18 07:41:07.059 UTC [1] LOG:  database system is ready to accept read-only connections
2023-12-18 07:41:07.083 UTC [21] LOG:  restored log file "000000010000000000000004" from archive
cp: can't stat 'barman_wal/000000010000000000000005': No such file or directory
2023-12-18 07:41:07.755 UTC [21] LOG:  redo done at 0/4FFFF28 system usage: CPU: user: 0.08 s, system: 0.02 s, elapsed: 0.69 s
2023-12-18 07:41:07.755 UTC [21] LOG:  last completed transaction was at log time 2023-12-15 15:25:13.895411+00
2023-12-18 07:41:07.755 UTC [21] FATAL:  recovery ended before configured recovery target was reached
2023-12-18 07:41:07.758 UTC [1] LOG:  startup process (PID 21) exited with exit code 1
2023-12-18 07:41:07.758 UTC [1] LOG:  terminating any other active server processes
2023-12-18 07:41:07.761 UTC [1] LOG:  shutting down due to startup process failure
2023-12-18 07:41:07.765 UTC [1] LOG:  database system is shut down

Timeline UTC+1
(Barman server, Postgres server have same timezone)
TIME | ACTION | WAL NUMBER | ADD NFO

16:18 CREATE TABLE      WAL 1
16:19 INSERT 0 1001     WAL 1
16:20 WAL SWITCH        WAL 2
16:20 BASE BACKUP       WAL 3 20231215T162003
16:22 INSERT 0 1001     WAL 4
16:25 INSERT 0 50001    WAL 4
16:25 INSERT 0 100001   WAL 5
16:26 BASE BACKUP       WAL 6 EXCEPT 152004 cars 
16:29 BASE BACKUP WAIT  WAL 7 EXCEPT 152004 cars  
16:35 INSERT 0 100001   WAL 8 EXCEPT 252005 cars 
16:35 INSERT 0 100001   WAL 9 EXCEPT 352006 cars

Barman log

2023-12-18 08:39:25,578 [6438] barman.wal_archiver INFO: No xlog segments found from streaming for remote.
2023-12-18 08:39:26,889 [6438] barman.recovery_executor INFO: Starting remote restore for server remote using backup 20231215T162003
2023-12-18 08:39:26,890 [6438] barman.recovery_executor INFO: Destination directory: /root/dev/pg-wal/pg-data/pgdata
2023-12-18 08:39:26,890 [6438] barman.recovery_executor INFO: Remote command: ssh SERVER
2023-12-18 08:39:26,891 [6438] barman.recovery_executor INFO: Doing PITR. Recovery target time: '2023-12-15 16:24:00+01:00'
2023-12-18 08:39:27,487 [6438] barman.recovery_executor WARNING: Unable to retrieve safe horizon time for smart rsync copy: The /root/dev/pg-wal/pg-data/pgdata/.barman-recover.info file does not exist
2023-12-18 08:39:28,705 [6438] barman.recovery_executor INFO: Copying the base backup.
2023-12-18 08:39:28,716 [6438] barman.copy_controller INFO: Copy started (safe before None)
2023-12-18 08:39:28,717 [6438] barman.copy_controller INFO: Copy step 1 of 4: [global] analyze PGDATA directory: /Users/USERNAME/dev/pg_wal_test/barman/data/remote/base/20231215T162003/data/
2023-12-18 08:39:29,566 [6438] barman.copy_controller INFO: Copy step 2 of 4: [global] create destination directories and delete unknown files for PGDATA directory: /Users/USERNAME/dev/pg_wal_test/barman/data/remote/base/20231215T162003/data/
2023-12-18 08:39:45,065 [6438] barman.copy_controller INFO: Copy finished (safe before None)
2023-12-18 08:39:47,053 [6438] barman.recovery_executor INFO: Copying required WAL segments.
2023-12-18 08:39:47,054 [6438] barman.recovery_executor INFO: Starting copy of 2 WAL files 2/2 from WalFileInfo(compression='gzip', name='000000010000000000000003', size=16491, time=1702653605.3655617) to WalFileInfo(compression='gzip', name='000000010000000000000004', size=7354841, time=1702653930.5049307)
2023-12-18 08:39:56,860 [6438] barman.recovery_executor INFO: Finished copying 2 WAL files.
2023-12-18 08:39:56,862 [6438] barman.recovery_executor INFO: Generating recovery configuration
2023-12-18 08:39:59,018 [6438] barman.recovery_executor INFO: Identify dangerous settings in destination directory.
@JP95Git
Copy link

JP95Git commented Mar 15, 2024

I've got the same problem using PostgreSQL 16.1 and Barman 3.9.0.

Recovery using
barman --config /path/to/barman.conf backup --wait localhost
works fine and restores PostgreSQL to the latest state, but adding --target-time="2024-03-15 13:50:56.844481+00:00" lead to a missing WAL file.

@JP95Git
Copy link

JP95Git commented Apr 10, 2024

The issue still persists in Barman 3.10. Here are logs and more details.

Started the recovery using this command:
/path/to/barman --config /path/to/barman.conf recover localhost 20240410T165613 /path/to/database --target-time "2024-04-10 14:56:15.915033+00:00"

Starting local restore for server localhost using backup 20240410T165613
Destination directory: /path/to/database
Doing PITR. Recovery target time: '2024-04-10 14:56:15.915033+00:00'
Using safe horizon time for smart rsync copy: 2024-04-10 14:56:13.756299+00: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
postgresql.auto.conf line 7: recovery_target_time = None

Recovery completed (start time: 2024-04-10 17:20:21.768695+02:00, elapsed time: less than one second)
Your PostgreSQL server has been successfully prepared for recovery!

Started the PostgreSQL server, but it failed to start.

Log file of barman:

2024-04-10 17:20:21,736 [2504447] barman.config WARNING: Discarding configuration file: .barman.auto.conf (not a file)
2024-04-10 17:20:21,764 [2504447] barman.wal_archiver INFO: No xlog segments found from streaming for localhost.
2024-04-10 17:20:21,770 [2504447] barman.recovery_executor INFO: Starting local restore for server localhost using backup 20240410T165613
2024-04-10 17:20:21,771 [2504447] barman.recovery_executor INFO: Destination directory: /path/to/database
2024-04-10 17:20:21,772 [2504447] barman.recovery_executor INFO: Doing PITR. Recovery target time: '2024-04-10 14:56:15.915033+00:00'
2024-04-10 17:20:21,787 [2504447] barman.recovery_executor INFO: Using safe horizon time for smart rsync copy: 2024-04-10 14:56:13.756299+00:00
2024-04-10 17:20:21,796 [2504447] barman.recovery_executor INFO: Copying the base backup.
2024-04-10 17:20:21,799 [2504447] barman.copy_controller INFO: Copy started (safe before datetime.datetime(2024, 4, 10, 14, 56, 13, 756299, tzinfo=tzutc()))
2024-04-10 17:20:21,799 [2504447] barman.copy_controller INFO: Copy step 1 of 4: [global] analyze PGDATA directory: /path/to/database-backup/localhost/base/20240410T165613/data/
2024-04-10 17:20:21,991 [2504447] barman.copy_controller INFO: Copy step 2 of 4: [global] create destination directories and delete unknown files for PGDATA directory: /path/to/database-backup/localhost/base/20240410T165613/data/
2024-04-10 17:20:22,108 [2504462] barman.copy_controller INFO: Copy step 3 of 4: [bucket 0] starting copy safe files from PGDATA directory: /path/to/database-backup/localhost/base/20240410T165613/data/
2024-04-10 17:20:22,207 [2504462] barman.copy_controller INFO: Copy step 3 of 4: [bucket 0] finished (duration: less than one second) copy safe files from PGDATA directory: /path/to/database-backup/localhost/base/20240410T165613/data/
2024-04-10 17:20:22,213 [2504462] barman.copy_controller INFO: Copy step 4 of 4: [bucket 0] starting copy files with checksum from PGDATA directory: /path/to/database-backup/localhost/base/20240410T165613/data/
2024-04-10 17:20:22,260 [2504462] barman.copy_controller INFO: Copy step 4 of 4: [bucket 0] finished (duration: less than one second) copy files with checksum from PGDATA directory: /path/to/database-backup/localhost/base/20240410T165613/data/
2024-04-10 17:20:22,261 [2504447] barman.copy_controller INFO: Copy finished (safe before 2024-04-10 14:56:13.756299+00:00)
2024-04-10 17:20:22,273 [2504447] barman.recovery_executor INFO: Copying required WAL segments.
2024-04-10 17:20:22,274 [2504447] barman.recovery_executor INFO: Starting copy of 2 WAL files 2/2 from WalFileInfo(compression='gzip', name='00000001000000000000000D', size=16465, time=1712760976.317646) to WalFileInfo(compression='gzip', name='00000001000000000000000E', size=16396, time=1712760977.4366577)
2024-04-10 17:20:22,481 [2504447] barman.recovery_executor INFO: Finished copying 2 WAL files.
2024-04-10 17:20:22,482 [2504447] barman.recovery_executor INFO: Generating recovery configuration
2024-04-10 17:20:22,492 [2504447] barman.recovery_executor INFO: Identify dangerous settings in destination directory.

Log file of PostgreSQL:

2024-04-10 15:20:44.521 UTC [2504481] LOG:  starting PostgreSQL 16.1 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat 11.4.1-2), 64-bit
2024-04-10 15:20:44.521 UTC [2504481] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2024-04-10 15:20:44.521 UTC [2504481] LOG:  listening on IPv6 address "::", port 5432
2024-04-10 15:20:44.542 UTC [2504481] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2024-04-10 15:20:44.548 UTC [2504485] LOG:  database system was interrupted; last known up at 2024-04-10 14:56:13 UTC
2024-04-10 15:20:44.548 UTC [2504485] LOG:  creating missing WAL directory "pg_wal/archive_status"
2024-04-10 15:20:44.699 UTC [2504486] FATAL:  the database system is starting up
2024-04-10 15:20:44.703 UTC [2504487] FATAL:  the database system is starting up
2024-04-10 15:20:44.706 UTC [2504488] FATAL:  the database system is starting up
cp: der Aufruf von stat für 'barman_wal/00000002.history' ist nicht möglich: Datei oder Verzeichnis nicht gefunden
2024-04-10 15:20:44.817 UTC [2504485] LOG:  starting point-in-time recovery to 2024-04-10 14:56:15.915033+00
2024-04-10 15:20:44.834 UTC [2504485] LOG:  restored log file "00000001000000000000000D" from archive
2024-04-10 15:20:44.965 UTC [2504485] LOG:  redo starts at 0/D000028
2024-04-10 15:20:44.983 UTC [2504485] LOG:  restored log file "00000001000000000000000E" from archive
cp: der Aufruf von stat für 'barman_wal/00000001000000000000000F' ist nicht möglich: Datei oder Verzeichnis nicht gefunden
2024-04-10 15:20:45.089 UTC [2504485] LOG:  consistent recovery state reached at 0/D000100
2024-04-10 15:20:45.089 UTC [2504481] LOG:  database system is ready to accept read-only connections
cp: der Aufruf von stat für 'barman_wal/00000001000000000000000F' ist nicht möglich: Datei oder Verzeichnis nicht gefunden
2024-04-10 15:20:45.095 UTC [2504485] LOG:  redo done at 0/E000060 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.13 s
2024-04-10 15:20:45.095 UTC [2504485] FATAL:  recovery ended before configured recovery target was reached
2024-04-10 15:20:45.096 UTC [2504481] LOG:  startup process (PID 2504485) exited with exit code 1
2024-04-10 15:20:45.097 UTC [2504481] LOG:  terminating any other active server processes
2024-04-10 15:20:45.097 UTC [2504481] LOG:  shutting down due to startup process failure
2024-04-10 15:20:45.099 UTC [2504481] LOG:  database system is shut down

@gcalacoci
Copy link
Contributor

Hi, Could you please provide the output of the barman diagnose immediately before executing a P.I.T.R. command that fails like the above?

Also, the logs like you did before.

Thanks a lot!

@JP95Git
Copy link

JP95Git commented Apr 18, 2024

Here are the requested information. I don't have a full test environment available, so I just created a blank database, backup it several times and tried to restore it using "--target-time", just to show the error.

[username@xusername-PG1 database-backup]$ /opt/username/programs/barman/bin/barman --config /opt/username/programs/barman/etc/barman.conf list-backups localhost
localhost 20240418T185600 - Thu Apr 18 16:56:02 2024 - Size: 29.4 MiB - WAL Size: 16.2 KiB
localhost 20240418T185551 - Thu Apr 18 16:55:55 2024 - Size: 29.4 MiB - WAL Size: 32.1 KiB
localhost 20240418T000005 - Wed Apr 17 22:00:26 2024 - Size: 29.4 MiB - WAL Size: 32.3 KiB
[username@xusername-PG1 database-backup]$ barman --config /opt/username/programs/barman/etc/barman.conf show-backup localhost 20240418T185600
Backup 20240418T185600:
  Server Name            : localhost
  System Id              : 7356240957958843836
  Status                 : DONE
  PostgreSQL Version     : 160001
  PGDATA directory       : /opt/username/database

  Base backup information:
    Disk usage           : 29.4 MiB (29.4 MiB with WALs)
    Incremental size     : 8.9 KiB (-99.97%)
    Timeline             : 1
    Begin WAL            : 000000010000000000000010
    End WAL              : 000000010000000000000010
    WAL number           : 1
    WAL compression ratio: 99.90%
    Begin time           : 2024-04-18 16:56:00.224345+00:00
    End time             : 2024-04-18 16:56:02.161839+00:00
    Copy time            : less than one second
    Estimated throughput : 9.2 KiB/s
    Begin Offset         : 40
    End Offset           : 256
    Begin LSN            : 0/10000028
    End LSN              : 0/10000100

  WAL information:
    No of files          : 1
    Disk usage           : 16.2 KiB
    WAL rate             : 22.00/hour
    Compression ratio    : 99.90%
    Last available       : 000000010000000000000011

  Catalog information:
    Retention Policy     : VALID
    Previous Backup      : 20240418T185551
    Next Backup          : - (this is the latest base backup)

https://medium.com/@kiwiv/recover-your-database-with-barman-be5ee4e11939

If we want to use this backup, note the begin and end time and you can recover from the any time in between. For this example will pick up the end time.

I picked the end date of the backup.

[username@xusername-PG1 database-backup]$ barman --config /opt/username/programs/barman/etc/barman.conf recover localhost 20240418T185600 /opt/username/database --target-time "2024-04-18 16:56:02.161839+00:00"
Starting local restore for server localhost using backup 20240418T185600
Destination directory: /opt/username/database
Doing PITR. Recovery target time: '2024-04-18 16:56:02.161839+00: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-04-18 19:12:55.447251+02:00, elapsed time: 2 seconds)
Your PostgreSQL server has been successfully prepared for recovery!

Log of PostgreSQL:

2024-04-18 17:13:59.443 UTC [796275] LOG:  starting PostgreSQL 16.1 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 11.4.1 20230605 (Red Hat 11.4.1-2), 64-bit
2024-04-18 17:13:59.444 UTC [796275] LOG:  listening on IPv4 address "0.0.0.0", port 5432
2024-04-18 17:13:59.444 UTC [796275] LOG:  listening on IPv6 address "::", port 5432
2024-04-18 17:13:59.449 UTC [796275] LOG:  listening on Unix socket "/tmp/.s.PGSQL.5432"
2024-04-18 17:13:59.454 UTC [796279] LOG:  database system was interrupted; last known up at 2024-04-18 16:56:00 UTC
2024-04-18 17:13:59.454 UTC [796279] LOG:  creating missing WAL directory "pg_wal/archive_status"
2024-04-18 17:13:59.897 UTC [796281] FATAL:  the database system is starting up
2024-04-18 17:13:59.899 UTC [796282] FATAL:  the database system is starting up
2024-04-18 17:13:59.901 UTC [796283] FATAL:  the database system is starting up
cp: der Aufruf von stat für 'barman_wal/00000002.history' ist nicht möglich: Datei oder Verzeichnis nicht gefunden
2024-04-18 17:14:01.363 UTC [796279] LOG:  starting point-in-time recovery to 2024-04-18 16:56:02.161839+00
2024-04-18 17:14:01.381 UTC [796279] LOG:  restored log file "000000010000000000000010" from archive
2024-04-18 17:14:01.904 UTC [796300] FATAL:  the database system is not yet accepting connections
2024-04-18 17:14:01.904 UTC [796300] DETAIL:  Consistent recovery state has not been yet reached.
2024-04-18 17:14:01.907 UTC [796301] FATAL:  the database system is not yet accepting connections
2024-04-18 17:14:01.907 UTC [796301] DETAIL:  Consistent recovery state has not been yet reached.
2024-04-18 17:14:01.910 UTC [796302] FATAL:  the database system is not yet accepting connections
2024-04-18 17:14:01.910 UTC [796302] DETAIL:  Consistent recovery state has not been yet reached.
2024-04-18 17:14:02.233 UTC [796305] FATAL:  the database system is not yet accepting connections
2024-04-18 17:14:02.233 UTC [796305] DETAIL:  Consistent recovery state has not been yet reached.
2024-04-18 17:14:02.235 UTC [796306] FATAL:  the database system is not yet accepting connections
2024-04-18 17:14:02.235 UTC [796306] DETAIL:  Consistent recovery state has not been yet reached.
2024-04-18 17:14:02.241 UTC [796308] FATAL:  the database system is not yet accepting connections
2024-04-18 17:14:02.241 UTC [796308] DETAIL:  Consistent recovery state has not been yet reached.
2024-04-18 17:14:02.243 UTC [796309] FATAL:  the database system is not yet accepting connections
2024-04-18 17:14:02.243 UTC [796309] DETAIL:  Consistent recovery state has not been yet reached.
2024-04-18 17:14:02.661 UTC [796279] LOG:  redo starts at 0/10000028
2024-04-18 17:14:02.680 UTC [796279] LOG:  restored log file "000000010000000000000011" from archive
cp: der Aufruf von stat für 'barman_wal/000000010000000000000012' ist nicht möglich: Datei oder Verzeichnis nicht gefunden
2024-04-18 17:14:02.810 UTC [796279] LOG:  consistent recovery state reached at 0/10000100
2024-04-18 17:14:02.810 UTC [796275] LOG:  database system is ready to accept read-only connections
cp: der Aufruf von stat für 'barman_wal/000000010000000000000012' ist nicht möglich: Datei oder Verzeichnis nicht gefunden
2024-04-18 17:14:02.814 UTC [796279] LOG:  redo done at 0/110001B0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 1.30 s
2024-04-18 17:14:02.814 UTC [796279] FATAL:  recovery ended before configured recovery target was reached
2024-04-18 17:14:02.815 UTC [796275] LOG:  startup process (PID 796279) exited with exit code 1
2024-04-18 17:14:02.815 UTC [796275] LOG:  terminating any other active server processes
2024-04-18 17:14:02.816 UTC [796275] LOG:  shutting down due to startup process failure
2024-04-18 17:14:02.818 UTC [796275] LOG:  database system is shut down

barman diagnose

{
    "global": {
        "config": {
            "backup_method": "rsync",
            "backup_options": "concurrent_backup",
            "barman_home": "/opt/username/database-backup",
            "barman_user": "username",
            "compression": "gzip",
            "configuration_files_directory": "/opt/username/programs/barman/etc",
            "errors_list": [],
            "log_file": "/opt/username/programs/barman/logs/barman.log",
            "path_prefix": "/opt/username/programs/postgres/bin",
            "reuse_backup": "link",
            "slot_name": "barman",
            "streaming_archiver": "on"
        },
        "system_info": {
            "barman_ver": "3.10.0",
            "kernel_ver": "Linux xusername-PG1 5.14.0-362.18.1.el9_3.0.1.x86_64 #1 SMP PREEMPT_DYNAMIC Sun Feb 11 13:49:23 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux",
            "python_ver": "Python 3.9.18",
            "release": "RedHat Linux Rocky Linux release 9.3 (Blue Onyx)",
            "rsync_ver": "rsync  version 3.2.3  protocol version 31",
            "ssh_ver": "",
            "timestamp": "2024-04-18T18:59:10.292506+02:00"
        }
    },
    "models": {},
    "servers": {
        "localhost": {
            "active_model": null,
            "backups": {
                "20240418T000005": {
                    "backup_id": "20240418T000005",
                    "backup_label": "'START WAL LOCATION: 0/C000060 (file 00000001000000000000000C)\\nCHECKPOINT LOCATION: 0/C000098\\nBACKUP METHOD: streamed\\nBACKUP FROM: primary\\nSTART TIME: 2024-04-17 22:00:11 UTC\\nLABEL: Barman backup localhost 20240418T000005\\nSTART TIMELINE: 1\\n'",
                    "begin_offset": 96,
                    "begin_time": "2024-04-18T00:00:05.707294+02:00",
                    "begin_wal": "00000001000000000000000C",
                    "begin_xlog": "0/C000060",
                    "compression": null,
                    "config_file": "/opt/username/database/postgresql.conf",
                    "copy_stats": {
                        "analysis_time": 0.965946,
                        "analysis_time_per_item": {
                            "pgdata": 0.965946
                        },
                        "copy_time": 12.807903,
                        "copy_time_per_item": {
                            "pg_control": 0.295303,
                            "pgdata": 12.509192
                        },
                        "number_of_workers": 1,
                        "serialized_copy_time": 12.799614,
                        "serialized_copy_time_per_item": {
                            "pg_control": 0.295303,
                            "pgdata": 12.504311
                        },
                        "total_time": 14.197323
                    },
                    "deduplicated_size": 30794643,
                    "end_offset": 368,
                    "end_time": "2024-04-18T00:00:26.479322+02:00",
                    "end_wal": "00000001000000000000000C",
                    "end_xlog": "0/C000170",
                    "error": null,
                    "hba_file": "/opt/username/database/pg_hba.conf",
                    "ident_file": "/opt/username/database/pg_ident.conf",
                    "included_files": [
                        "/opt/username/database/postgresql.auto.conf"
                    ],
                    "mode": "rsync-concurrent",
                    "pgdata": "/opt/username/database",
                    "server_name": "localhost",
                    "size": 30794643,
                    "status": "DONE",
                    "systemid": "7356240957958843836",
                    "tablespaces": null,
                    "timeline": 1,
                    "version": 160001,
                    "xlog_segment_size": 16777216
                },
                "20240418T185551": {
                    "backup_id": "20240418T185551",
                    "backup_label": "'START WAL LOCATION: 0/E000028 (file 00000001000000000000000E)\\nCHECKPOINT LOCATION: 0/E000098\\nBACKUP METHOD: streamed\\nBACKUP FROM: primary\\nSTART TIME: 2024-04-18 16:55:53 UTC\\nLABEL: Barman backup localhost 20240418T185551\\nSTART TIMELINE: 1\\n'",
                    "begin_offset": 40,
                    "begin_time": "2024-04-18T18:55:51.775903+02:00",
                    "begin_wal": "00000001000000000000000E",
                    "begin_xlog": "0/E000028",
                    "compression": null,
                    "config_file": "/opt/username/database/postgresql.conf",
                    "copy_stats": {
                        "analysis_time": 0.792977,
                        "analysis_time_per_item": {
                            "pgdata": 0.792977
                        },
                        "copy_time": 0.973467,
                        "copy_time_per_item": {
                            "pg_control": 0.295436,
                            "pgdata": 0.674826
                        },
                        "number_of_workers": 1,
                        "serialized_copy_time": 0.963715,
                        "serialized_copy_time_per_item": {
                            "pg_control": 0.295436,
                            "pgdata": 0.668279
                        },
                        "total_time": 1.785295
                    },
                    "deduplicated_size": 9140,
                    "end_offset": 312,
                    "end_time": "2024-04-18T18:55:55.285195+02:00",
                    "end_wal": "00000001000000000000000E",
                    "end_xlog": "0/E000138",
                    "error": null,
                    "hba_file": "/opt/username/database/pg_hba.conf",
                    "ident_file": "/opt/username/database/pg_ident.conf",
                    "included_files": [
                        "/opt/username/database/postgresql.auto.conf"
                    ],
                    "mode": "rsync-concurrent",
                    "pgdata": "/opt/username/database",
                    "server_name": "localhost",
                    "size": 30794643,
                    "status": "DONE",
                    "systemid": "7356240957958843836",
                    "tablespaces": null,
                    "timeline": 1,
                    "version": 160001,
                    "xlog_segment_size": 16777216
                },
                "20240418T185600": {
                    "backup_id": "20240418T185600",
                    "backup_label": "'START WAL LOCATION: 0/10000028 (file 000000010000000000000010)\\nCHECKPOINT LOCATION: 0/10000060\\nBACKUP METHOD: streamed\\nBACKUP FROM: primary\\nSTART TIME: 2024-04-18 16:56:00 UTC\\nLABEL: Barman backup localhost 20240418T185600\\nSTART TIMELINE: 1\\n'",
                    "begin_offset": 40,
                    "begin_time": "2024-04-18T18:56:00.224345+02:00",
                    "begin_wal": "000000010000000000000010",
                    "begin_xlog": "0/10000028",
                    "compression": null,
                    "config_file": "/opt/username/database/postgresql.conf",
                    "copy_stats": {
                        "analysis_time": 0.764417,
                        "analysis_time_per_item": {
                            "pgdata": 0.764417
                        },
                        "copy_time": 0.970696,
                        "copy_time_per_item": {
                            "pg_control": 0.292661,
                            "pgdata": 0.676094
                        },
                        "number_of_workers": 1,
                        "serialized_copy_time": 0.961986,
                        "serialized_copy_time_per_item": {
                            "pg_control": 0.292661,
                            "pgdata": 0.669325
                        },
                        "total_time": 1.756391
                    },
                    "deduplicated_size": 9099,
                    "end_offset": 256,
                    "end_time": "2024-04-18T18:56:02.161839+02:00",
                    "end_wal": "000000010000000000000010",
                    "end_xlog": "0/10000100",
                    "error": null,
                    "hba_file": "/opt/username/database/pg_hba.conf",
                    "ident_file": "/opt/username/database/pg_ident.conf",
                    "included_files": [
                        "/opt/username/database/postgresql.auto.conf"
                    ],
                    "mode": "rsync-concurrent",
                    "pgdata": "/opt/username/database",
                    "server_name": "localhost",
                    "size": 30794646,
                    "status": "DONE",
                    "systemid": "7356240957958843836",
                    "tablespaces": null,
                    "timeline": 1,
                    "version": 160001,
                    "xlog_segment_size": 16777216
                }
            },
            "config": {
                "active": true,
                "archiver": false,
                "archiver_batch_size": 0,
                "autogenerate_manifest": false,
                "aws_profile": null,
                "aws_region": null,
                "azure_credential": null,
                "azure_resource_group": null,
                "azure_subscription_id": null,
                "backup_compression": null,
                "backup_compression_format": null,
                "backup_compression_level": null,
                "backup_compression_location": null,
                "backup_compression_workers": null,
                "backup_directory": "/opt/username/database-backup/localhost",
                "backup_method": "rsync",
                "backup_options": "concurrent_backup",
                "bandwidth_limit": null,
                "barman_home": "/opt/username/database-backup",
                "barman_lock_directory": "/opt/username/database-backup",
                "basebackup_retry_sleep": 30,
                "basebackup_retry_times": 0,
                "basebackups_directory": "/opt/username/database-backup/localhost/base",
                "check_timeout": 30,
                "cluster": "localhost",
                "compression": "gzip",
                "config_changes_queue": "/opt/username/database-backup/cfg_changes.queue",
                "conninfo": "host=localhost port=5432 dbname=postgres user=barman",
                "create_slot": "manual",
                "custom_compression_filter": null,
                "custom_compression_magic": null,
                "custom_decompression_filter": null,
                "description": null,
                "disabled": false,
                "errors_directory": "/opt/username/database-backup/localhost/errors",
                "forward_config_path": false,
                "gcp_project": null,
                "gcp_zone": null,
                "immediate_checkpoint": false,
                "incoming_wals_directory": "/opt/username/database-backup/localhost/incoming",
                "last_backup_maximum_age": null,
                "last_backup_minimum_size": null,
                "last_wal_maximum_age": null,
                "lock_directory_cleanup": true,
                "max_incoming_wals_queue": null,
                "minimum_redundancy": 0,
                "msg_list": [],
                "name": "localhost",
                "network_compression": false,
                "parallel_jobs": 1,
                "parallel_jobs_start_batch_period": 1,
                "parallel_jobs_start_batch_size": 10,
                "path_prefix": "/opt/username/programs/postgres/bin",
                "post_archive_retry_script": null,
                "post_archive_script": null,
                "post_backup_retry_script": null,
                "post_backup_script": null,
                "post_delete_retry_script": null,
                "post_delete_script": null,
                "post_recovery_retry_script": null,
                "post_recovery_script": null,
                "post_wal_delete_retry_script": null,
                "post_wal_delete_script": null,
                "pre_archive_retry_script": null,
                "pre_archive_script": null,
                "pre_backup_retry_script": null,
                "pre_backup_script": null,
                "pre_delete_retry_script": null,
                "pre_delete_script": null,
                "pre_recovery_retry_script": null,
                "pre_recovery_script": null,
                "pre_wal_delete_retry_script": null,
                "pre_wal_delete_script": null,
                "primary_checkpoint_timeout": 0,
                "primary_conninfo": null,
                "primary_ssh_command": null,
                "recovery_options": "",
                "recovery_staging_path": null,
                "retention_policy": "window 7 d",
                "retention_policy_mode": "auto",
                "reuse_backup": "link",
                "slot_name": "barman",
                "snapshot_disks": null,
                "snapshot_gcp_project": null,
                "snapshot_instance": null,
                "snapshot_provider": null,
                "snapshot_zone": null,
                "ssh_command": "ssh username@localhost",
                "streaming_archiver": true,
                "streaming_archiver_batch_size": 0,
                "streaming_archiver_name": "barman_receive_wal",
                "streaming_backup_name": "barman_streaming_backup",
                "streaming_conninfo": "host=localhost port=5432 dbname=postgres user=barman",
                "streaming_wals_directory": "/opt/username/database-backup/localhost/streaming",
                "tablespace_bandwidth_limit": null,
                "wal_conninfo": null,
                "wal_retention_policy": "simple-wal 7 d",
                "wal_streaming_conninfo": null,
                "wals_directory": "/opt/username/database-backup/localhost/wals"
            },
            "status": {
                "archive_timeout": 0,
                "checkpoint_timeout": 300,
                "config_file": "/opt/username/database/postgresql.conf",
                "connection_error": null,
                "current_lsn": "0/110000C8",
                "current_size": 31254984.0,
                "current_xlog": "000000010000000000000011",
                "data_checksums": "off",
                "data_directory": "/opt/username/database",
                "has_backup_privileges": true,
                "has_monitoring_privileges": true,
                "hba_file": "/opt/username/database/pg_hba.conf",
                "hot_standby": "on",
                "ident_file": "/opt/username/database/pg_ident.conf",
                "included_files": [
                    "/opt/username/database/postgresql.auto.conf"
                ],
                "is_in_recovery": false,
                "is_superuser": true,
                "max_replication_slots": "10",
                "max_wal_senders": "10",
                "pg_receivexlog_compatible": true,
                "pg_receivexlog_installed": true,
                "pg_receivexlog_path": "/opt/username/programs/postgres/bin/pg_receivewal",
                "pg_receivexlog_supports_slots": true,
                "pg_receivexlog_synchronous": false,
                "pg_receivexlog_version": "16.1",
                "postgres_systemid": "7356240957958843836",
                "replication_slot": [
                    "barman",
                    true,
                    "0/11000000"
                ],
                "replication_slot_support": true,
                "server_txt_version": "16.1",
                "streaming": true,
                "streaming_supported": true,
                "streaming_systemid": "7356240957958843836",
                "synchronous_standby_names": [
                    ""
                ],
                "timeline": 1,
                "version_supported": true,
                "wal_compression": "off",
                "wal_keep_size": "0",
                "wal_level": "logical",
                "xlog_segment_size": 16777216,
                "xlogpos": "0/110000C8"
            },
            "system_info": {
                "kernel_ver": "Linux xusername-PG1 5.14.0-362.18.1.el9_3.0.1.x86_64 #1 SMP PREEMPT_DYNAMIC Sun Feb 11 13:49:23 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux",
                "python_ver": "Python 3.9.18",
                "release": "RedHat Linux Rocky Linux release 9.3 (Blue Onyx)",
                "rsync_ver": "rsync  version 3.2.3  protocol version 31",
                "ssh_ver": ""
            },
            "wals": {
                "last_archived_wal_per_timeline": {
                    "00000001": {
                        "compression": "gzip",
                        "name": "000000010000000000000010",
                        "size": 16460,
                        "time": 1713459362.313908
                    }
                }
            }
        }
    }
}

Logfile of barman:

2024-04-18 19:12:02,287 [796162] barman.postgres WARNING: Error retrieving PostgreSQL status: connection to server at "localhost" (::1), port 5432 failed: Connection refused
2024-04-18 19:12:02,287 [796162] barman.postgres WARNING: Error retrieving PostgreSQL status: connection to server at "localhost" (::1), port 5432 failed: Connection refused
2024-04-18 19:12:02,293 [796162] barman.backup_executor WARNING: Error retrieving PostgreSQL status: connection to server at "localhost" (::1), port 5432 failed: Connection refused
2024-04-18 19:12:02,293 [796162] barman.server ERROR: Check 'no access to monitoring functions' failed for server 'localhost'
2024-04-18 19:12:02,293 [796162] barman.server ERROR: Check 'PostgreSQL streaming (WAL streaming)' failed for server 'localhost'
2024-04-18 19:12:02,307 [796162] barman.server ERROR: Impossible to start WAL streaming. Check the log for more details, or run 'barman check localhost'
2024-04-18 19:12:55,423 [796166] barman.config WARNING: Discarding configuration file: .barman.auto.conf (not a file)
2024-04-18 19:12:55,444 [796166] barman.wal_archiver INFO: No xlog segments found from streaming for localhost.
2024-04-18 19:12:55,469 [796166] barman.recovery_executor INFO: Starting local restore for server localhost using backup 20240418T185600
2024-04-18 19:12:55,470 [796166] barman.recovery_executor INFO: Destination directory: /opt/username/database
2024-04-18 19:12:55,471 [796166] barman.recovery_executor INFO: Doing PITR. Recovery target time: '2024-04-18 16:56:02.161839+00:00'
2024-04-18 19:12:55,476 [796166] barman.recovery_executor WARNING: Unable to retrieve safe horizon time for smart rsync copy: The /opt/username/database/.barman-recover.info file does not exist
2024-04-18 19:12:55,483 [796166] barman.recovery_executor INFO: Copying the base backup.
2024-04-18 19:12:55,485 [796166] barman.copy_controller INFO: Copy started (safe before None)
2024-04-18 19:12:55,485 [796166] barman.copy_controller INFO: Copy step 1 of 4: [global] analyze PGDATA directory: /opt/username/database-backup/localhost/base/20240418T185600/data/
2024-04-18 19:12:55,650 [796166] barman.copy_controller INFO: Copy step 2 of 4: [global] create destination directories and delete unknown files for PGDATA directory: /opt/username/database-backup/localhost/base/20240418T185600/data/
2024-04-18 19:12:57,882 [796194] barman.copy_controller INFO: Copy step 3 of 4: [bucket 0] starting copy safe files from PGDATA directory: /opt/username/database-backup/localhost/base/20240418T185600/data/
2024-04-18 19:12:57,931 [796194] barman.copy_controller INFO: Copy step 3 of 4: [bucket 0] finished (duration: less than one second) copy safe files from PGDATA directory: /opt/username/database-backup/localhost/base/20240418T185600/data/
2024-04-18 19:12:57,937 [796194] barman.copy_controller INFO: Copy step 4 of 4: [bucket 0] starting copy files with checksum from PGDATA directory: /opt/username/database-backup/localhost/base/20240418T185600/data/
2024-04-18 19:12:58,191 [796194] barman.copy_controller INFO: Copy step 4 of 4: [bucket 0] finished (duration: less than one second) copy files with checksum from PGDATA directory: /opt/username/database-backup/localhost/base/20240418T185600/data/
2024-04-18 19:12:58,197 [796166] barman.copy_controller INFO: Copy finished (safe before None)
2024-04-18 19:12:58,211 [796166] barman.recovery_executor INFO: Copying required WAL segments.
2024-04-18 19:12:58,212 [796166] barman.recovery_executor INFO: Starting copy of 2 WAL files 2/2 from WalFileInfo(compression='gzip', name='000000010000000000000010', size=16460, time=1713459362.313908) to WalFileInfo(compression='gzip', name='000000010000000000000011', size=16557, time=1713459689.5802295)
2024-04-18 19:12:58,413 [796166] barman.recovery_executor INFO: Finished copying 2 WAL files.
2024-04-18 19:12:58,414 [796166] barman.recovery_executor INFO: Generating recovery configuration
2024-04-18 19:12:58,426 [796166] barman.recovery_executor INFO: Identify dangerous settings in destination directory.
2024-04-18 19:13:01,549 [796225] barman.config WARNING: Discarding configuration file: .barman.auto.conf (not a file)
2024-04-18 19:13:01,571 [796225] barman.utils INFO: Cleaning up lockfiles directory.
2024-04-18 19:13:01,700 [796226] barman.config WARNING: Discarding configuration file: .barman.auto.conf (not a file)
2024-04-18 19:13:01,719 [796226] barman.wal_archiver INFO: No xlog segments found from streaming for localhost.
2024-04-18 19:13:01,729 [796227] barman.config WARNING: Discarding configuration file: .barman.auto.conf (not a file)
2024-04-18 19:13:01,737 [796227] barman.postgres WARNING: Error retrieving PostgreSQL status: connection to server at "localhost" (::1), port 5432 failed: Connection refused

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants