bareos icon indicating copy to clipboard operation
bareos copied to clipboard
verified publisher icon bareos

Restore job starts using tape volume while other restore job is unloading it

Open SamuelBoerlin opened this issue 1 year ago • 6 comments

Bareos component version

bareos-dir, bareos-sd: 23.0.4~pre56.5de4c8180 (bareos.org community build) bareos-fd: 22.0.3 (24Mar23) 3.18_alpha20230329,alpine (community build for alpine)

Steps to reproduce

  1. Autochanger with two tape drives
  2. A couple of restore jobs running at the same time which need to restore from the same volume
  3. Relevant configurations:

Director:

Job {
  Name = Restore-Files
  Description = "Standard restore job."
  Type = Restore
  Client = bareos-fd
  FileSet = SelfTest

  Storage = File-IDF
  Pool = IDF-Incremental

  Priority = 10
  Allow Mixed Priority = yes

  Prefer Mounted Volumes = no
  Maximum Concurrent Jobs = 4

  Messages = Standard

  Where = /tmp/bareos-restores
}
Storage {
  Name = Tape
  Media Type = "LTO8_NEOXL80"
  Address = "127.0.0.1"

  Device = "Autochanger1"
  Auto Changer = yes

  Maximum Concurrent Jobs = 64

  Allow Compression = no

  Collect Statistics = yes
}

SD:

Autochanger {
  Name = "Autochanger1"

  Changer Device = /dev/tape/by-id/scsi-35000e111c71ac0b8
  Device = TapeDevice1, TapeDevice2

  Changer Command = "/usr/lib/bareos/scripts/mtx-changer %c %o %S %a %d"
}
Device {
  Name = TapeDevice1
  Description = "Tape device, LTO 8"
  Media Type = "LTO8_NEOXL80"

  Archive Device = /dev/tape/by-id/scsi-35000e111c71ac0b5-nst
  Drive Index = 0
  Autochanger = yes
  Removable Media = yes
  Always Open = yes

  Spool Directory = "/var/spool/bareos"

  Maximum File Size = 24GB
  Maximum Changer Wait = 15 minutes
  Drive Tape Alert Enabled = yes

  Maximum Concurrent Jobs = 1
}
Device {
  Name = TapeDevice2
  Description = "Tape device, LTO 8"
  Media Type = "LTO8_NEOXL80"

  Archive Device = /dev/tape/by-id/scsi-35000e111c71ac0bf-nst
  Drive Index = 1
  Autochanger = yes
  Removable Media = yes
  Always Open = yes

  Spool Directory = "/var/spool/bareos"

  Maximum File Size = 24GB
  Maximum Changer Wait = 15 minutes
  Drive Tape Alert Enabled = yes

  Maximum Concurrent Jobs = 1 
}

Expected results

