Failed archive command message with Remote Recovery

33 views
Skip to first unread message

Norman Larose

unread,
Apr 6, 2022, 9:47:33 AMApr 6
to Barman, Backup and Recovery Manager for PostgreSQL

Good morning everyone,

 

I have 3 servers:  barman pvlpg70c and 172.17.0.42 (pvlpg70d)

Barman version 2.19

Postgresql version 9.6.22  (cannot upgrade for now)

OS rhel 8

 

I'm trying to use remote recovery but am running into a problem. I'm using the following command to recover the database: 

 

Barman server:

barman recover --target-time "2022-04-06 02:16:07.923929-04:00" --remote-ssh-command "ssh post...@172.17.0.42" pvlpg70c 20220406T021610 /var/lib/pgsql/data

 

On 172.17.0.42 server log, 

 

< 2022-04-06 09:04:21.861 EDT > LOG:  database system was interrupted; last known up at 2022-04-06 02:16:06 EDT
< 2022-04-06 09:04:21.861 EDT > LOG:  creating missing WAL directory "pg_xlog/archive_status"
< 2022-04-06 09:04:22.024 EDT > LOG:  starting point-in-time recovery to 2022-04-06 02:16:07.923929-04
cp: cannot stat 'barman_wal/00000002.history': No such file or directory
< 2022-04-06 09:04:22.046 EDT > LOG:  restored log file "000000020000009F000000A0" from archive
< 2022-04-06 09:04:22.065 EDT > LOG:  redo starts at 9F/A0000028
< 2022-04-06 09:04:22.066 EDT > LOG:  consistent recovery state reached at 9F/A00000F8
cp: cannot stat 'barman_wal/000000020000009F000000A1': No such file or directory
< 2022-04-06 09:04:22.071 EDT > LOG:  redo done at 9F/A00000F8
< 2022-04-06 09:04:22.092 EDT > LOG:  restored log file "000000020000009F000000A0" from archive
cp: cannot stat 'barman_wal/00000003.history': No such file or directory
< 2022-04-06 09:04:22.117 EDT > LOG:  selected new timeline ID: 3
< 2022-04-06 09:04:22.147 EDT > LOG:  archive recovery complete
cp: cannot stat 'barman_wal/00000002.history': No such file or directory
< 2022-04-06 09:04:22.264 EDT > LOG:  MultiXact member wraparound protections are now enabled
< 2022-04-06 09:04:22.267 EDT > LOG:  database system is ready to accept connections
< 2022-04-06 09:04:22.267 EDT > LOG:  autovacuum launcher started
< 2022-04-06 09:04:22.270 EDT > LOG:  archive command failed with exit code 1
< 2022-04-06 09:04:22.270 EDT > DETAIL:  The failed archive command was: false
< 2022-04-06 09:04:23.273 EDT > LOG:  archive command failed with exit code 1
< 2022-04-06 09:04:23.273 EDT > DETAIL:  The failed archive command was: false
< 2022-04-06 09:04:24.276 EDT > LOG:  archive command failed with exit code 1
< 2022-04-06 09:04:24.276 EDT > DETAIL:  The failed archive command was: false
< 2022-04-06 09:04:24.276 EDT > WARNING:  archiving transaction log file "00000003.history" failed too many times, will try again later

 

on barman server:

-bash-4.4$ barman recover --target-time "2022-04-06 02:16:07.923929-04:00" --remote-ssh-command "ssh post...@172.17.0.42" pvlpg70c 20220406T021610 /var/lib/pgsql/data
Starting remote restore for server pvlpg70c using backup 20220406T021610
Destination directory: /var/lib/pgsql/data
Remote command: ssh post...@172.17.0.42

 

Doing PITR. Recovery target time: '2022-04-06 02:16:07.923929-04:00'
Using safe horizon time for smart rsync copy: 2022-04-06 02:16:06.404834-04: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 220: archive_command = false

Recovery completed (start time: 2022-04-06 09:27:00.480196, elapsed time: 3 seconds)

Your PostgreSQL server has been successfully prepared for recovery!

 

So everything seems to work

I check database on 172.17.0.42, all seems ok

But why messages on the log?

 

