Re: [Vchanger-users] Again wrong media and volume on error...

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

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)