I would expect jobs to reserve a volume (including while it's being unloaded from a drive) and then not allow other jobs to use it until it's done or no longer using that volume.

Actual results

If two concurrently running (restore) jobs attempt to reserve and read the same volume on two different drives it can sometimes happen that one job begins trying to read from a volume while another is currently unloading it, which causes one of the jobs to fail to restore anything.

More specifically: Job 126146 unloads the volume from TapeDevice2 (drive 1) so that it can load it into TapeDevice1 (drive 0). Job 126148 starts using TapeDevice2 (Using Device "TapeDevice2" to read, Ready to read from volume "UB1067L8" on device "TapeDevice2") shortly after, while the unloading is probably still in progress. Job 126148 then of course can't restore anything because there's no volume loaded anymore, or it's in the process of being unloaded, but surprisingly it exits only with a warning (Warning: File count mismatch: expected=1 , restored=0) and not error. Job 126146 meanwhile logs an error that the unload command failed (probably because tape library detects that something is wrong and fails the command, see logs), then however the job proceeds and successfully restores.

Environment

- OS:

NAME="Ubuntu"
VERSION="20.04.6 LTS (Focal Fossa)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 20.04.6 LTS"
VERSION_ID="20.04"
HOME_URL="https://www.ubuntu.com/"
SUPPORT_URL="https://help.ubuntu.com/"
BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/"
PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy"
VERSION_CODENAME=focal
UBUNTU_CODENAME=focal
- Tape library/drives: NEOXL80, 2x Ultrium HH08 LTO8 drives

Relevant log output

Logs of the two conflicting restore jobs:

2024-06-26 03:09:01.047	bareos-dir JobId 126146: Start Restore Job Restore-Files.2024-06-26_03.08.58_55
2024-06-26 03:09:01.263	bareos-dir JobId 126146: Connected Storage daemon at 127.0.0.1:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
2024-06-26 03:09:01.431	bareos-dir JobId 126146:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
2024-06-26 03:09:01.627	bareos-dir JobId 126146: Using Device "TapeDevice1" to read.
2024-06-26 03:09:01.831	bareos-dir JobId 126146: Probing client protocol... (result will be saved until config reload)
2024-06-26 03:09:01.981	bareos-dir JobId 126146: Using Client Initiated Connection (bsync-dsp-dev-02).
2024-06-26 03:09:02.143	bareos-dir JobId 126146:    Handshake: Immediate TLS 
2024-06-26 03:09:02.351	bareos-dir JobId 126146:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
2024-06-26 03:09:04.531	bsync-dsp-dev-02 JobId 126146: Connected Storage daemon at 131.152.51.191:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
2024-06-26 03:09:04.699	bsync-dsp-dev-02 JobId 126146:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
2024-06-26 03:09:04.855	bareos-sd JobId 126146: 3307 Issuing autochanger "unload slot 84, drive 0" command.
2024-06-26 03:10:39.534	bareos-dir JobId 126148: Start Restore Job Restore-Files.2024-06-26_03.10.37_57
2024-06-26 03:10:39.699	bareos-dir JobId 126148: Connected Storage daemon at 127.0.0.1:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
2024-06-26 03:10:39.795	bareos-dir JobId 126148:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
2024-06-26 03:12:00.495	bareos-sd JobId 126146: 3307 Issuing autochanger "unload slot 87, drive 1" command.
2024-06-26 03:12:00.559	bareos-dir JobId 126148: Using Device "TapeDevice2" to read.
2024-06-26 03:12:00.691	bareos-dir JobId 126148: Probing client protocol... (result will be saved until config reload)
2024-06-26 03:12:00.825	bareos-dir JobId 126148: Using Client Initiated Connection (bsync-dsp-dev-06).
2024-06-26 03:12:00.979	bareos-dir JobId 126148:    Handshake: Immediate TLS 
2024-06-26 03:12:01.135	bareos-dir JobId 126148:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
2024-06-26 03:12:03.286	bsync-dsp-dev-06 JobId 126148: Connected Storage daemon at 131.152.51.191:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
2024-06-26 03:12:03.475	bsync-dsp-dev-06 JobId 126148:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
2024-06-26 03:13:35.729	bareos-sd JobId 126148: Ready to read from volume "UB1067L8" on device "TapeDevice2" (/dev/tape/by-id/scsi-35000e111c71ac0bf-nst).
2024-06-26 03:13:35.839	bareos-sd JobId 126148: Forward spacing Volume "UB1067L8" to file:block 70:0.
2024-06-26 03:15:50.264	bareos-sd JobId 126146: 3997 Bad autochanger "unload slot 87, drive 1": ERR=Child exited with code 1.
2024-06-26 03:15:51.749	bareos-sd JobId 126146: Warning: stored/acquire.cc:275 Read open device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst) Volume "UB1067L8" failed: ERR=backends/generic_tape_device.cc:127 Unable to open device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst): ERR=No medium found
2024-06-26 03:16:41.337	bareos-sd JobId 126148: Releasing device "TapeDevice2" (/dev/tape/by-id/scsi-35000e111c71ac0bf-nst).
2024-06-26 03:16:41.449	bareos-sd JobId 126146: 3307 Issuing autochanger "unload slot 87, drive 1" command.
2024-06-26 03:16:41.591	bareos-dir JobId 126148: Warning: File count mismatch: expected=1 , restored=0
2024-06-26 03:16:41.696	bareos-dir JobId 126148: Bareos bareos-dir 23.0.4~pre56.5de4c8180 (21Jun24):
  Build OS:               Ubuntu 20.04.5 LTS
  JobId:                  126148
  Job:                    Restore-Files.2024-06-26_03.10.37_57
  Restore Client:         "bsync-dsp-dev-06" 22.0.3 (24Mar23) 3.18_alpha20230329,alpine
  Start time:             26-Jun-2024 03:10:39
  End time:               26-Jun-2024 03:16:41
  Elapsed time:           6 mins 2 secs
  Files Expected:         1
  Files Restored:         0
  Bytes Restored:         0
  Rate:                   0.0 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Bareos binary info:     Bareos community build (UNSUPPORTED): Get professional support from https://www.bareos.com
  Job triggered by:       User
  Termination:            Restore OK -- with warnings