-bash-4.4$ barman status pvlpg70c

Server pvlpg70c:

        Description: pvlpg70c backup config

        Active: True

        Disabled: False

        PostgreSQL version: 9.6.22

        Cluster state: in production

        pgespresso extension: Not available

        Current data size: 25.7 GiB

        PostgreSQL Data directory: /var/lib/pgsql/data

        Current WAL segment: 000000020000009F000000A1

        PostgreSQL 'archive_command' setting: test ! -f barman@pvlbar0b:/var/lib/barman/pvlpg70c/incoming/%f && rsync -a %p barman@pvlbar0b:/var/lib/barman/pvlpg70c/incoming/%f

        Last archived WAL: 000000020000009F000000A0.00000028.backup, at Wed Apr  6 02:16:08 2022

        Failures of WAL archiver: 0

        Server WAL archiving rate: 0.14/hour

        Passive node: False

        Retention policies: enforced (mode: auto, retention: RECOVERY WINDOW OF 3 DAYS, WAL retention: MAIN)

        No. of available backups: 4

        First available backup: 20220403T022635

        Last available backup: 20220406T021610

        Minimum redundancy requirements: satisfied (4/0)

 

-bash-4.4$ barman diagnose

{

    "global": {

        "config": {

            "barman_home": "/var/lib/barman",

            "barman_user": "barman",

            "basebackup_retry_sleep": "30",

            "basebackup_retry_times": "3",

            "compression": "gzip",

            "errors_list": [],

            "immediate_checkpoint": "true",

            "last_backup_maximum_age": "1 DAYS",

            "log_file": "/var/log/barman/barman.log",

            "reuse_backup": "link"

        },

        "system_info": {

            "barman_ver": "2.19",

            "kernel_ver": "Linux pvlbar0b.bnbquebec.ca 4.18.0-348.20.1.el8_5.x86_64 #1 SMP Tue Mar 8 12:56:54 EST 2022 x86_64 x86_64 x86_64 GNU/Linux",

            "python_ver": "Python 3.6.8",

            "release": "LSB Version:\t:core-4.1-amd64:core-4.1-noarch:cxx-4.1-amd64:cxx-4.1-noarch:desktop-4.1-amd64:desktop-4.1-noarch:printing-4.1-amd64:printing-4.1-noarch\nDistributor ID:\tRedHatEnterprise\nDescription:\tRed Hat Enterprise Linux release 8.5 (Ootpa)\nRelease:\t8.5\nCodename:\tOotpa",

            "rsync_ver": "rsync  version 3.1.3  protocol version 31",

            "ssh_ver": "",

            "timestamp": "2022-04-06T09:37:17.997431-04:00"

        }

    },

    "servers": {

        "pvlpg70c": {

            "backups": {

                "20220403T022635": {

                    "backup_id": "20220403T022635",

                    "backup_label": null,

                    "begin_offset": 40,

                    "begin_time": "2022-04-03T02:26:32.701168-04:00",

                    "begin_wal": "000000020000009F0000009A",

                    "begin_xlog": "9F/9A000028",

                    "config_file": "/var/lib/pgsql/data/postgresql.conf",

                    "copy_stats": {

                        "analysis_time": 0.721035,

                        "analysis_time_per_item": {

                            "pgdata": 0.721035

                        },

                        "copy_time": 0.607593,

                        "copy_time_per_item": {

                            "pg_control": 0.15461,

                            "pgdata": 0.45164

                        },

                        "number_of_workers": 1,

                        "serialized_copy_time": 0.595052,

                        "serialized_copy_time_per_item": {

                            "pg_control": 0.15461,

                            "pgdata": 0.440442

                        },

                        "total_time": 1.431401

                    },

                    "deduplicated_size": 279347,

                    "end_offset": 304,

                    "end_time": "2022-04-03T02:26:34.274986-04:00",

                    "end_wal": "000000020000009F0000009A",

                    "end_xlog": "9F/9A000130",

                    "error": null,

                    "hba_file": "/var/lib/pgsql/data/pg_hba.conf",

                    "ident_file": "/var/lib/pgsql/data/pg_ident.conf",

                    "included_files": null,

                    "mode": "rsync-exclusive",

                    "pgdata": "/var/lib/pgsql/data",

                    "server_name": "pvlpg70c",

                    "size": 27587059754,

                    "status": "DONE",

                    "systemid": "6722145376946109766",

                    "tablespaces": null,

                    "timeline": 2,

                    "version": 90622,

                    "xlog_segment_size": 16777216

                },

                "20220404T022254": {

                    "backup_id": "20220404T022254",

                    "backup_label": null,

                    "begin_offset": 40,

                    "begin_time": "2022-04-04T02:22:51.012437-04:00",

                    "begin_wal": "000000020000009F0000009C",

                    "begin_xlog": "9F/9C000028",

                    "config_file": "/var/lib/pgsql/data/postgresql.conf",

                    "copy_stats": {

                        "analysis_time": 0.685279,

                        "analysis_time_per_item": {

                            "pgdata": 0.685279

                        },

                        "copy_time": 0.590455,

                        "copy_time_per_item": {

                            "pg_control": 0.151368,

                            "pgdata": 0.437755

                        },

                        "number_of_workers": 1,

                        "serialized_copy_time": 0.578027,

                        "serialized_copy_time_per_item": {

                            "pg_control": 0.151368,

                            "pgdata": 0.426659

                        },

                        "total_time": 1.402039

                    },

                    "deduplicated_size": 279347,

                    "end_offset": 248,

                    "end_time": "2022-04-04T02:22:52.564025-04:00",

                    "end_wal": "000000020000009F0000009C",

                    "end_xlog": "9F/9C0000F8",

                    "error": null,

                    "hba_file": "/var/lib/pgsql/data/pg_hba.conf",

                    "ident_file": "/var/lib/pgsql/data/pg_ident.conf",

                    "included_files": null,

                    "mode": "rsync-exclusive",

                    "pgdata": "/var/lib/pgsql/data",

                    "server_name": "pvlpg70c",

                    "size": 27587059754,

                    "status": "DONE",

                    "systemid": "6722145376946109766",

                    "tablespaces": null,

                    "timeline": 2,

                    "version": 90622,

                    "xlog_segment_size": 16777216

                },

                "20220405T021717": {

                    "backup_id": "20220405T021717",

                    "backup_label": null,

                    "begin_offset": 40,

                    "begin_time": "2022-04-05T02:17:14.151580-04:00",

                    "begin_wal": "000000020000009F0000009E",

                    "begin_xlog": "9F/9E000028",

                    "config_file": "/var/lib/pgsql/data/postgresql.conf",

                    "copy_stats": {

                        "analysis_time": 0.73027,

                        "analysis_time_per_item": {

                            "pgdata": 0.73027

                        },

                        "copy_time": 0.638257,

                        "copy_time_per_item": {

                            "pg_control": 0.151434,

                            "pgdata": 0.485477

                        },

                        "number_of_workers": 1,

                        "serialized_copy_time": 0.626546,

                        "serialized_copy_time_per_item": {

                            "pg_control": 0.151434,

                            "pgdata": 0.475112

                        },

                        "total_time": 1.441451

                    },

                    "deduplicated_size": 279347,

                    "end_offset": 304,

                    "end_time": "2022-04-05T02:17:15.737524-04:00",

                    "end_wal": "000000020000009F0000009E",

                    "end_xlog": "9F/9E000130",

                    "error": null,

                    "hba_file": "/var/lib/pgsql/data/pg_hba.conf",

                    "ident_file": "/var/lib/pgsql/data/pg_ident.conf",

                    "included_files": null,

                    "mode": "rsync-exclusive",

                    "pgdata": "/var/lib/pgsql/data",

                    "server_name": "pvlpg70c",

                    "size": 27587059754,

                    "status": "DONE",

                    "systemid": "6722145376946109766",

                    "tablespaces": null,

                    "timeline": 2,

                    "version": 90622,

                    "xlog_segment_size": 16777216

                },

                "20220406T021610": {

                    "backup_id": "20220406T021610",

                    "backup_label": null,

                    "begin_offset": 40,

                    "begin_time": "2022-04-06T02:16:06.404834-04:00",

                    "begin_wal": "000000020000009F000000A0",

                    "begin_xlog": "9F/A0000028",

                    "config_file": "/var/lib/pgsql/data/postgresql.conf",

                    "copy_stats": {

                        "analysis_time": 0.659934,

                        "analysis_time_per_item": {

                            "pgdata": 0.659934

                        },

                        "copy_time": 0.622637,

                        "copy_time_per_item": {

                            "pg_control": 0.162957,

                            "pgdata": 0.458256

                        },

                        "number_of_workers": 1,

                        "serialized_copy_time": 0.610899,

                        "serialized_copy_time_per_item": {

                            "pg_control": 0.162957,

                            "pgdata": 0.447942

                        },

                        "total_time": 1.372549

                    },

                    "deduplicated_size": 279347,

                    "end_offset": 248,

                    "end_time": "2022-04-06T02:16:07.923929-04:00",

                    "end_wal": "000000020000009F000000A0",

                    "end_xlog": "9F/A00000F8",

                    "error": null,

                    "hba_file": "/var/lib/pgsql/data/pg_hba.conf",

                    "ident_file": "/var/lib/pgsql/data/pg_ident.conf",

                    "included_files": null,

                    "mode": "rsync-exclusive",

                    "pgdata": "/var/lib/pgsql/data",

                    "server_name": "pvlpg70c",

                    "size": 27587059754,

                    "status": "DONE",

                    "systemid": "6722145376946109766",

                    "tablespaces": null,

                    "timeline": 2,

                    "version": 90622,

                    "xlog_segment_size": 16777216

                }

            },

            "config": {

                "active": true,

                "archiver": true,

                "archiver_batch_size": 0,

                "backup_directory": "/var/lib/barman/pvlpg70c",

                "backup_method": "rsync",

                "backup_options": "exclusive_backup",

                "bandwidth_limit": null,

                "barman_home": "/var/lib/barman",

                "barman_lock_directory": "/var/lib/barman",

                "basebackup_retry_sleep": 30,

                "basebackup_retry_times": 3,

                "basebackups_directory": "/var/lib/barman/pvlpg70c/base",

                "check_timeout": 30,

                "compression": "gzip",

                "conninfo": "host=172.17.0.51 user=barman port=4407 dbname=portfolio password=*REDACTED*",

                "create_slot": "manual",

                "custom_compression_filter": null,

                "custom_compression_magic": null,

                "custom_decompression_filter": null,

                "description": "pvlpg70c backup config",

                "disabled": false,

                "errors_directory": "/var/lib/barman/pvlpg70c/errors",

                "forward_config_path": false,

                "immediate_checkpoint": true,

                "incoming_wals_directory": "/var/lib/barman/pvlpg70c/incoming",

                "last_backup_maximum_age": "7 days",

                "last_backup_minimum_size": null,

                "last_wal_maximum_age": null,

                "max_incoming_wals_queue": null,

                "minimum_redundancy": 0,

                "msg_list": [],

                "name": "pvlpg70c",

                "network_compression": false,

                "parallel_jobs": 1,

                "path_prefix": null,

                "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_ssh_command": null,

                "recovery_options": "",

                "retention_policy": "window 3 d",

                "retention_policy_mode": "auto",

                "reuse_backup": "link",

                "slot_name": null,

                "ssh_command": "ssh post...@172.17.0.51",

                "streaming_archiver": false,

                "streaming_archiver_batch_size": 0,

                "streaming_archiver_name": "barman_receive_wal",

                "streaming_backup_name": "barman_streaming_backup",

                "streaming_conninfo": "host=172.17.0.51 user=barman port=4407 dbname=portfolio password=*REDACTED*",

                "streaming_wals_directory": "/var/lib/barman/pvlpg70c/streaming",

                "tablespace_bandwidth_limit": null,

                "wal_retention_policy": "simple-wal 3 d",

                "wals_directory": "/var/lib/barman/pvlpg70c/wals"

            },

            "status": {

                "archive_command": "test ! -f barman@pvlbar0b:/var/lib/barman/pvlpg70c/incoming/%f && rsync -a %p barman@pvlbar0b:/var/lib/barman/pvlpg70c/incoming/%f",

                "archive_mode": "on",

                "archive_timeout": 0,

                "archived_count": 27,

                "checkpoint_timeout": 300,

                "config_file": "/var/lib/pgsql/data/postgresql.conf",

                "current_archived_wals_per_second": 3.98540678932389e-05,

                "current_lsn": "9F/A1006900",

                "current_size": 27576976194.0,

                "current_xlog": "000000020000009F000000A1",

                "data_checksums": "off",

                "data_directory": "/var/lib/pgsql/data",

                "failed_count": 0,

                "has_backup_privileges": true,

                "hba_file": "/var/lib/pgsql/data/pg_hba.conf",

                "hot_standby": "off",

                "ident_file": "/var/lib/pgsql/data/pg_ident.conf",

                "is_archiving": true,

                "is_in_recovery": false,

                "is_superuser": true,

                "last_archived_time": "2022-04-06T02:16:08.427032-04:00",

                "last_archived_wal": "000000020000009F000000A0.00000028.backup",

                "last_failed_time": null,

                "last_failed_wal": null,

                "max_replication_slots": "0",

                "max_wal_senders": "0",

                "pgespresso_installed": false,

                "postgres_systemid": "6722145376946109766",

                "replication_slot": null,

                "replication_slot_support": true,

                "server_txt_version": "9.6.22",

                "stats_reset": "2022-03-29T13:26:03.438111-04:00",

                "synchronous_standby_names": [

                    ""

                ],

                "wal_compression": "off",

                "wal_keep_segments": "0",

                "wal_level": "replica",

                "xlog_segment_size": 16777216

            },

            "system_info": {

                "kernel_ver": "Linux pvlpg70c.bnquebec.ca 4.18.0-348.20.1.el8_5.x86_64 #1 SMP Tue Mar 8 12:56:54 EST 2022 x86_64 x86_64 x86_64 GNU/Linux",

                "python_ver": "Python 3.6.8",

                "release": "LSB Version:\t:core-4.1-amd64:core-4.1-noarch:cxx-4.1-amd64:cxx-4.1-noarch:desktop-4.1-amd64:desktop-4.1-noarch:printing-4.1-amd64:printing-4.1-noarch\nDistributor ID:\tRedHatEnterprise\nDescription:\tRed Hat Enterprise Linux release 8.5 (Ootpa)\nRelease:\t8.5\nCodename:\tOotpa",

                "rsync_ver": "rsync  version 3.1.3  protocol version 31",

                "ssh_ver": ""

            },

            "wals": {

                "last_archived_wal_per_timeline": {

                    "00000002": {

                        "compression": "gzip",

                        "name": "000000020000009F000000A0",

                        "size": 27144,

                        "time": 1649225767.9337902

                    }

                }

            }

        }

    }

}

 

 

