Re: [Vchanger-users] Again wrong media and volume on error...
Brought to you by:
jaybus2
|
From: Marco G. <ga...@li...> - 2023-05-11 11:10:26
|
Mandi! Josh Fisher via Vchanger-users In chel di` si favelave... Sorry, i was busy in other things. > The 'update slots' should be run immediately after the disk is ejected, > before any jobs run again. In the bacula catalog, the volumes have > slot=N so that bacula knows which slot has which volume. When bacula > performs the 'update slots' it invokes vchanger to get the current list > of volumes in each slot. That causes vchanger to return an empty volume > label for each slot (because the disk is not mounted and the files are > not found). When vchanger returns empty strings for each slot's volume > label, bacula sets the volume's slot value to zero. After that, bacula > will not select that volume any more for future jobs. > > The problem is, if a job runs before the 'update slots', bacula will > still think those volumes are in slots and available. A script at friday 7:00 unload the RDX cartdrige; vchanger report: May 05 07:00:02: [29520]: restored state of magazine 2 May 05 07:00:02: [29520]: filesystem 9cf163ae-a762-4af7-9a11-e4f325ec2c7f has udev assigned device /dev/sdc1 May 05 07:00:02: [29520]: filesystem 9cf163ae-a762-4af7-9a11-e4f325ec2c7f (device /dev/sdc1) mounted at /mnt/vchanger/9cf163ae-a762-4af7-9a11-e4f325ec2c7f May 05 07:00:02: [29520]: magazine 0 is not mounted May 05 07:00:02: [29520]: magazine 1 is not mounted May 05 07:00:02: [29520]: magazine 2 has 10 volumes on /mnt/vchanger/9cf163ae-a762-4af7-9a11-e4f325ec2c7f May 05 07:00:02: [29520]: 10 volumes on magazine 2 assigned slots 1-10 May 05 07:00:02: [29520]: saved state of magazine 2 May 05 07:00:02: [29520]: saved dynamic configuration (max used slot: 10) May 05 07:00:02: [29520]: drive 0 previously unloaded May 05 07:00:02: [29520]: found symlink for drive 1 -> /mnt/vchanger/9cf163ae-a762-4af7-9a11-e4f325ec2c7f/SDPVE2RDX_0002_0005 May 05 07:00:02: [29520]: drive 1 previously loaded from slot 6 (SDPVE2RDX_0002_0005) May 05 07:00:02: [29520]: found symlink for drive 2 -> /mnt/vchanger/9cf163ae-a762-4af7-9a11-e4f325ec2c7f/SDPVE2RDX_0002_0007 May 05 07:00:02: [29520]: drive 2 previously loaded from slot 8 (SDPVE2RDX_0002_0007) May 05 07:00:02: [29520]: ==== preforming LOADED command May 05 07:00:02: [29520]: SUCCESS reporting drive 0 loaded from slot 0 May 05 07:00:06: [29650]: restored state of magazine 2 May 05 07:00:06: [29650]: filesystem 9cf163ae-a762-4af7-9a11-e4f325ec2c7f has udev assigned device /dev/sdc1 May 05 07:00:06: [29650]: device /dev/sdc1 not found in system mounts, searching all udev device aliases May 05 07:00:06: [29650]: filesystem 9cf163ae-a762-4af7-9a11-e4f325ec2c7f (device /dev/sdc1) not mounted May 05 07:00:06: [29650]: magazine 0 is not mounted May 05 07:00:06: [29650]: magazine 1 is not mounted May 05 07:00:06: [29650]: magazine 2 is not mounted May 05 07:00:06: [29650]: update slots needed. magazine 2 no longer mounted; previous: 10 volumes in slots 1-10 May 05 07:00:06: [29650]: saved dynamic configuration (max used slot: 10) May 05 07:00:06: [29650]: drive 0 previously unloaded May 05 07:00:06: [29650]: volume SDPVE2RDX_0002_0005 no longer available, unloading drive 1 May 05 07:00:06: [29650]: deleted symlink for drive 1 May 05 07:00:06: [29650]: volume SDPVE2RDX_0002_0007 no longer available, unloading drive 2 May 05 07:00:06: [29650]: deleted symlink for drive 2 May 05 07:00:06: [29650]: ==== preforming REFRESH command May 05 07:00:06: [29650]: running '/usr/sbin/bconsole -n -u 30' May 05 07:00:06: [29650]: popen: child stdin uses pipe (4 -> 5) May 05 07:00:06: [29650]: popen: child stdout uses pipe (6 -> 7) May 05 07:00:06: [29650]: popen: forking now May 05 07:00:06: [29650]: popen: parent closing pipe ends 4,7,-1 used by child May 05 07:00:06: [29650]: popen: parent writes child's stdin to 5 May 05 07:00:06: [29650]: popen: parent reads child's stdout from 6 May 05 07:00:06: [29650]: popen: parent returning pid=29651 of child May 05 07:00:06: [29650]: sending bconsole command 'update slots storage="SDPVE2RDX" drive="0"' May 05 07:00:06: [29651]: popen: child closing pipe ends 5,6,-1 used by parent May 05 07:00:06: [29651]: popen: child will read stdin from 4 May 05 07:00:06: [29651]: popen: child will write stdout to 7 May 05 07:00:06: [29651]: popen: child executing '/usr/sbin/bconsole' May 05 07:00:07: [29654]: filesystem 9cf163ae-a762-4af7-9a11-e4f325ec2c7f has udev assigned device /dev/sdc1 May 05 07:00:07: [29654]: device /dev/sdc1 not found in system mounts, searching all udev device aliases May 05 07:00:07: [29654]: filesystem 9cf163ae-a762-4af7-9a11-e4f325ec2c7f (device /dev/sdc1) not mounted May 05 07:00:07: [29654]: magazine 0 is not mounted May 05 07:00:07: [29654]: magazine 1 is not mounted May 05 07:00:07: [29654]: magazine 2 is not mounted May 05 07:00:07: [29654]: saved dynamic configuration (max used slot: 10) May 05 07:00:07: [29654]: drive 0 previously unloaded May 05 07:00:07: [29654]: ==== preforming SLOTS command May 05 07:00:07: [29654]: SUCCESS reporting 10 slots May 05 07:00:07: [29656]: filesystem 9cf163ae-a762-4af7-9a11-e4f325ec2c7f has udev assigned device /dev/sdc1 May 05 07:00:07: [29656]: device /dev/sdc1 not found in system mounts, searching all udev device aliases May 05 07:00:07: [29656]: filesystem 9cf163ae-a762-4af7-9a11-e4f325ec2c7f (device /dev/sdc1) not mounted May 05 07:00:07: [29656]: magazine 0 is not mounted May 05 07:00:07: [29656]: magazine 1 is not mounted May 05 07:00:07: [29656]: magazine 2 is not mounted May 05 07:00:07: [29656]: saved dynamic configuration (max used slot: 10) May 05 07:00:07: [29656]: drive 0 previously unloaded May 05 07:00:07: [29656]: ==== preforming LOADED command May 05 07:00:07: [29656]: SUCCESS reporting drive 0 loaded from slot 0 May 05 07:00:07: [29657]: filesystem 9cf163ae-a762-4af7-9a11-e4f325ec2c7f has udev assigned device /dev/sdc1 May 05 07:00:07: [29657]: device /dev/sdc1 not found in system mounts, searching all udev device aliases May 05 07:00:07: [29657]: filesystem 9cf163ae-a762-4af7-9a11-e4f325ec2c7f (device /dev/sdc1) not mounted May 05 07:00:07: [29657]: magazine 0 is not mounted May 05 07:00:07: [29657]: magazine 1 is not mounted May 05 07:00:07: [29657]: magazine 2 is not mounted May 05 07:00:07: [29657]: saved dynamic configuration (max used slot: 10) May 05 07:00:07: [29657]: drive 0 previously unloaded May 05 07:00:07: [29657]: ==== preforming LIST command May 05 07:00:07: [29657]: SUCCESS sent list to stdout May 05 07:00:07: [29650]: bconsole: bconsole terminated normally May 05 07:00:07: [29650]: 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="SDPVE2RDX" drive="0" Automatically selected Catalog: BaculaLNF Using Catalog "BaculaLNF" Connecting to Storage daemon SDPVE2RDX at sdpve2.sd.lnf.it:9103 ... 3306 Issuing autochanger "slots" command. Device "RDXAutochanger" has 10 slots. Connecting to Storage daemon SDPVE2RDX at sdpve2.sd.lnf.it:9103 ... 3306 Issuing autochanger "list" command. No Volumes found to label, or no barcodes. You have messages. May 05 07:00:07: [29650]: bconsole update slots command success May 05 07:00:13: [29773]: magazine 0 is not mounted May 05 07:00:13: [29773]: magazine 1 is not mounted May 05 07:00:13: [29773]: magazine 2 is not mounted May 05 07:00:13: [29773]: saved dynamic configuration (max used slot: 10) May 05 07:00:13: [29773]: drive 0 previously unloaded May 05 07:00:13: [29773]: ==== preforming REFRESH command So seems to me that 'update slots' get correctly sent... > Make sure that the 'update slots' is actually being performed by udev > when the disk is ejected. It might be that the udev rules from the > vchanger source code do not work as expected for RDX drives. For USB > drives, the device node is removed when the drive is detached. But with > RDX, disk is ejected and device node remains. So udev may not be > triggering the call to the vchanger script that is invoking I suspect > that the udev events are different for RDX and so the udev rules are not > invoking vchanger when the disk is ejected. > > In the vchanger log, it should log "bconsole update slots command > success" if udev is properly invoking vchanger. Otherwise, you might see > "WARNING! 'update slots' needed in bconsole" or "bconsole: exited with > rc=N" if the vchanger instance invoked by udev had an error calling > bconsole. See the log. All seems gone well. Also, after some minutes, a user load the RDX: May 05 07:10:36: [3616]: filesystem 5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 has udev assigned device /dev/sdc1 May 05 07:10:36: [3616]: filesystem 5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 (device /dev/sdc1) mounted at /mnt/vchanger/5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 May 05 07:10:36: [3616]: magazine 0 has 10 volumes on /mnt/vchanger/5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 May 05 07:10:36: [3616]: update slots needed. magazine 0 has 10 volumes, previously had 0 May 05 07:10:36: [3616]: magazine 1 is not mounted May 05 07:10:36: [3616]: magazine 2 is not mounted May 05 07:10:36: [3616]: 10 volumes on magazine 0 assigned slots 1-10 May 05 07:10:36: [3616]: saved state of magazine 0 May 05 07:10:36: [3616]: saved dynamic configuration (max used slot: 10) May 05 07:10:36: [3616]: drive 0 previously unloaded May 05 07:10:36: [3616]: ==== preforming REFRESH command May 05 07:10:36: [3616]: running '/usr/sbin/bconsole -n -u 30' May 05 07:10:36: [3616]: popen: child stdin uses pipe (4 -> 5) May 05 07:10:36: [3616]: popen: child stdout uses pipe (6 -> 7) May 05 07:10:36: [3616]: popen: forking now May 05 07:10:36: [3616]: popen: parent closing pipe ends 4,7,-1 used by child May 05 07:10:36: [3616]: popen: parent writes child's stdin to 5 May 05 07:10:36: [3616]: popen: parent reads child's stdout from 6 May 05 07:10:36: [3616]: popen: parent returning pid=3617 of child May 05 07:10:36: [3616]: sending bconsole command 'update slots storage="SDPVE2RDX" drive="0"' May 05 07:10:36: [3617]: popen: child closing pipe ends 5,6,-1 used by parent May 05 07:10:36: [3617]: popen: child will read stdin from 4 May 05 07:10:36: [3617]: popen: child will write stdout to 7 May 05 07:10:36: [3617]: popen: child executing '/usr/sbin/bconsole' May 05 07:10:37: [3620]: restored state of magazine 0 May 05 07:10:37: [3620]: filesystem 5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 has udev assigned device /dev/sdc1 May 05 07:10:37: [3620]: filesystem 5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 (device /dev/sdc1) mounted at /mnt/vchanger/5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 May 05 07:10:37: [3620]: magazine 0 has 10 volumes on /mnt/vchanger/5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 May 05 07:10:37: [3620]: 10 volumes on magazine 0 assigned slots 1-10 May 05 07:10:37: [3620]: magazine 1 is not mounted May 05 07:10:37: [3620]: magazine 2 is not mounted May 05 07:10:37: [3620]: saved state of magazine 0 May 05 07:10:37: [3620]: saved dynamic configuration (max used slot: 10) May 05 07:10:37: [3620]: drive 0 previously unloaded May 05 07:10:37: [3620]: ==== preforming SLOTS command May 05 07:10:37: [3620]: SUCCESS reporting 10 slots May 05 07:10:37: [3659]: restored state of magazine 0 May 05 07:10:37: [3659]: filesystem 5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 has udev assigned device /dev/sdc1 May 05 07:10:37: [3659]: filesystem 5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 (device /dev/sdc1) mounted at /mnt/vchanger/5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 May 05 07:10:37: [3659]: magazine 0 has 10 volumes on /mnt/vchanger/5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 May 05 07:10:37: [3659]: 10 volumes on magazine 0 assigned slots 1-10 May 05 07:10:37: [3659]: magazine 1 is not mounted May 05 07:10:37: [3659]: magazine 2 is not mounted May 05 07:10:37: [3659]: saved state of magazine 0 May 05 07:10:37: [3659]: saved dynamic configuration (max used slot: 10) May 05 07:10:37: [3659]: drive 0 previously unloaded May 05 07:10:37: [3659]: ==== preforming LOADED command May 05 07:10:37: [3659]: SUCCESS reporting drive 0 loaded from slot 0 May 05 07:10:37: [3660]: restored state of magazine 0 May 05 07:10:37: [3660]: filesystem 5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 has udev assigned device /dev/sdc1 May 05 07:10:37: [3660]: filesystem 5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 (device /dev/sdc1) mounted at /mnt/vchanger/5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 May 05 07:10:38: [3660]: magazine 0 has 10 volumes on /mnt/vchanger/5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 May 05 07:10:38: [3660]: 10 volumes on magazine 0 assigned slots 1-10 May 05 07:10:38: [3660]: magazine 1 is not mounted May 05 07:10:38: [3660]: magazine 2 is not mounted May 05 07:10:38: [3660]: saved state of magazine 0 May 05 07:10:38: [3660]: saved dynamic configuration (max used slot: 10) May 05 07:10:38: [3660]: drive 0 previously unloaded May 05 07:10:38: [3660]: ==== preforming LIST command May 05 07:10:38: [3660]: SUCCESS sent list to stdout May 05 07:10:38: [3616]: bconsole: bconsole terminated normally May 05 07:10:38: [3616]: 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="SDPVE2RDX" drive="0" Automatically selected Catalog: BaculaLNF Using Catalog "BaculaLNF" Connecting to Storage daemon SDPVE2RDX at sdpve2.sd.lnf.it:9103 ... 3306 Issuing autochanger "slots" command. Device "RDXAutochanger" has 10 slots. Connecting to Storage daemon SDPVE2RDX at sdpve2.sd.lnf.it:9103 ... 3306 Issuing autochanger "list" command. Catalog record for Volume "SDPVE2RDX_0000_0000" updated to reference slot 1. Catalog record for Volume "SDPVE2RDX_0000_0001" updated to reference slot 2. Catalog record for Volume "SDPVE2RDX_0000_0002" updated to reference slot 3. Catalog record for Volume "SDPVE2RDX_0000_0003" updated to reference slot 4. Catalog record for Volume "SDPVE2RDX_0000_0004" updated to reference slot 5. Catalog record for Volume "SDPVE2RDX_0000_0005" updated to reference slot 6. Catalog record for Volume "SDPVE2RDX_0000_0006" updated to reference slot 7. Catalog record for Volume "SDPVE2RDX_0000_0007" updated to reference slot 8. Catalog record for Volume "SDPVE2RDX_0000_0008" updated to reference slot 9. Catalog record for Volume "SDPVE2RDX_0000_0009" updated to reference slot 10. You have messages. May 05 07:10:38: [3616]: bconsole update slots command success Also this seems correct. -- ...ma quel suo volo certo vuol dire che bisognava volare (F. Guccini) |