2024-06-26 03:18:06.451	bareos-sd JobId 126146: 3304 Issuing autochanger "load slot 87, drive 0" command.
2024-06-26 03:18:42.375	bareos-sd JobId 126146: 3305 Autochanger "load slot 87, drive 0", status is OK.
2024-06-26 03:18:44.671	bareos-sd JobId 126146: Ready to read from volume "UB1067L8" on device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst).
2024-06-26 03:18:44.767	bareos-sd JobId 126146: Forward spacing Volume "UB1067L8" to file:block 70:0.
2024-06-26 03:21:12.103	bareos-sd JobId 126146: Releasing device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst).
2024-06-26 03:21:13.023	bareos-dir JobId 126146: Bareos bareos-dir 23.0.4~pre56.5de4c8180 (21Jun24):
  Build OS:               Ubuntu 20.04.5 LTS
  JobId:                  126146
  Job:                    Restore-Files.2024-06-26_03.08.58_55
  Restore Client:         "bsync-dsp-dev-02" 22.0.3 (24Mar23) 3.18_alpha20230329,alpine
  Start time:             26-Jun-2024 03:09:00
  End time:               26-Jun-2024 03:21:12
  Elapsed time:           12 mins 12 secs
  Files Expected:         1
  Files Restored:         1
  Bytes Restored:         6,021,200,746
  Rate:                   8225.7 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Bareos binary info:     Bareos community build (UNSUPPORTED): Get professional support from https://www.bareos.com
  Job triggered by:       User
  Termination:            Restore OK

Corresponding tape library warning (ignore timestamp, it's wrong):

Event: 4129 - Media removal prevented by drive
Ticket-No :	157
Time:	26.06.2024 02:38:41
State:	Singular
Severity:	WARNING
Component:	Drive
Component ID:	2 (20)
 Details
Details 1
CMD_NAME:	MOVE_MEDIUM
CMD_INITIATOR:	SCSI_CHANGER
SRC_ELEM_ADDR:	2 (20)
SRC_ELEM_TYPE:	Drive (4)
DST_ELEM_ADDR:	2.17 (337)
DST_ELEM_TYPE:	Slot (2)
MCHG_MEDI_PVT:	UB1067L8
ERRORCODE:	Move medium failed (MOVE_MEDIUM_FAILED)
SEVERITY:	WARNING
SYS_COMPONENT:	DRIVE
PHY_NUM:	2 (20)
Details 2
ERRORCODE:	Failed moving media from drive (MOV_MOVE_FROM_DRIVE_FAILED)
SEVERITY:	WARNING
SYS_COMPONENT:	DRIVE
PHY_NUM:	2 (20)
Details 3
CMD_NAME:	TDRV_UNLOAD_TAPE
CMD_INITIATOR:	MOVER
ERRORCODE:	Media removal prevented for tape drive (MC_MEDI_REM_PREVENT_DTE)
SEVERITY:	WARNING
TDRV_VEND_ID:	IBM
TDRV_PRD_ID:	ULTRIUM-HH8
TDRV_PRD_REV_LEV:	Q3A1
TDRV_SERNUM:	10WT050151
CARTRIDGE_LABEL:	UB1067L8
CARTRIDGE_TYPE:	Data tape
CARTRIDGE_GENERATION:	8
CARTRIDGE_MANUFACTURER:	IBM
CARTRIDGE_SERIAL_NUMBER:	I210621001
SLOT_NUMBER:	2.17 (337)
SYS_COMPONENT:	DRIVE
PHY_NUM:	2 (20)
Solution Suggestion:
Check backup application how to allow media removal from drive. If unsuccessful try Force Drive Media Eject option in operations menu.

Relevant traces output

No response

Anything else?

I suspect this might have to do with Prefer Mounted Volumes = no as the documentation points out that issues might arise with it. Though if I remember correctly I had to add this to ensure that these restore jobs can actually run at the same time while some other long running job (e.g. migrate/copy) is currently using another drive.

I don't have any issues with the tape library with any of the other jobs; it's just these restore jobs that run at the same time that need to read from the same volume.

SamuelBoerlin avatar Jun 26 '24 08:06 SamuelBoerlin

Hi @SamuelBoerlin, we are currently trying to reproduce and fix this issue.

  • Does this issue still occur for you ?
  • How often does it happen ?
  • Is it possible for you to create a debug trace for me on the sd ?

Im currently not able to reproduce this at all.

Sorry for taking so long to look at this!

sebsura avatar Feb 07 '25 07:02 sebsura

Hi

Yes, it still happens every couple of days (we're doing multiple automated restores each night). It's still running 23.0.4~pre56.5de4c8180.

I should be able to get a debug trace. What debug level should I use?

SamuelBoerlin avatar Feb 07 '25 12:02 SamuelBoerlin

Debug level 200 would be great!

sebsura avatar Feb 10 '25 06:02 sebsura

Here's the debug trace.

The file was massive because there were a couple of other VF/consolidate jobs running at the same time, so I've filtered out any lines from mac.cc which I think should be unrelated anyways the jobs in this case weren't using any tapes. I hope that's fine.

The involved jobs seemed to be 176511, 176512, 176513 and 176514 judging from their overlapping timeframes and warnings/errors.

*list joblog jobid=176511
 2025-02-11 05:23:25 bareos-dir JobId 176511: Start Restore Job Restore-Files.2025-02-11_05.23.25_11
 2025-02-11 05:23:25 bareos-dir JobId 176511: Connected Storage daemon at 127.0.0.1:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:23:25 bareos-dir JobId 176511:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:23:25 bareos-dir JobId 176511: Using Device "TapeDevice1" to read.
 2025-02-11 05:23:26 bareos-dir JobId 176511: Probing client protocol... (result will be saved until config reload)
 2025-02-11 05:23:26 bareos-dir JobId 176511: Using Client Initiated Connection (bsync-dsp-dev-03).
 2025-02-11 05:23:26 bareos-dir JobId 176511:    Handshake: Immediate TLS 
 2025-02-11 05:23:26 bareos-dir JobId 176511:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:23:28 bsync-dsp-dev-03 JobId 176511: Connected Storage daemon at 10.32.158.45:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:23:28 bsync-dsp-dev-03 JobId 176511:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:23:29 bareos-sd JobId 176511: Ready to read from volume "UB1056L8" on device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst).
 2025-02-11 05:23:29 bareos-sd JobId 176511: Forward spacing Volume "UB1056L8" to file:block 28:0.
 2025-02-11 05:24:52 bareos-sd JobId 176511: Releasing device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst).
 2025-02-11 05:24:52 bareos-dir JobId 176511: Bareos bareos-dir 23.0.4~pre56.5de4c8180 (21Jun24):
  Build OS:               Ubuntu 20.04.5 LTS
  JobId:                  176511
  Job:                    Restore-Files.2025-02-11_05.23.25_11
  Restore Client:         "bsync-dsp-dev-03" 22.0.3 (24Mar23) 3.18_alpha20230329,alpine
  Start time:             11-Feb-2025 05:23:25
  End time:               11-Feb-2025 05:24:52
  Elapsed time:           1 min 27 secs
  Files Expected:         1
  Files Restored:         1
  Bytes Restored:         10,331,113,661
  Rate:                   118748.4 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Bareos binary info:     Bareos community build (UNSUPPORTED): Get professional support from https://www.bareos.com
  Job triggered by:       User
  Termination:            Restore OK

*list joblog jobid=176512
Automatically selected Catalog: Catalog
Using Catalog "Catalog"
 2025-02-11 05:23:48 bareos-dir JobId 176512: Start Restore Job Restore-Files.2025-02-11_05.23.48_12
 2025-02-11 05:23:49 bareos-dir JobId 176512: Connected Storage daemon at 127.0.0.1:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:23:49 bareos-dir JobId 176512:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:23:49 bareos-dir JobId 176512: Using Device "TapeDevice2" to read.
 2025-02-11 05:23:49 bareos-dir JobId 176512: Probing client protocol... (result will be saved until config reload)
 2025-02-11 05:23:49 bareos-dir JobId 176512: Using Client Initiated Connection (bsync-dsp-dev-04).
 2025-02-11 05:23:49 bareos-dir JobId 176512:    Handshake: Immediate TLS 
 2025-02-11 05:23:49 bareos-dir JobId 176512:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:23:52 bsync-dsp-dev-04 JobId 176512: Connected Storage daemon at 10.32.158.45:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:23:52 bsync-dsp-dev-04 JobId 176512:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:23:52 bareos-sd JobId 176512: 3301 Issuing autochanger "loaded? drive 1" command.
 2025-02-11 05:23:53 bareos-sd JobId 176512: 3302 Autochanger "loaded? drive 1", result: nothing loaded.
 2025-02-11 05:24:52 bareos-sd JobId 176512: 3307 Issuing autochanger "unload slot 92, drive 0" command.
 2025-02-11 05:26:38 bareos-sd JobId 176512: 3997 Bad autochanger "unload slot 92, drive 0": ERR=Child exited with code 1.
 2025-02-11 05:26:38 bareos-sd JobId 176512: 3301 Issuing autochanger "loaded? drive 1" command.
 2025-02-11 05:26:39 bareos-sd JobId 176512: 3302 Autochanger "loaded? drive 1", result: nothing loaded.
 2025-02-11 05:26:39 bareos-sd JobId 176512: Warning: stored/acquire.cc:275 Read open device "TapeDevice2" (/dev/tape/by-id/scsi-35000e111c71ac0bf-nst) Volume "UB1056L8" failed: ERR=backends/generic_tape_device.cc:127 Unable to open device "TapeDevice2" (/dev/tape/by-id/scsi-35000e111c71ac0bf-nst): ERR=No medium found

 2025-02-11 05:26:39 bareos-sd JobId 176512: 3301 Issuing autochanger "loaded? drive 1" command.
 2025-02-11 05:26:41 bareos-sd JobId 176512: 3302 Autochanger "loaded? drive 1", result: nothing loaded.
 2025-02-11 05:26:41 bareos-sd JobId 176512: 3301 Issuing autochanger "loaded? drive 0" command.
 2025-02-11 05:26:42 bareos-sd JobId 176512: 3302 Autochanger "loaded? drive 0", result is Slot 92.
 2025-02-11 05:27:41 bareos-sd JobId 176512: 3307 Issuing autochanger "unload slot 92, drive 0" command.
 2025-02-11 05:29:06 bareos-sd JobId 176512: 3304 Issuing autochanger "load slot 92, drive 1" command.
 2025-02-11 05:29:41 bareos-sd JobId 176512: 3305 Autochanger "load slot 92, drive 1", status is OK.
 2025-02-11 05:29:43 bareos-sd JobId 176512: Ready to read from volume "UB1056L8" on device "TapeDevice2" (/dev/tape/by-id/scsi-35000e111c71ac0bf-nst).
 2025-02-11 05:29:43 bareos-sd JobId 176512: Forward spacing Volume "UB1056L8" to file:block 28:0.
 2025-02-11 05:31:39 bareos-sd JobId 176512: Releasing device "TapeDevice2" (/dev/tape/by-id/scsi-35000e111c71ac0bf-nst).
 2025-02-11 05:31:40 bareos-dir JobId 176512: Bareos bareos-dir 23.0.4~pre56.5de4c8180 (21Jun24):
  Build OS:               Ubuntu 20.04.5 LTS
  JobId:                  176512
  Job:                    Restore-Files.2025-02-11_05.23.48_12
  Restore Client:         "bsync-dsp-dev-04" 22.0.3 (24Mar23) 3.18_alpha20230329,alpine
  Start time:             11-Feb-2025 05:23:48
  End time:               11-Feb-2025 05:31:40
  Elapsed time:           7 mins 52 secs
  Files Expected:         1
  Files Restored:         1
  Bytes Restored:         10,331,113,661
  Rate:                   21888.0 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Bareos binary info:     Bareos community build (UNSUPPORTED): Get professional support from https://www.bareos.com
  Job triggered by:       User
  Termination:            Restore OK

*list joblog jobid=176513
 2025-02-11 05:24:08 bareos-dir JobId 176513: Start Restore Job Restore-Files.2025-02-11_05.24.08_13
 2025-02-11 05:24:08 bareos-dir JobId 176513: Connected Storage daemon at 127.0.0.1:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:24:08 bareos-dir JobId 176513:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:24:52 bareos-dir JobId 176513: Using Device "TapeDevice1" to read.
 2025-02-11 05:24:52 bareos-dir JobId 176513: Probing client protocol... (result will be saved until config reload)
 2025-02-11 05:24:52 bareos-dir JobId 176513: Using Client Initiated Connection (bsync-dsp-dev-06).
 2025-02-11 05:24:52 bareos-dir JobId 176513:    Handshake: Immediate TLS 
 2025-02-11 05:24:52 bareos-dir JobId 176513:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:24:55 bsync-dsp-dev-06 JobId 176513: Connected Storage daemon at 10.32.158.45:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:24:55 bsync-dsp-dev-06 JobId 176513:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:25:26 bareos-sd JobId 176513: Ready to read from volume "UB1056L8" on device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst).
 2025-02-11 05:25:26 bareos-sd JobId 176513: Forward spacing Volume "UB1056L8" to file:block 28:0.
 2025-02-11 05:25:55 bareos-sd JobId 176513: Releasing device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst).
 2025-02-11 05:25:55 bareos-dir JobId 176513: Warning: File count mismatch: expected=1 , restored=0
 2025-02-11 05:25:55 bareos-dir JobId 176513: Bareos bareos-dir 23.0.4~pre56.5de4c8180 (21Jun24):
  Build OS:               Ubuntu 20.04.5 LTS
  JobId:                  176513
  Job:                    Restore-Files.2025-02-11_05.24.08_13
  Restore Client:         "bsync-dsp-dev-06" 22.0.3 (24Mar23) 3.18_alpha20230329,alpine
  Start time:             11-Feb-2025 05:24:08
  End time:               11-Feb-2025 05:25:55
  Elapsed time:           1 min 47 secs
  Files Expected:         1
  Files Restored:         0
  Bytes Restored:         0
  Rate:                   0.0 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Bareos binary info:     Bareos community build (UNSUPPORTED): Get professional support from https://www.bareos.com
  Job triggered by:       User
  Termination:            Restore OK -- with warnings

