Re: [Vchanger-users] Again wrong media and volume on error...
Brought to you by:
jaybus2
Menu
▾
▴
Re: [Vchanger-users] Again wrong media and volume on error...
|
From: Josh F. <jf...@ja...> - 2023-05-08 12:50:04
|
On 5/8/23 05:04, Marco Gaiarin wrote: > Situation: we have found that in a site there was a (phisical) labeling > error, that we have now corrected. > > Practically media 1 and 2 (or 0 and 1, if you prefere) was swapped. Clerly > after 'consuming' media 3 (or 2), now we have inserted the correct media 1 > (or 0), but the retention was wrong (the expired media is the 2 (or 1). > > See the volume report: > > *list media pool=VEN-SD-SDPVE2RDXPool > +---------+---------------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------+----------+---------------------+-----------+ > | mediaid | volumename | volstatus | enabled | volbytes | volfiles | volretention | recycle | slot | inchanger | mediatype | voltype | volparts | lastwritten | expiresin | > +---------+---------------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------+----------+---------------------+-----------+ > ... > > 1 | 2022-08-25 23:01:40 | 0 | > | 75 | SDPVE2RDX_0001_0000 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-16 02:06:08 | 0 | > | 76 | SDPVE2RDX_0001_0001 | Used | 1 | 348,836,026 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-19 23:02:28 | 134,134 | > | 77 | SDPVE2RDX_0001_0002 | Used | 1 | 257,396,874 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-20 23:02:40 | 220,546 | > | 78 | SDPVE2RDX_0001_0003 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | ... > > So it is right that Bacula does not use volumes in media 0 (they are not > expired), but try and try to use the (just expired) volume in media 1, > clearly putting them on error: > > 08-May 09:35 lnfbacula-dir JobId 6648: Recycled volume "SDPVE2RDX_0001_0007" > 08-May 09:36 sdpve2-sd JobId 6648: Warning: mount.c:215 Open of File device "RDXStorage0" (/var/spool/vchanger/SDPVE2RDX/0) Volume "SDPVE2RDX_0001_0007" failed: ERR=file_dev.c:190 Could not open(/var/spool/vchanger/SDPVE2RDX/0,OPEN_READ_WRITE,0640): ERR=No such file or directory > ... > > if i purge volume in error, at subsequent run bacula put them on error. > > > I've tried to do an: > update slots storage=SDPVE2RDX 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. > repurge all volumes in error, but nothing changed. Back in error. > > > vchanger log report no error: > > May 08 09:30:59: [32513]: restored state of magazine 0 > May 08 09:30:59: [32513]: filesystem 5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 has udev assigned device /dev/sdc1 > May 08 09:30:59: [32513]: filesystem 5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 (device /dev/sdc1) mounted at /mnt/vchanger/5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 > May 08 09:30:59: [32513]: magazine 0 has 10 volumes on /mnt/vchanger/5ba3d8a2-80e2-4322-9d83-839d2f6dc8b4 > May 08 09:30:59: [32513]: 10 volumes on magazine 0 assigned slots 1-10 > May 08 09:30:59: [32513]: magazine 1 is not mounted > May 08 09:30:59: [32513]: magazine 2 is not mounted > May 08 09:30:59: [32513]: saved state of magazine 0 > May 08 09:30:59: [32513]: saved dynamic configuration (max used slot: 10) > May 08 09:30:59: [32513]: drive 0 previously unloaded > May 08 09:30:59: [32513]: ==== preforming LOADED command > May 08 09:30:59: [32513]: SUCCESS reporting drive 0 loaded from slot 0 > > What happened?! Why bacula try to mount volume not in slots? 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. > > The only strange things is the SD status: > > *status storage=SDPVE2RDX > Connecting to Storage daemon SDPVE2RDX at sdpve2.sd.lnf.it:9103 > > sdpve2-sd Version: 9.4.2 (04 February 2019) x86_64-pc-linux-gnu debian 10.5 > Daemon started 09-Mar-23 13:05. Jobs: run=65, running=1. > Heap: heap=8,192 smbytes=799,871 max_bytes=1,156,238 bufs=211 max_bufs=265 > Sizes: boffset_t=8 size_t=8 int32_t=4 int64_t=8 mode=0,0 newbsr=0 > Res: ndevices=3 nautochgr=1 > > Running Jobs: > Writing: Full Backup job VEN-SD-SDPVE2-VMs JobId=6648 Volume="" > pool="VEN-SD-SDPVE2RDXPool" device="RDXStorage0" (/var/spool/vchanger/SDPVE2RDX/0) > spooling=0 despooling=0 despool_wait=0 > Files=0 Bytes=0 AveBytes/sec=0 LastBytes/sec=0 > FDReadSeqNo=6 in_msg=6 out_msg=400 fd=7 > Writing: Incremental Backup job VEN-SD-Sdinny JobId=6668 Volume="" > pool="VEN-SD-SDPVE2RDXPool" device="RDXStorage1" (/var/spool/vchanger/SDPVE2RDX/1) > spooling=0 despooling=0 despool_wait=0 > Files=0 Bytes=0 AveBytes/sec=0 LastBytes/sec=0 > FDReadSeqNo=6 in_msg=6 out_msg=147 fd=5 > ==== > > Jobs waiting to reserve a drive: > ==== > > Terminated Jobs: > JobId Level Files Bytes Status Finished Name > =================================================================== > 6330 Incr 8,449 273.7 M OK 27-Apr-23 23:03 VEN-SD-Sdinny > 6365 Full 627,377 181.8 G OK 28-Apr-23 22:08 VEN-SD-Sdinny > 6386 Incr 1,565 97.32 M OK 29-Apr-23 23:02 VEN-SD-Sdinny > 6408 Full 6 43.45 G OK 30-Apr-23 02:05 VEN-SD-SDPVE2-VMs > 6427 Incr 1,508 157.7 M OK 30-Apr-23 23:03 VEN-SD-Sdinny > 6461 Incr 1,122 234.7 M OK 01-May-23 23:02 VEN-SD-Sdinny > 6498 Incr 7,495 431.8 M OK 02-May-23 23:02 VEN-SD-Sdinny > 6533 Incr 9,558 255.0 M OK 03-May-23 23:02 VEN-SD-Sdinny > 6568 Incr 10,131 290.5 M OK 04-May-23 23:01 VEN-SD-Sdinny > 6603 Full 0 0 Cancel 07-May-23 20:01 VEN-SD-Sdinny > ==== > > Device status: > Autochanger "RDXAutochanger" with devices: > "RDXStorage0" (/var/spool/vchanger/SDPVE2RDX/0) > "RDXStorage1" (/var/spool/vchanger/SDPVE2RDX/1) > "RDXStorage2" (/var/spool/vchanger/SDPVE2RDX/2) > > Device File: "RDXStorage0" (/var/spool/vchanger/SDPVE2RDX/0) is not open. > Device is BLOCKED waiting to create a volume for: > Pool: VEN-SD-SDPVE2RDXPool > Media type: RDX > Drive 0 is not loaded. > == > > Device File: "RDXStorage1" (/var/spool/vchanger/SDPVE2RDX/1) is not open. > Device is BLOCKED waiting to create a volume for: > Pool: VEN-SD-SDPVE2RDXPool > Media type: RDX > Slot 6 was last loaded in drive 1. > == > > Device File: "RDXStorage2" (/var/spool/vchanger/SDPVE2RDX/2) is not open. > Slot 8 was last loaded in drive 2. > == > ==== > > Used Volume status: > Reserved volume: SDPVE2RDX_0001_0003 on File device "RDXStorage1" (/var/spool/vchanger/SDPVE2RDX/1) > Reader=0 writers=0 reserves=1 volinuse=0 worm=0 > Reserved volume: SDPVE2RDX_0001_0005 on File device "RDXStorage0" (/var/spool/vchanger/SDPVE2RDX/0) > Reader=0 writers=0 reserves=1 volinuse=0 worm=0 > ==== > > Attr spooling: 0 active jobs, 0 bytes; 63 total jobs, 178,915,351 max bytes. > ==== > > > Thanks. > |
