View Issue Details

IDProjectCategoryView StatusLast Update
0001466bareos-corefile daemonpublic2022-05-27 23:43
Reporterkhvalera Assigned To 
PriorityurgentSeverityminorReproducibilityalways
Status newResolutionopen 
PlatformMacOSMacOS XOS Version10
Product Version21.1.3 
Summary0001466: Backups triggering twice with "Run On Incoming Connect Interval
DescriptionI 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

Steps To ReproduceThe 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
Additional InformationLooking at the client log, I noticed that when the first backup job is started on a client, a second socket it opened :

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?
TagsNo tags attached.
bareos-master: impact
bareos-master: action
bareos-19.2: impact
bareos-19.2: action
bareos-18.2: impact
bareos-18.2: action
bareos-17.2: impact
bareos-17.2: action
bareos-16.2: impact
bareos-16.2: action
bareos-15.2: impact
bareos-15.2: action
bareos-14.2: impact
bareos-14.2: action
bareos-13.2: impact
bareos-13.2: action
bareos-12.4: impact
bareos-12.4: action

Activities

Beshiros

Beshiros

2022-05-27 23:11

reporter   ~0004626

I had the problem when running on Bareos 20.1. Upgrading to Bareos 21 and I still have the problem.
khvalera

khvalera

2022-05-27 23:11

reporter   ~0004627

Just ran into this same problem :( Linux Version 21.1.3

Issue History

Date Modified Username Field Change
2022-05-27 23:11 khvalera New Issue
2022-05-27 23:11 khvalera Issue generated from: 0001417
2022-05-27 23:11 khvalera Note Added: 0004626
2022-05-27 23:11 khvalera Note Added: 0004627