I have found the problem. See below.
On 4/2/24 05:33, Marco Gaiarin wrote:
Mandi! Josh Fisher via Bacula-users
In chel di` si favelave...
This is the Easter weekend in italy, so backup will fail in most of my
sites; i'm enabling debug for sites, i'll come back here on monday...
When the magazine is ejected and no magazine is in drive, the output of
'list media' command from bconsole should be saved to see if it shows all
volumes to be not in changer, if that is possible for you.
...
So, trying to determine what happened... cartdrige 1 (0) ejected on friday
morning:
Mar 29 07:00:02: [30941]: restored state of magazine 0
Mar 29 07:00:02: [30941]: filesystem ea70e0c4-8076-4448-9b7e-4bb268a56c18 has
udev assigned device /dev/sdc1
Mar 29 07:00:02: [30941]: filesystem ea70e0c4-8076-4448-9b7e-4bb268a56c18
(device /dev/sdc1) mounted at /mnt/vchanger/ea70e0c4-8076-4448-9b7e-4bb268a56c18
Mar 29 07:00:02: [30941]: magazine 0 has 10 volumes on
/mnt/vchanger/ea70e0c4-8076-4448-9b7e-4bb268a56c18
Mar 29 07:00:02: [30941]: 10 volumes on magazine 0 assigned slots 1-10
Mar 29 07:00:02: [30941]: magazine 1 is not mounted
Mar 29 07:00:02: [30941]: magazine 2 is not mounted
Mar 29 07:00:02: [30941]: saved state of magazine 0
Mar 29 07:00:02: [30941]: saved dynamic configuration (max used slot: 10)
Mar 29 07:00:02: [30941]: found symlink for drive 0 ->
/mnt/vchanger/ea70e0c4-8076-4448-9b7e-4bb268a56c18/VIPVE2RDX_0000_0001
Mar 29 07:00:02: [30941]: drive 0 previously loaded from slot 2
(VIPVE2RDX_0000_0001)
Mar 29 07:00:02: [30941]: found symlink for drive 1 ->
/mnt/vchanger/ea70e0c4-8076-4448-9b7e-4bb268a56c18/VIPVE2RDX_0000_0006
Mar 29 07:00:02: [30941]: drive 1 previously loaded from slot 7
(VIPVE2RDX_0000_0006)
Mar 29 07:00:02: [30941]: found symlink for drive 2 ->
/mnt/vchanger/ea70e0c4-8076-4448-9b7e-4bb268a56c18/VIPVE2RDX_0000_0007
Mar 29 07:00:02: [30941]: drive 2 previously loaded from slot 8
(VIPVE2RDX_0000_0007)
Mar 29 07:00:02: [30941]: ==== preforming UNLOAD command
Mar 29 07:00:02: [30941]: deleted symlink for drive 0
Mar 29 07:00:02: [30941]: deleted state file for drive 0
Mar 29 07:00:02: [30941]: unloaded drive 0
Mar 29 07:00:02: [30941]: SUCCESS unloading slot 2 from drive 0
Mar 29 07:00:05: [31075]: restored state of magazine 0
Mar 29 07:00:05: [31075]: filesystem ea70e0c4-8076-4448-9b7e-4bb268a56c18 has
udev assigned device /dev/sdc1
Mar 29 07:00:05: [31075]: device /dev/sdc1 not found in system mounts,
searching all udev device aliases
Mar 29 07:00:05: [31075]: filesystem ea70e0c4-8076-4448-9b7e-4bb268a56c18
(device /dev/sdc1) not mounted
Mar 29 07:00:05: [31075]: magazine 0 is not mounted
Mar 29 07:00:05: [31075]: update slots needed. magazine 0 no longer mounted;
previous: 10 volumes in slots 1-10
Mar 29 07:00:05: [31075]: magazine 1 is not mounted
Mar 29 07:00:05: [31075]: magazine 2 is not mounted
Mar 29 07:00:05: [31075]: saved dynamic configuration (max used slot: 10)
Mar 29 07:00:05: [31075]: drive 0 previously unloaded
Mar 29 07:00:05: [31075]: volume VIPVE2RDX_0000_0006 no longer available,
unloading drive 1
Mar 29 07:00:05: [31075]: deleted symlink for drive 1
Mar 29 07:00:05: [31075]: volume VIPVE2RDX_0000_0007 no longer available,
unloading drive 2
Mar 29 07:00:05: [31075]: deleted symlink for drive 2
Mar 29 07:00:05: [31075]: ==== preforming REFRESH command
Mar 29 07:00:05: [31075]: running '/usr/sbin/bconsole -n -u 30'
Mar 29 07:00:05: [31075]: popen: child stdin uses pipe (4 -> 5)
Mar 29 07:00:05: [31075]: popen: child stdout uses pipe (6 -> 7)
Mar 29 07:00:05: [31075]: popen: forking now
Mar 29 07:00:05: [31075]: popen: parent closing pipe ends 4,7,-1 used by child
Mar 29 07:00:05: [31075]: popen: parent writes child's stdin to 5
Mar 29 07:00:05: [31075]: popen: parent reads child's stdout from 6
Mar 29 07:00:05: [31075]: popen: parent returning pid=31076 of child
Mar 29 07:00:05: [31075]: sending bconsole command 'update slots storage="VIPVE2RDX"
drive="0"'
Mar 29 07:00:05: [31076]: popen: child closing pipe ends 5,6,-1 used by parent
Mar 29 07:00:05: [31076]: popen: child will read stdin from 4
Mar 29 07:00:05: [31076]: popen: child will write stdout to 7
Mar 29 07:00:05: [31076]: popen: child executing '/usr/sbin/bconsole'
Mar 29 07:00:06: [31079]: filesystem ea70e0c4-8076-4448-9b7e-4bb268a56c18 has
udev assigned device /dev/sdc1
Mar 29 07:00:06: [31079]: device /dev/sdc1 not found in system mounts,
searching all udev device aliases
Mar 29 07:00:06: [31079]: filesystem ea70e0c4-8076-4448-9b7e-4bb268a56c18
(device /dev/sdc1) not mounted
Mar 29 07:00:06: [31079]: magazine 0 is not mounted
Mar 29 07:00:06: [31079]: magazine 1 is not mounted
Mar 29 07:00:06: [31079]: magazine 2 is not mounted
Mar 29 07:00:06: [31079]: saved dynamic configuration (max used slot: 10)
Mar 29 07:00:06: [31079]: drive 0 previously unloaded
Mar 29 07:00:06: [31079]: ==== preforming SLOTS command
Mar 29 07:00:06: [31079]: SUCCESS reporting 10 slots
Mar 29 07:00:06: [31081]: filesystem ea70e0c4-8076-4448-9b7e-4bb268a56c18 has
udev assigned device /dev/sdc1
Mar 29 07:00:06: [31081]: device /dev/sdc1 not found in system mounts,
searching all udev device aliases
Mar 29 07:00:06: [31081]: filesystem ea70e0c4-8076-4448-9b7e-4bb268a56c18
(device /dev/sdc1) not mounted
Mar 29 07:00:06: [31081]: magazine 0 is not mounted
Mar 29 07:00:06: [31081]: magazine 1 is not mounted
Mar 29 07:00:06: [31081]: magazine 2 is not mounted
Mar 29 07:00:06: [31081]: saved dynamic configuration (max used slot: 10)
Mar 29 07:00:06: [31081]: drive 0 previously unloaded
Mar 29 07:00:06: [31081]: ==== preforming LOADED command
Mar 29 07:00:06: [31081]: SUCCESS reporting drive 0 loaded from slot 0
Mar 29 07:00:06: [31096]: filesystem ea70e0c4-8076-4448-9b7e-4bb268a56c18 has
udev assigned device /dev/sdc1
Mar 29 07:00:06: [31096]: device /dev/sdc1 not found in system mounts,
searching all udev device aliases
Mar 29 07:00:06: [31096]: filesystem ea70e0c4-8076-4448-9b7e-4bb268a56c18
(device /dev/sdc1) not mounted
Mar 29 07:00:06: [31096]: magazine 0 is not mounted
Mar 29 07:00:06: [31096]: magazine 1 is not mounted
Mar 29 07:00:06: [31096]: magazine 2 is not mounted
Mar 29 07:00:06: [31096]: saved dynamic configuration (max used slot: 10)
Mar 29 07:00:06: [31096]: drive 0 previously unloaded
Mar 29 07:00:06: [31096]: ==== preforming LIST command
Mar 29 07:00:06: [31096]: SUCCESS sent list to stdout
Mar 29 07:00:06: [31075]: bconsole: bconsole terminated normally
Mar 29 07:00:06: [31075]: bconsole output:
Connecting to Director bacula.lnf.it:9101
1000 OK: 103 lnfbacula-dir Version: 9.4.2 (04 February 2019)
Enter a period to cancel a command.
update slots storage="VIPVE2RDX" drive="0"
Automatically selected Catalog: BaculaLNF
Using Catalog "BaculaLNF"
Connecting to Storage daemon VIPVE2RDX at vipve2.vi.lnf.it:9103 ...
3306 Issuing autochanger "slots" command.
Device "RDXAutochanger" has 10 slots.
Connecting to Storage daemon VIPVE2RDX at vipve2.vi.lnf.it:9103 ...
3306 Issuing autochanger "list" command.
No Volumes found to label, or no barcodes.
You have messages.
Mar 29 07:00:06: [31075]: bconsole update slots command success
Mar 29 07:00:14: [31214]: magazine 0 is not mounted
Mar 29 07:00:14: [31214]: magazine 1 is not mounted
Mar 29 07:00:14: [31214]: magazine 2 is not mounted
Mar 29 07:00:14: [31214]: saved dynamic configuration (max used slot: 10)
Mar 29 07:00:14: [31214]: drive 0 previously unloaded
Mar 29 07:00:14: [31214]: ==== preforming REFRESH command
OK. These things we know:
1. Udev invoked vchanger as pid 31075 when the cartridge was removed.
2. Vchanger invoked bconsole with 'update slots' command as pid 31076.
3. In processing the 'update slots', bconsole did the following:
a) Invoked vchanger as pid 31079 with SLOTS command.
- vchanger was successful and sent '10' to stdout 10
b) Invoked vchanger as pid 31081 with LOADED command for drive 0.
- vchanger was successful and sent '0' to stdout
c) invoked vchanger as pid 31096 with LIST command.
- vchanger was successful and sent list of empty slots to stdout,
something like:
1:
2:
...
4. vchanger pid 31875 exited successfully
So, everything appears to have worked correctly, however...we do not know at
this point for sure what bconsole did with vchanger's response to the LIST
command. We see in the output that vchanger pid 31875 received from bconsole
that bconsole reported 'No Volumes found to label, or no barcodes'. That is
correct. There indeed are no barcodes listed in the LIST command because there
are no cartridges mounted.
But did bconsole update the Bacula catalog database to change the volume records
of those volumes to change their slot field to zero? I have not encountered
this,
so experimented with my system to find out why. Here is what I discovered.
1. To discover what volumes are available in a vchanger device, Bacula sends
it a LIST command. The output of the LIST command is a list of slot numbers,
one on each line, where each slot number is followed by a ':' and then either
the barcode string of the volume in that slot or else the empty string if
there is no volume in that slot.
2. When at least one of the lines of output from the LIST command contains a
barcode, Bacula works as expected. If a media is removed from the system,
then Bacula will update its catalog database and change the volume record
for volumes that were previously in slots, but are now empty, to indicate
that they are in xlot zero (ie. not in-changer).
3. If the output of the LIST command contains a list of slots where not even
one slot contains a barcode, then Bacula will report "No Volumes found to
label, or no barcodes" and will not update the catalog at all.
I would argue that (3) above is a bug. The autochanger script (vchanger in
this case) is reporting its volumes correctly. When there is no media mounted,
there literally are no volumes found. Bacula should still update the volume
slots even when the LIST command sent to the autochanger script reports no
barcodes found at all.
I don't encounter this because I use a fixed disk partition for my incremental
pool volumes. When I remove all of my full and differential pool media, the
LIST command output still contains the barcodes of the volumes on the fixed
disk partition. I find that if I also umount the fixed partition, then I can
duplicate your results.
To truly fix it, there would need to be a change in how Bacula handles the
case where zero volumes are in-changer.
For your immediate need, the simple solution is to setup a small directory
on fixed disk with a single volume file and add it to your vchanger config
as a magazine. That will cause vchanger to always have at least one slot
with a barcode in its LIST command output, so it should never run into the
problem.
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