any help will be greatly appreciated

 

 

 

 

 

Michael Wallace

unread,
Apr 14, 2022, 7:55:18 AMApr 14
to pgba...@googlegroups.com
Hi Norman,

The messages in the log relating to archive_command are because Barman has set archive_command to false in the postgresql config. This is a safety measure to protect against cases where a server has been recovered from a backup but the original server is still running - this would result in WALs from two separate servers being written to the same archive. Once you have verified recovery is successful and nothing else is writing to the WAL archive you can re-enable archive_command and then archiving should continue as normal.

Hope that helps,

Mike

--
--
You received this message because you are subscribed to the "Barman for PostgreSQL" group.
To post to this group, send email to pgba...@googlegroups.com
To unsubscribe from this group, send email to
pgbarman+u...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/pgbarman?hl=en?hl=en-GB

---
You received this message because you are subscribed to the Google Groups "Barman, Backup and Recovery Manager for PostgreSQL" group.
To unsubscribe from this group and stop receiving emails from it, send an email to pgbarman+u...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/pgbarman/74909f48-ff5e-48bf-934a-3e9794effe3dn%40googlegroups.com.

Norman Larose

unread,
Apr 19, 2022, 2:00:24 PMApr 19
to Barman, Backup and Recovery Manager for PostgreSQL
thank you for your reply and have a nice day.
Reply all
Reply to author
Forward
0 new messages