Backups triggering twice with "Run On Incoming Connect Interval"

[Alexandre Denault]

Hi,

I am currently setting up backups for Laptops using the "Run On Incoming Connect Interval" feature. So far, backups are triggering upon connections every 12 to 16 hours, so I'm happy with that. However, every time backups are triggered, a second backup is scheduled to run immediately after. Backups running on normal schedules do not have this problem. Both client (MacOS) and director (Docker running on Linux) are running version 20.0.1. Here is an example of the log :

1623        Backup Cosmos        2021-12-27 22:56:09        2021-12-27 22:56:15        MacHome        Incremental        18        6.37 MB        
1622        Backup Cosmos        2021-12-27 22:55:09        2021-12-27 22:55:24        MacHome        Incremental        385        291.17 MB       
1610        Backup Cosmos        2021-12-27 09:06:38        2021-12-27 09:08:24        MacHome        Incremental        2340        4.69 GB         
1609        Backup Cosmos        2021-12-27 09:04:48        2021-12-27 09:06:34        MacHome        Incremental        2339        4.7 GB         
1608        Backup Cosmos        2021-12-26 18:31:34        2021-12-26 18:33:37        MacHome        Incremental        5138        5.15 GB           
1607        Backup Cosmos        2021-12-26 18:29:04        2021-12-26 18:31:23        MacHome        Incremental        5138        5.15 GB

The configuration of the job is as follows :

Job {

Name = "Backup Cosmos"

Client = "cosmos"

JobDefs = "DefaultJob"

FileSet = "MacHome"

RunOnIncomingConnectInterval = 12h

# Run Script with would ping monitoring system removed for simplicity

}

JobDefs {

Name = "DefaultJob"

Type = Backup

Storage = File

Messages = Standard

Pool = Incremental

Priority = 10

Write Bootstrap = "/var/lib/bareos/%c.bsr"

Full Backup Pool = Full

Differential Backup Pool = Differential

Incremental Backup Pool = Incremental

Max Diff Interval = 10d

Max Full Interval = 35d

}

Client {

Name = cosmos

Address = x.x.x.x

Password = xyz

Connection From Client To Director = yes

Heartbeat Interval = 60

}

On the client, the following line is added to the myself.conf

Connection From Client To Director = yes

I'm happy to supply any other information which might be useful. Does anybody have suggestion on how I can debug this problem?

Cheers,

Alex

[Alexandre Denault]

Hi,

I figure out what it going on and I think this might be a bug. I just don't know how to signal it to the developers. Here is what I have :

Looking at the client log, I noticed that when the first backup job is started on a client, a second socket it openned : 

elita (100): lib/bsys.cc:576-0 ReadStateFile seek to 192

elita (100): lib/recent_job_results_list.cc:57-0 Read num_items=10

elita (10): filed/socket_server.cc:128-0 filed: listening on port 9102

elita (100): lib/jcr.cc:195-0 Construct JobControlRecord

elita (100): lib/bnet_server_tcp.cc:160-0 Addresses host[ipv4;0.0.0.0;9102]

elita (100): lib/bsock.cc:84-0 Construct BareosSocket

elita (100): lib/bsock.cc:163-0 All source addresses

elita (100): lib/bsock_tcp.cc:234-0 Current host[ipv4;10.0.1.204;9101] All host[ipv4;10.0.1.204;9101]

elita (100): lib/bsock_tcp.cc:152-0 who=bareos-dir host=10.0.1.204 port=9101

elita (100): lib/tls_openssl_private.cc:65-0 Construct TlsOpenSslPrivate

elita (100): lib/tls_openssl_private.cc:606-0 Set tcp filedescriptor: <4>

elita (100): lib/tls_openssl_private.cc:618-0 Set protocol: <>

elita (100): lib/tls_openssl_private.cc:552-0 Set ca_certfile: <>

elita (100): lib/tls_openssl_private.cc:558-0 Set ca_certdir: <>

elita (100): lib/tls_openssl_private.cc:564-0 Set crlfile_: <>

elita (100): lib/tls_openssl_private.cc:570-0 Set certfile_: <>

elita (100): lib/tls_openssl_private.cc:576-0 Set keyfile_: <>

elita (100): lib/tls_openssl_private.cc:594-0 Set dhfile_: <>

elita (100): lib/tls_openssl_private.cc:612-0 Set cipherlist: <>

elita (100): lib/tls_openssl_private.cc:600-0 Set Verify Peer: <false>

elita (50): lib/tls_openssl.cc:65-0 Preparing TLS_PSK CLIENT context for identity R_CLIENT elita

elita (100): lib/tls_openssl_private.cc:537-0 psk_client_cb. identity: R_CLIENT elita.

elita (50): lib/bnet.cc:196-0 TLS client negotiation established.

elita (10): filed/dir_cmd.cc:2331-0 Opened connection with Director bareos-dir

elita (100): lib/cram_md5.cc:166-0 cram-get received: auth cram-md5 <489928684.1641010677@R_DIRECTOR::bareos-dir> ssl=1

elita (50): lib/cram_md5.cc:62-0 my_name: <R_CLIENT::elita> - challenge_name: <R_DIRECTOR::bareos-dir>

elita (99): lib/cram_md5.cc:231-0 sending resp to challenge: m89SGwF7Ax+VTU++K5+zEC

