Barman backup fails with Cannot terminate exclusive backup

[Douglas Reed]

Hi

We are having a problem with one of our barman backups and wonder if you could help us

Details are as follows

The first time it worked fine but the following day it failed with the following messages;

Backup start at LSN: 5057/2C928440 (00000002000050570000002C, 00928440)
Starting backup copy via rsync/SSH for 20200205T003502
Copy done (time: 1 hour, 2 minutes, 33 seconds)
Asking PostgreSQL server to finalize the backup.
ERROR: Backup failed issuing stop backup command.
DETAILS: Cannot terminate exclusive backup. You might have to manually execute pg_stop_backup on your PostgreSQL server
Processing xlog segments from file archival for o8z-data1.rs.fsbtech.com
        000000020000505B000000EB
        000000020000505B000000EC
        000000020000505B000000ED
        000000020000505B000000EE
        000000020000505B000000EF
        000000020000505B000000F0
        000000020000505B000000F1
        000000020000505B000000F2
        000000020000505B000000F3
        000000020000505B000000F4
        000000020000505B000000F5
        000000020000505B000000F6
        000000020000505B000000F7
        000000020000505B000000F8
        000000020000505B000000F9
        000000020000505B000000FA
        000000020000505B000000FB
        000000020000505B000000FC
        000000020000505B000000FD
        000000020000505B000000FE
        000000020000505B000000FF
        000000020000505C00000000

I logged into the target database server and issue a stop backup command and tried again manually later but with the same result


The other backup which we are running is smaller and works fine

barman list-backup all

data1.rs.fsbtech.com 20200205T020742 - Wed Feb  5 02:49:26 2020 - Size: 288.2 GiB - WAL Size: 6.5 GiB
data1.rs.fsbtech.com 20200204T003502 - Tue Feb  4 01:14:48 2020 - Size: 287.6 GiB - WAL Size: 19.2 GiB
o8z-data1.rs.fsbtech.com 20200205T141312 - EMPTY
o8z-data1.rs.fsbtech.com 20200205T120832 - FAILED
o8z-data1.rs.fsbtech.com 20200204T100548 - Tue Feb  4 11:19:06 2020 - Size: 522.7 GiB - WAL Size: 186.8 GiB (tablespaces: data2:/data/pg/pg_data, temp_disk:/data/pg/pg_data_tmp)

The status and checks are as follows;

barman check o8z-data1.rs.fsbtech.com

Server o8z-data1.rs.fsbtech.com:
    PostgreSQL: OK
    is_superuser: OK
    wal_level: OK
    directories: OK
    retention policy settings: OK
    backup maximum age: OK (no last_backup_maximum_age provided)
    compression settings: OK
    failed backups: FAILED (there are 1 failed backups)
    minimum redundancy requirements: OK (have 1 backups, expected at least 0)
    ssh: OK (PostgreSQL server)
    not in recovery: OK
    systemid coherence: OK
    archive_mode: OK
    archive_command: OK
    continuous archiving: OK
    archiver errors: OK

barman status o8z-data1.rs.fsbtech.com

Server o8z-data1.rs.fsbtech.com:
    Description: o8z platform
    Active: True
    Disabled: False
    PostgreSQL version: 9.6.16
    Cluster state: in production
    pgespresso extension: Not available
    Current data size: 515.7 GiB
    PostgreSQL Data directory: /var/lib/pgsql/9.6/data
    Current WAL segment: 000000020000506D00000063
    PostgreSQL 'archive_command' setting: /home/postgres/bin/pgWalSender.bsh %p %f
    Last archived WAL: 000000020000506D00000062, at Wed Feb  5 13:25:51 2020
    Failures of WAL archiver: 0
    Server WAL archiving rate: 58.09/hour
    Passive node: False
    Retention policies: not enforced
    No. of available backups: 1
    First available backup: 20200204T100548
    Last available backup: 20200204T100548
    Minimum redundancy requirements: satisfied (1/0)

Many thanks

[Jan Birk]

Hi,

Have you - in any ways - invalidated the ssh keys?

ex can you use ssh without passwords?

Best

Jan

> This communication and any attachments contain information which is
> confidential and maybe subject to legal privilege. It is intended for the
> recipients only. If you are not the intended recipient you must not copy,
> distribute, publish rely on or otherwise use without the sole consent of FSB
> Technology (UK) Ltd. Some of our communications may contain confidential
> information which would be a criminal offence to disclose or use without the
> explicit consent and of authority of FSB Technology (UK) Ltd. Electronic
> messages are not secure or error free and can contain viruses or may be
> delayed, the sender is not liable for any of these occurrences. FSB Technology
> (UK) Ltd reserves the right to monitor, record and retain electronic messages.
> For compliance with legal and regulatory standards. If you receive this e-mail
> in error, please notify cont...@fsbtech.com immediately and delete the e-
> mail from your computer. This e-mail is not intended to, and should it be
> taken to create any legal relationship or contractual agreement with FSB
> Technology (UK) Ltd.
> --
> --
> 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/4e03c520-ef02-4a4c-bfef-4e3018584ae0%40googlegroups.com
> .

[Douglas Reed]

Hi

I've tested connections in both direction with the ssh keys, it connects without prompting etc, also I have tried connecting using psql from user barman on the backup server to the database on the target server, all seems fine

Regards

[Luca Ferrari]

On Wed, Feb 5, 2020 at 3:30 PM Douglas Reed <dou...@fsbtech.com> wrote:
> DETAILS: Cannot terminate exclusive backup. You might have to manually execute pg_stop_backup on your PostgreSQL server

I don't have a barman machine at my fingertips right now, but I'm
pretty sure exclusive backups are not the default option for a 9.6
server.
Since in the status output there's a pg_espresso line, any chance you
are running a quite old barman?

[Douglas Reed]

Hi

I'm running version 2.10

[Douglas Reed]

I setup debug in the control file

Here is a cut of the logfile starting at about the point that the backup started, up until it failed

Regards

[Douglas Reed]

 xxx

[Luca Ferrari]

This is what emerges from the logs:

Error issuing pg_stop_backup command: server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.

any clue on the postgresql side? Something that can tell us, from the
postgresql logs, why he is closing the connection?

I also suspect this message is out of date (or there is something in
the configuration that is forcing exclusive backup):

ERROR: Backup failed issuing stop backup command.
DETAILS: Cannot terminate exclusive backup. You might have to manually
execute pg_stop_backup on your PostgreSQL server

Luca

[Douglas Reed]

Hi

-- Test backup run between 14:08 and 15:39

05/02/20 @ 14:08 - Starting
05/02/20 @ 14:08 -  SERVER_ID=o8z-data1.rs.fsbtech.com    PURGE_OLD=N    PUSH_WAL=N    PUSH_BASE_BK=N    PURGE_OLD_S3=N
05/02/20 @ 14:08 - Sleeping for 3mins
05/02/20 @ 14:13 - Backing up target o8z-data1.rs.fsbtech.com
Starting backup using rsync-exclusive method for server o8z-data1.rs.fsbtech.com in /data/barman/o8z-data1.rs.fsbtech.com/base/20200205T141312
Backup start at LSN: 506E/C8F602B0 (000000020000506E000000C8, 00F602B0)
Starting backup copy via rsync/SSH for 20200205T141312
Copy done (time: 1 hour, 1 minute, 59 seconds)

Asking PostgreSQL server to finalize the backup.

ERROR: Backup failed issuing stop backup command.
DETAILS: Cannot terminate exclusive backup. You might have to manually execute pg_stop_backup on your PostgreSQL server

05/02/20 @ 15:39 - ERROR: Performing backup (1)


-- I was able to get the following from the logs


Feb  5 12:03:31 o8z-data1 postgres[166045]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 12:03:31 o8z-data1 postgres[166045]: [9-1] user=barman,db=postgres,app=barmanclient=172.10.1.11 LOG:  duration: 87.900 ms  statement: SELECT sum(pg_tablespace_size(oid)) FROM pg_tablespace
Feb  5 12:03:31 o8z-data1 postgres[166045]: [10-1] user=barman,db=postgres,app=barmanclient=172.10.1.11 LOG:  duration: 42.651 ms  statement: SELECT *, current_setting('archive_mode') IN ('on', 'always') AND (last_failed_wal IS NULL OR last_failed_wal LIKE '%.history' AND substring(last_failed_wal from 1 for 8) <= substring(last_archived_wal from 1 for 8) OR last_failed_time <= last_archived_time) AS is_archiving, CAST (archived_count AS NUMERIC) / EXTRACT (EPOCH FROM age(now(), stats_reset)) AS current_archived_wals_per_second FROM pg_stat_archiver
Feb  5 12:03:31 o8z-data1 postgres[166045]: [11-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  disconnection: session time: 0:00:00.254 user=barman database=postgres host=172.10.1.11 port=35244
Feb  5 12:08:32 o8z-data1 postgres[168047]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 12:09:47 o8z-data1 postgres[168549]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 12:09:47 o8z-data1 postgres[168549]: [9-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  disconnection: session time: 0:00:00.281 user=barman database=postgres host=172.10.1.11 port=35262
Feb  5 12:16:57 o8z-data1 postgres[168047]: [9-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  duration: 504600.110 ms  statement: SELECT location, (pg_xlogfile_name_offset(location)).*, now() AS timestamp FROM pg_start_backup('Barman backup o8z-data1.rs.fsbtech.com 20200205T120832',false) AS location
Feb  5 13:23:58 o8z-data1 postgres[200730]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 13:23:58 o8z-data1 postgres[200730]: [9-1] user=barman,db=postgres,app=psqlclient=172.10.1.11 LOG:  disconnection: session time: 0:00:00.008 user=barman database=postgres host=172.10.1.11 port=35370
Feb  5 13:26:12 o8z-data1 postgres[201517]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 13:26:12 o8z-data1 postgres[201517]: [9-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  disconnection: session time: 0:00:00.314 user=barman database=postgres host=172.10.1.11 port=35374
Feb  5 13:26:32 o8z-data1 postgres[201694]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 13:26:32 o8z-data1 postgres[201694]: [9-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  disconnection: session time: 0:00:00.044 user=barman database=postgres host=172.10.1.11 port=35378
Feb  5 13:37:24 o8z-data1 postgres[206491]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 13:37:24 o8z-data1 postgres[206491]: [9-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  disconnection: session time: 0:00:00.058 user=barman database=postgres host=172.10.1.11 port=35466
Feb  5 13:37:57 o8z-data1 postgres[206774]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 13:37:57 o8z-data1 postgres[206774]: [9-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  disconnection: session time: 0:00:00.041 user=barman database=postgres host=172.10.1.11 port=35598
Feb  5 14:08:11 o8z-data1 postgres[219638]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 14:08:11 o8z-data1 postgres[219638]: [9-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  disconnection: session time: 0:00:00.061 user=barman database=postgres host=172.10.1.11 port=35702
Feb  5 14:13:12 o8z-data1 postgres[221621]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 14:22:05 o8z-data1 postgres[221621]: [9-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  duration: 532554.465 ms  statement: SELECT location, (pg_xlogfile_name_offset(location)).*, now() AS timestamp FROM pg_start_backup('Barman backup o8z-data1.rs.fsbtech.com 20200205T141312',false) AS location
Feb  5 14:28:16 o8z-data1 postgres[168047]: [10-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  could not receive data from client: Connection timed out
Feb  5 14:28:16 o8z-data1 postgres[168047]: [11-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  unexpected EOF on client connection with an open transaction
Feb  5 14:28:16 o8z-data1 postgres[168047]: [12-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  disconnection: session time: 2:19:44.252 user=barman database=postgres host=172.10.1.11 port=35256
Feb  5 15:22:14 o8z-data1 postgres[6369]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  5 15:22:14 o8z-data1 postgres[6369]: [9-1] user=barman,db=postgres,app=psqlclient=172.10.1.11 LOG:  disconnection: session time: 0:00:00.010 user=barman database=postgres host=172.10.1.11 port=35802
Feb  5 16:33:24 o8z-data1 postgres[221621]: [10-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  could not receive data from client: Connection timed out
Feb  5 16:33:24 o8z-data1 postgres[221621]: [11-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  unexpected EOF on client connection with an open transaction
Feb  5 16:33:24 o8z-data1 postgres[221621]: [12-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  disconnection: session time: 2:20:12.231 user=barman database=postgres host=172.10.1.11 port=35714
Feb  6 00:30:01 o8z-data1 postgres[240990]: [8-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  connection authorized: user=barman database=postgres
Feb  6 00:30:01 o8z-data1 postgres[240990]: [9-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG:  disconnection: session time: 0:00:00.071 user=barman database=postgres host=172.10.1.11 port=36378

--
--
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/CAKoxK%2B6cNrqb6t3T5EXbqmUNrs73MtkOTzzV1dE1OrPSssoi_A%40mail.gmail.com.

--

____________________________

Douglas Reed (DBA)

FSB Technology (UK) Ltd

Avalon House

57-63 Scrutton Street
London, EC2A 4PF
t: +44 (0) 203 974 8610

This communication and any attachments contain information which is confidential and maybe subject to legal privilege. It is intended for the recipients only. If you are not the intended recipient you must not copy, distribute, publish rely on or otherwise use without the sole consent of FSB Technology (UK) Ltd. Some of our communications may contain confidential information which would be a criminal offence to disclose or use without the explicit consent and of authority of FSB Technology (UK) Ltd. Electronic messages are not secure or error free and can contain viruses or may be delayed, the sender is not liable for any of these occurrences. FSB Technology (UK) Ltd reserves the right to monitor, record and retain electronic messages. For compliance with legal and regulatory standards. If you receive this e-mail in error, please notify cont...@fsbtech.com immediately and delete the e-mail from your computer. This e-mail is not intended to, and should it be taken to create any legal relationship or contractual agreement with FSB Technology (UK) Ltd.

[Luca Ferrari]

On Thu, Feb 6, 2020 at 9:50 AM Douglas Reed <dou...@fsbtech.com> wrote:
> 05/02/20 @ 14:13 - Backing up target o8z-data1.rs.fsbtech.com
> Starting backup using rsync-exclusive method for server o8z-data1.rs.fsbtech.com in /data/barman/o8z-data1.rs.fsbtech.com/base/20200205T141312

This clarify (to me) the need for an exclusive backup, sorry I was
thinking about streaming replication.

> Feb 5 14:28:16 o8z-data1 postgres[168047]: [11-1] user=barman,db=postgres,app=[unknown]client=172.10.1.11 LOG: unexpected EOF on client connection with an open transaction

this means barman is dropping the connection, but I don't know why. It
could be an application problem (exception?) or a timeout somewhere in
python code.
Barman developers could provide some hints.

Luca

[Douglas Reed]

Hi again

Just had another backup failure, different database this time (but bigger)

The interesting thing is that all of these backups run perfectly on our Rackspace environment
using barman version 2.4 but after we have migrated to another provider. We seem to be getting
failures on our larger databases.

06/02/20 @ 10:10 - Starting
06/02/20 @ 10:10 -  SERVER_ID=o8k-data1.rs.fsbtech.com    PURGE_OLD=N    PUSH_WAL=N    PUSH_BASE_BK=N    PURGE_OLD_S3=N
06/02/20 @ 10:10 - Sleeping for 3mins
06/02/20 @ 10:15 - Backing up target o8k-data1.rs.fsbtech.com
Starting backup using rsync-exclusive method for server o8k-data1.rs.fsbtech.com in /data/barman/o8k-data1.rs.fsbtech.com/base/20200206T101524
Backup start at LSN: 855C/57A62B60 (000000020000855C00000057, 00A62B60)
This is the first backup for server o8k-data1.rs.fsbtech.com
WAL segments preceding the current backup have been found:
        0000000200008553000000DB from server o8k-data1.rs.fsbtech.com has been removed
        0000000200008553000000DC from server o8k-data1.rs.fsbtech.com has been removed
        0000000200008553000000DD from server o8k-data1.rs.fsbtech.com has been removed
        0000000200008553000000DE from server o8k-data1.rs.fsbtech.com has been removed
        0000000200008553000000DF from server o8k-data1.rs.fsbtech.com has been removed
        0000000200008553000000E0 from server o8k-data1.rs.fsbtech.com has been removed
         .........
Starting backup copy via rsync/SSH for 20200206T101524
Copy done (time: 1 hour, 17 minutes, 18 seconds)
This is the first backup for server o8k-data1.rs.fsbtech.com

Asking PostgreSQL server to finalize the backup.
ERROR: Backup failed issuing stop backup command.
DETAILS: Cannot terminate exclusive backup. You might have to manually execute pg_stop_backup on your PostgreSQL server

06/02/20 @ 11:51 - ERROR: Performing backup (1)
06/02/20 @ 11:51 - dbBackup: Performing backup

Thanks

--
--
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/CAKoxK%2B4N2i03tnYHPHNqhp5CbG_SoOf_sZVbFkjh2_3BNqo6Ew%40mail.gmail.com.

[Douglas Reed]

Sorry forgot this;

data1.rs.fsbtech.com 20200206T003503 - Thu Feb  6 01:13:45 2020 - Size: 288.8 GiB - WAL Size: 6.8 GiB
data1.rs.fsbtech.com 20200205T020742 - Wed Feb  5 02:49:26 2020 - Size: 288.2 GiB - WAL Size: 15.1 GiB
o8k-data1.rs.fsbtech.com 20200206T101524 - FAILED
o8z-data1.rs.fsbtech.com 20200204T100548 - Tue Feb  4 11:19:06 2020 - Size: 522.7 GiB - WAL Size: 332.4 GiB (tablespaces: data2:/data/pg/pg_data, temp_disk:/data/pg/pg_data_tmp)

[Luca Ferrari]

On Thu, Feb 6, 2020 at 12:57 PM Douglas Reed <dou...@fsbtech.com> wrote:
> The interesting thing is that all of these backups run perfectly on our Rackspace environment
> using barman version 2.4 but after we have migrated to another provider. We seem to be getting
> failures on our larger databases.

Were backups running on the new provider with barman 2.4 or you
changed provider and barman version at same time?
This could be useful for barman developers in the case there's a regression.

Luca

[Douglas Reed]

We have a new backup server and installed the latest version of barman

This is a Nutanix environment

Regards

--
--
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/CAKoxK%2B4CmwzPYF0o9Jq0jyjeRrGaktFOgvJv3nMqdFL8BEgMYg%40mail.gmail.com.

[Muhammad Amer Siddique]

Two things are interesting.

1. Manual execution of command to stop backup given same error result. Please check if dB is in backup state.

2. Is there some firewall between your servers which can terminate session ?