*list joblog jobid=176514
 2025-02-11 05:26:31 bareos-dir JobId 176514: Start Restore Job Restore-Files.2025-02-11_05.26.31_14
 2025-02-11 05:26:31 bareos-dir JobId 176514: Connected Storage daemon at 127.0.0.1:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:26:32 bareos-dir JobId 176514:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:26:32 bareos-dir JobId 176514: Using Device "TapeDevice1" to read.
 2025-02-11 05:26:32 bareos-dir JobId 176514: Probing client protocol... (result will be saved until config reload)
 2025-02-11 05:26:32 bareos-dir JobId 176514: Using Client Initiated Connection (bsync-dsp-dev-05).
 2025-02-11 05:26:32 bareos-dir JobId 176514:    Handshake: Immediate TLS 
 2025-02-11 05:26:32 bareos-dir JobId 176514:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:26:34 bsync-dsp-dev-05 JobId 176514: Connected Storage daemon at 10.32.158.45:9103, encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:26:34 bsync-dsp-dev-05 JobId 176514:  Encryption: TLS_CHACHA20_POLY1305_SHA256 TLSv1.3
 2025-02-11 05:26:34 bareos-sd JobId 176514: Ready to read from volume "UB1056L8" on device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst).
 2025-02-11 05:26:34 bareos-sd JobId 176514: Forward spacing Volume "UB1056L8" to file:block 28:0.
 2025-02-11 05:27:41 bareos-sd JobId 176514: Releasing device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst).
 2025-02-11 05:27:42 bareos-dir JobId 176514: Bareos bareos-dir 23.0.4~pre56.5de4c8180 (21Jun24):
  Build OS:               Ubuntu 20.04.5 LTS
  JobId:                  176514
  Job:                    Restore-Files.2025-02-11_05.26.31_14
  Restore Client:         "bsync-dsp-dev-05" 22.0.3 (24Mar23) 3.18_alpha20230329,alpine
  Start time:             11-Feb-2025 05:26:31
  End time:               11-Feb-2025 05:27:42
  Elapsed time:           1 min 11 secs
  Files Expected:         1
  Files Restored:         1
  Bytes Restored:         10,331,113,661
  Rate:                   145508.6 KB/s
  FD Errors:              0
  FD termination status:  OK
  SD termination status:  OK
  Bareos binary info:     Bareos community build (UNSUPPORTED): Get professional support from https://www.bareos.com
  Job triggered by:       User
  Termination:            Restore OK

Here's an interesting excerpt where 176511 finishes reading and 176512 decides to unload the tape (for swapping to it to the other drive) while 176513 at the same time reserves it:

11-Feb-2025 05:24:44.543988 bareos-sd (200): stored/sd_stats.cc:309-0 New stats [1739247884]: JobId 175721, JobFiles 1077119, JobBytes 39716251079128, DevName FileDevice-A-WO-0001
11-Feb-2025 05:24:44.544004 bareos-sd (200): stored/sd_stats.cc:309-0 New stats [1739247884]: JobId 175904, JobFiles 691843, JobBytes 33579279067354, DevName FileDevice-C-WO-0001
11-Feb-2025 05:24:44.544036 bareos-sd (200): stored/sd_stats.cc:309-0 New stats [1739247884]: JobId 176133, JobFiles 135635, JobBytes 24572446394771, DevName FileDevice-C-WO-0002
11-Feb-2025 05:24:52.087261 bareos-sd (100): stored/acquire.cc:537-176511 releasing device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst)
11-Feb-2025 05:24:52.087300 bareos-sd (150): stored/acquire.cc:546-176511 dir_update_vol_info. label=1 Vol=UB1056L8
11-Feb-2025 05:24:52.087335 bareos-sd (50): stored/askdir.cc:299-176511 Update cat VolBytes=168045582336
11-Feb-2025 05:24:52.087445 bareos-sd (50): stored/askdir.cc:318-176511 >dird CatReq Job=Restore-Files.2025-02-11_05.23.25_11 UpdateMedia VolName=UB1056L8 VolJobs=86 VolFiles=88 VolBlocks=160303 VolBytes=168045582336 VolMounts=12 VolErrors=0 Vol
Writes=32137889 MaxVolBytes=0 EndTime=1739247892 VolStatus=Used Slot=92 relabel=0 InChanger=1 VolReadTime=120870156 VolWriteTime=37777955761 VolFirstWritten=0
11-Feb-2025 05:24:52.087478 bareos-sd (50): lib/tls_openssl_private.cc:325-176511 SSL_get_error() returned error value 2
11-Feb-2025 05:24:52.334223 bareos-sd (50): stored/askdir.cc:116-176511 <dird 1000 OK VolName=UB1056L8 VolJobs=86 VolFiles=88 VolBlocks=160303 VolBytes=168045582336 VolMounts=12 VolErrors=0 VolWrites=32137889 MaxVolBytes=0 VolCapacityBytes=0 Vol
Status=Used Slot=92 MaxVolJobs=0 MaxVolFiles=0 InChanger=1 VolReadTime=120870156 VolWriteTime=37777955761 EndFile=87 EndBlock=1984 LabelType=0 MediaId=4571 EncryptionKey= MinBlocksize=0 MaxBlocksize=0
11-Feb-2025 05:24:52.334269 bareos-sd (50): stored/askdir.cc:146-176511 DoGetVolumeInfo return true slot=92 Volume=UB1056L8, VolminBlocksize=0 VolMaxBlocksize=0
11-Feb-2025 05:24:52.334286 bareos-sd (50): stored/askdir.cc:150-176511 setting dcr->VolMinBlocksize(0) to vol.VolMinBlocksize(0)
11-Feb-2025 05:24:52.334316 bareos-sd (50): stored/askdir.cc:153-176511 setting dcr->VolMaxBlocksize(0) to vol.VolMaxBlocksize(0)
11-Feb-2025 05:24:52.335171 bareos-sd (150): stored/vol_mgr.cc:188-176511 remove_read_vol=UB1056L8 JobId=176511 found=1
11-Feb-2025 05:24:52.335195 bareos-sd (150): stored/vol_mgr.cc:695-176511 === clear in_use vol=UB1056L8
11-Feb-2025 05:24:52.335211 bareos-sd (150): stored/vol_mgr.cc:712-176511 === set not reserved vol=UB1056L8 num_writers=0 dev_reserved=0 dev="TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst)
11-Feb-2025 05:24:52.335225 bareos-sd (100): stored/acquire.cc:601-176511 0 writers, 0 reserve, dev="TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst)
11-Feb-2025 05:24:52.335249 bareos-sd (200): scsitapealert/scsitapealert-sd.cc:163-176511 scsitapealert-sd: Unknown event 21
11-Feb-2025 05:24:52.335263 bareos-sd (100): stored/acquire.cc:656-176511 JobId=176511 broadcast wait_device_release at 11-Feb-2025 05:24:52
11-Feb-2025 05:24:52.335361 bareos-sd (200): stored/acquire.cc:774-176511 Detach Jid=176511 dcr=7f3d80008230 size=1 to dev="TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst)
11-Feb-2025 05:24:52.335389 bareos-sd (100): stored/acquire.cc:676-176511 Device "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst) released by JobId=176511
11-Feb-2025 05:24:52.335403 bareos-sd (30): stored/read.cc:101-176511 Done reading.
11-Feb-2025 05:24:52.335432 bareos-sd (50): lib/tls_openssl_private.cc:325-176511 SSL_get_error() returned error value 2
11-Feb-2025 05:24:52.338600 bareos-sd (100): stored/autochanger.cc:621-176512 Issuing autochanger "unload slot 92, drive 0" command.
11-Feb-2025 05:24:52.338661 bareos-sd (100): stored/dev.cc:886-176512 close_dev "TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst)
11-Feb-2025 05:24:52.338601 bareos-sd (150): stored/reserve.cc:405-176513 Start find_suit_dev PrefMnt=0 exact=0 suitable=0 chgronly=1 any=0
11-Feb-2025 05:24:52.342473 bareos-sd (150): stored/reserve.cc:533-176513 Try match changer res=VirtualChanger-IDF, wanted Autochanger1
11-Feb-2025 05:24:52.342497 bareos-sd (150): stored/reserve.cc:533-176513 Try match changer res=VirtualChanger-DA, wanted Autochanger1
11-Feb-2025 05:24:52.342509 bareos-sd (150): stored/reserve.cc:533-176513 Try match changer res=VirtualChanger-C, wanted Autochanger1
11-Feb-2025 05:24:52.342521 bareos-sd (150): stored/reserve.cc:533-176513 Try match changer res=VirtualChanger-A, wanted Autochanger1
11-Feb-2025 05:24:52.342534 bareos-sd (150): stored/reserve.cc:533-176513 Try match changer res=Autochanger1, wanted Autochanger1
11-Feb-2025 05:24:52.342547 bareos-sd (150): stored/reserve.cc:539-176513 Try changer device TapeDevice1
11-Feb-2025 05:24:52.342577 bareos-sd (150): stored/reserve.cc:641-176513 chk MediaType device=LTO8_NEOXL80 request=LTO8_NEOXL80
11-Feb-2025 05:24:52.342590 bareos-sd (150): stored/reserve.cc:648-176513 chk AccessMode append=0 access_mode=3
11-Feb-2025 05:24:52.342623 bareos-sd (150): stored/reserve.cc:682-176513 try reserve TapeDevice1
11-Feb-2025 05:24:52.342642 bareos-sd (100): stored/block.cc:137-176513 created new block of blocksize 1048576 (dev->max_block_size)
11-Feb-2025 05:24:52.342660 bareos-sd (200): stored/acquire.cc:774-176513 Detach Jid=176513 dcr=7f3dcc0098e0 size=2 to dev="TapeDevice2" (/dev/tape/by-id/scsi-35000e111c71ac0bf-nst)
11-Feb-2025 05:24:52.342680 bareos-sd (200): stored/acquire.cc:755-176513 Attach Jid=176513 dcr=7f3dcc0098e0 size=0 dev="TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst)
11-Feb-2025 05:24:52.342701 bareos-sd (150): stored/reserve.cc:138-176513 Inc reserve=0 dev="TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst)
11-Feb-2025 05:24:52.342715 bareos-sd (150): stored/reserve.cc:770-176513 Read reserved=1 dev_name=Autochanger1 mediatype=LTO8_NEOXL80 pool=IDF-Incremental ok=1
11-Feb-2025 05:24:52.342836 bareos-sd (150): stored/reserve.cc:784-176513 >dird: 3000 OK use device device=TapeDevice1
11-Feb-2025 05:24:52.342855 bareos-sd (150): stored/reserve.cc:557-176513 Device TapeDevice1 reserved=1 for read.
11-Feb-2025 05:24:52.342871 bareos-sd (150): stored/reserve.cc:503-176513 available device found=Autochanger1
11-Feb-2025 05:24:52.342886 bareos-sd (150): stored/reserve.cc:515-176513 OK dev found. Vol=
11-Feb-2025 05:24:52.342920 bareos-sd (50): lib/tls_openssl_private.cc:325-176513 SSL_get_error() returned error value 2
11-Feb-2025 05:24:52.342589 bareos-sd (100): stored/dev.cc:979-176512 Enter unmount
11-Feb-2025 05:24:52.346465 bareos-sd (100): stored/dev.cc:874-176512 Clear volhdr vol=UB1056L8
11-Feb-2025 05:24:52.346486 bareos-sd (200): stored/autochanger.cc:628-176512 close dev="TapeDevice1" (/dev/tape/by-id/scsi-35000e111c71ac0b5-nst) reserve=1
11-Feb-2025 05:24:52.346499 bareos-sd (100): stored/autochanger.cc:630-176512 Run program=/usr/lib/bareos/scripts/mtx-changer /dev/tape/by-id/scsi-35000e111c71ac0b8 unload 92 /dev/tape/by-id/scsi-35000e111c71ac0b5-nst 0
11-Feb-2025 05:24:52.870565 bareos-sd (110): stored/fd_cmds.cc:206-176511 <filed: read close session 1177
11-Feb-2025 05:24:52.870598 bareos-sd (120): stored/fd_cmds.cc:409-176511 Read close session: read close session 1177
11-Feb-2025 05:24:52.870672 bareos-sd (160): stored/fd_cmds.cc:417-176511 >filed: 3000 OK close Status = 82
11-Feb-2025 05:24:52.873191 bareos-sd (200): autoxflate/autoxflate-sd.cc:216-176511 autoxflate-sd: freePlugin JobId=176511
11-Feb-2025 05:24:52.873213 bareos-sd (200): scsitapealert/scsitapealert-sd.cc:132-176511 scsitapealert-sd: freePlugin JobId=176511
11-Feb-2025 05:24:52.873231 bareos-sd (190): stored/dir_cmd.cc:300-176511 Command run requests quit

Full trace: bareos-sd.trace.txt

SamuelBoerlin avatar Feb 11 '25 10:02 SamuelBoerlin