Failed archive command message with Remote Recovery

Norman Larose

unread,

Apr 6, 2022, 9:47:33 AM4/6/22

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 AM4/14/22

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 PM4/19/22

to Barman, Backup and Recovery Manager for PostgreSQL

thank you for your reply and have a nice day.

Reply all

Reply to author

Forward