elita (50): lib/cram_md5.cc:106-0 send: auth cram-md5 <1288004040.1641010677@R_CLIENT::elita> ssl=1

elita (50): lib/cram_md5.cc:134-0 Authenticate OK f59utyt55ldroh+th4+gFD

elita (100): lib/jcr.cc:195-0 Construct JobControlRecord

elita (100): filed/dir_cmd.cc:462-0 <dird: JobId=1695 Job=Backup_Elita.2022-01-01_04.18.15_21 SDid=24 SDtime=1640922268 Authorization=LCEA-AANP-JPBG-CCLB-FEOF-NNMP-FMBO-PIFL ssl=4

elita (100): lib/bsock.cc:84-0 Construct BareosSocket

elita (100): lib/bsock.cc:163-0 All source addresses

elita (100): filed/dir_cmd.cc:473-0 Executing JobId= command.

elita (100): lib/bsock_tcp.cc:234-0 Current host[ipv4;10.0.1.204;9101] All host[ipv4;10.0.1.204;9101]

elita (5): filed/dir_cmd.cc:1623-0 set sd auth key

elita (5): filed/dir_cmd.cc:1626-0 set sd ssl_policy to 4

elita (100): lib/bsock_tcp.cc:152-0 who=bareos-dir host=10.0.1.204 port=9101

elita (100): lib/tls_openssl_private.cc:65-0 Construct TlsOpenSslPrivate

elita (100): lib/tls_openssl_private.cc:606-0 Set tcp filedescriptor: <5>

elita (100): lib/tls_openssl_private.cc:618-0 Set protocol: <>

elita (100): lib/tls_openssl_private.cc:552-0 Set ca_certfile: <>

elita (100): lib/tls_openssl_private.cc:558-0 Set ca_certdir: <>

elita (100): lib/tls_openssl_private.cc:564-0 Set crlfile_: <>

elita (100): lib/tls_openssl_private.cc:570-0 Set certfile_: <>

elita (100): lib/tls_openssl_private.cc:576-0 Set keyfile_: <>

elita (100): lib/tls_openssl_private.cc:594-0 Set dhfile_: <>

elita (100): lib/tls_openssl_private.cc:612-0 Set cipherlist: <>

elita (100): lib/tls_openssl_private.cc:600-0 Set Verify Peer: <false>

elita (50): lib/tls_openssl.cc:65-0 Preparing TLS_PSK CLIENT context for identity R_CLIENT elita

elita (100): lib/tls_openssl_private.cc:537-0 psk_client_cb. identity: R_CLIENT elita.

elita (50): lib/bnet.cc:196-0 TLS client negotiation established.

elita (10): filed/dir_cmd.cc:2331-0 Opened connection with Director bareos-dir

elita (100): filed/dir_cmd.cc:462-0 <dird: level = differential mtime_only=0

elita (100): filed/dir_cmd.cc:473-0 Executing level = command.

elita (10): filed/dir_cmd.cc:1447-0 LevelCmd: level = differential mtime_only=0

elita (100): filed/dir_cmd.cc:462-0 <dird: level = since_utime 1640620669 mtime_only=0 prev_job=Backup_Elita.2021-12-27_15.57.08_06

elita (100): filed/dir_cmd.cc:473-0 Executing level = command.

elita (100): lib/cram_md5.cc:166-0 elita (10): filed/dir_cmd.cc:1447-0 LevelCmd: level = since_utime 1640620669 mtime_only=0 prev_job=Backup_Elita.2021-12-27_15.57.08_06

cram-get received: auth cram-md5 <642302895.1641010697@R_DIRECTOR::bareos-dir> ssl=1

elita (100): filed/dir_cmd.cc:1499-0 since_time=1640620669 prev_job=Backup_Elita.2021-12-27_15.57.08_06

elita (50): lib/cram_md5.cc:62-0 my_name: <R_CLIENT::elita> - challenge_name: <R_DIRECTOR::bareos-dir>

elita (99): lib/cram_md5.cc:231-0 sending resp to challenge: K++4U7+Bt4UHJ4+U4QoiSB

elita (50): lib/cram_md5.cc:106-0 send: auth cram-md5 <861086444.1641010697@R_CLIENT::elita> ssl=1

elita (50): lib/cram_md5.cc:134-0 Authenticate OK cxBcYkYgy5xq17/ucR+b1D

According to this page ( https://docs.bareos.org/TasksAndConcepts/NetworkSetup.html ) this is normal behavior :

When a waiting connection is used for a job, the Bareos File Daemon will detect this and creates an additional connection. This is required, to keep the client responsive for additional commands, like cancel.

The problem is that the director detects this as a new incoming connection and triggers a second backup. I can even see the connect time change for the client in the Bareos-Dir Status (Client Initiated Connections (waiting for jobs)). Is there a special way to ignore this second connection, or is it possible that "Run On Incoming Connect Interval" is broken?

Thanks,

[Alexandre Denault]

Hi,

Found out how and posted : https://bugs.bareos.org/view.php?id=1417

Thanks,

[khvalera]

Just ran into this same problem :( Linux Version 21.1.3   

среда, 5 января 2022 г. в 15:13:15 UTC+2, alexandr...@gmail.com: