When is a volume reservation actually made?

[Konstantin Kabassanov]

HI,

I saw the following situation. Two jobs start with a 2 minutes delay between them and use one of the tapes from a given pool (containing 2 tapes to simplify) with any of the changer 2 tape drives.

Usually it works pretty well, but yesterday there was another "foreign" tape in one of the drives (used for a previous restore operation) that had to be unloaded first. So first job started, SD requested an unload and a load. From servers logs it appears that they succeeded. Slot 1 did contain R0B007L7 before load.

The strange thing happened when second job started between the unload and the load process. The second tape R0B00FL7 was already loaded in the second drive.

I wonder what could have happened… Bareos claimed that R0B007L7 was already reserved, so either something wrong happened when restore tape had been loaded before, or second job reserved the wrong tape… Next, the first job tried do get the second tape from the pool, but as it was used by the other job, it failed correctly.

Once the second job terminated normally, the first one got its tape (the second one) and succeeded also. A third job got R0B007L7 (the tape that was rejected before due to reservation) and performed as usual...

18-juin 13:00 recover-dir JobId 6519: Start Backup JobId 6519, Job=Backup_recover-ol-ant.2020-06-18_13.00.00_20
18-juin 13:00 recover-dir JobId 6519: Connected Storage daemon at myserver.domain:9103, encryption: None
18-juin 13:00 recover-dir JobId 6519: Using Device "Drive-1" to write.
18-juin 13:00 recover-dir JobId 6519: Probing client protocol... (result will be saved until config reload)
18-juin 13:00 recover-dir JobId 6519: Connected Client: recover-ol-ant at 127.0.0.1:50010, encryption: None
18-juin 13:00 recover-dir JobId 6519:    Handshake: Cleartext
18-juin 13:00 recover-dir JobId 6519:  Encryption: None
18-juin 13:00 recover-dir JobId 6519: Sending Accurate information.
18-juin 13:00 recover-ol-ant JobId 6519: Connected Storage daemon at myserver.domain:9103, encryption: None
18-juin 13:00 recover-ol-ant JobId 6519: Extended attribute support is enabled
18-juin 13:00 recover-ol-ant JobId 6519: ACL support is enabled
18-juin 13:00 recover-sd JobId 6519: 3307 Issuing autochanger "unload slot 40, drive 0" command.
18-juin 13:01 recover-sd JobId 6519: 3304 Issuing autochanger "load slot 1, drive 0" command.

18-juin 13:02 recover-dir JobId 6520: Start Backup JobId 6520, Job=Backup_recover-ol-he.2020-06-18_13.02.00_21
18-juin 13:02 recover-dir JobId 6520: Connected Storage daemon at myserver.domain:9103, encryption: None
18-juin 13:02 recover-dir JobId 6520: Using Device "Drive-2" to write.
18-juin 13:02 recover-dir JobId 6520: Probing client protocol... (result will be saved until config reload)
18-juin 13:02 recover-dir JobId 6520: Connected Client: recover-ol-he at 127.0.0.1:50020, encryption: None
18-juin 13:02 recover-dir JobId 6520:    Handshake: Cleartext
18-juin 13:02 recover-dir JobId 6520:  Encryption: None

18-juin 13:02 recover-sd JobId 6519: 3305 Autochanger "load slot 1, drive 0", status is OK.
18-juin 13:02 recover-sd JobId 6519: Warning: stored/vol_mgr.cc:544 Need volume from other drive, but swap not possible. Status: read=0 num_writers=0 num_reserve=1 swap=0 vol=R0B007L7 from dev="Drive-2" (/dev/nst1) to "Drive-1" (/dev/nst0)
18-juin 13:02 recover-sd JobId 6519: Warning: stored/vol_mgr.cc:544 Need volume from other drive, but swap not possible. Status: read=0 num_writers=0 num_reserve=1 swap=0 vol=R0B007L7 from dev="Drive-2" (/dev/nst1) to "Drive-1" (/dev/nst0)
18-juin 13:02 recover-sd JobId 6519: Warning: stored/mount.cc:539 Could not reserve volume R0B007L7 on "Drive-1" (/dev/nst0)
18-juin 13:02 recover-sd JobId 6519: 3307 Issuing autochanger "unload slot 1, drive 0" command.

18-juin 13:02 recover-dir JobId 6520: Sending Accurate information.
18-juin 13:02 recover-ol-he JobId 6520: Connected Storage daemon at myserver.domain:9103, encryption: None
18-juin 13:05 recover-ol-he JobId 6520: Extended attribute support is enabled
18-juin 13:05 recover-ol-he JobId 6520: ACL support is enabled

18-juin 13:06 recover-sd JobId 6519: Warning: Volume "R0B00FL7" wanted on "Drive-1" (/dev/nst0) is in use by device "Drive-2" (/dev/nst1)
18-juin 13:06 recover-sd JobId 6519: Warning: stored/mount.cc:275 Open device "Drive-1" (/dev/nst0) Volume "R0B00FL7" failed: ERR=backends/generic_tape_device.cc:141 Unable to open device "Drive-1" (/dev/nst0): ERR=Aucun médium trouvé
...

Any ideas ?

Thanks.