vchanger-users Mailing List for vchanger
Brought to you by:
jaybus2
You can subscribe to this list here.
| 2009 |
Jan
|
Feb
|
Mar
|
Apr
(2) |
May
(6) |
Jun
(1) |
Jul
|
Aug
(6) |
Sep
(1) |
Oct
(1) |
Nov
(3) |
Dec
(2) |
|---|---|---|---|---|---|---|---|---|---|---|---|---|
| 2010 |
Jan
(3) |
Feb
(5) |
Mar
(20) |
Apr
(1) |
May
(1) |
Jun
|
Jul
|
Aug
(1) |
Sep
(1) |
Oct
|
Nov
|
Dec
(1) |
| 2011 |
Jan
(2) |
Feb
(2) |
Mar
(24) |
Apr
(34) |
May
(14) |
Jun
|
Jul
(31) |
Aug
(12) |
Sep
(5) |
Oct
|
Nov
|
Dec
|
| 2013 |
Jan
|
Feb
|
Mar
|
Apr
|
May
|
Jun
(6) |
Jul
|
Aug
(2) |
Sep
|
Oct
|
Nov
|
Dec
|
| 2015 |
Jan
|
Feb
|
Mar
(1) |
Apr
(3) |
May
(2) |
Jun
|
Jul
|
Aug
(10) |
Sep
(8) |
Oct
|
Nov
(6) |
Dec
(4) |
| 2016 |
Jan
|
Feb
(5) |
Mar
(1) |
Apr
|
May
(1) |
Jun
(6) |
Jul
(8) |
Aug
|
Sep
(1) |
Oct
|
Nov
(5) |
Dec
|
| 2017 |
Jan
|
Feb
|
Mar
|
Apr
(2) |
May
(3) |
Jun
(1) |
Jul
(8) |
Aug
|
Sep
(5) |
Oct
(9) |
Nov
|
Dec
|
| 2018 |
Jan
|
Feb
|
Mar
|
Apr
|
May
|
Jun
|
Jul
|
Aug
|
Sep
|
Oct
|
Nov
|
Dec
(1) |
| 2020 |
Jan
|
Feb
|
Mar
|
Apr
|
May
(3) |
Jun
|
Jul
|
Aug
|
Sep
|
Oct
|
Nov
|
Dec
|
| 2022 |
Jan
|
Feb
|
Mar
|
Apr
|
May
|
Jun
(4) |
Jul
(8) |
Aug
(4) |
Sep
(21) |
Oct
(3) |
Nov
|
Dec
|
| 2023 |
Jan
(24) |
Feb
(10) |
Mar
(13) |
Apr
(6) |
May
(14) |
Jun
|
Jul
|
Aug
(4) |
Sep
|
Oct
(1) |
Nov
|
Dec
|
| 2025 |
Jan
|
Feb
(2) |
Mar
(1) |
Apr
|
May
|
Jun
|
Jul
|
Aug
|
Sep
|
Oct
|
Nov
|
Dec
|
|
From: Justin C. <jus...@gm...> - 2025-03-24 13:04:14
|
vchanger is still not working any more for me, is there anyone who can help me solve this? > On 23. Feb 2025, at 14:39, Justin Case <jus...@gm...> wrote: > > Hi there, > > I have a case of vchanger seemingly loading the wrong volume (see the attached director log) > the director requests: usbdisk_0002_0016 > the vchanger loads: usbdisk_0001_0016 (notice the loaded volume is from magazine/disk 1, but requested was a volume from magazine/disk 2) > > I have also checked the vchanger log and it is consistent with this observation. vchanger really does set the link to usbdisk_0001_0016 for drive 1 > > I have also checked ahandful of copy jobs preceding this job and there vchanger was loading the correct volumes. > > 1) Why might this happen? > 2) Could this be a misconfiguration on my end? What might be wrongly configured? > 3) Is there anything I can do about it? > > <copy_job_log.txt> > > |
|
From: Marco G. <ga...@li...> - 2025-02-25 18:10:12
|
Mandi! Justin Case In chel di` si favelave... > 1) Why might this happen? Because Bacula is 'greedy', and so (try to) backup on every media they found; vchanger use a 'metaphore' of a changer, where every USB media is a set of media (like a set of tapes) and every set of media have their device: so if yo have three usb media, you have three set of media and three devices. If for any reason the current usb device exaust the media, bacula (try to) mount volumes that are on other usb media. Clearly cannot, so put the media on error state. > 2) Could this be a misconfiguration on my end? What might be wrongly configured? Mostly no; if you have followed the documentation, all will work; but this sort of backup have some drawbacks, so if you lost or delay some usb media change strange things can happen. > 3) Is there anything I can do about it? I've setup some scripts that (try to) fix this errors, and can run against usb media. They are simple bash script full of italian sentences and comments. sorry... https://wiki.lilliput.linux.it/files/bacula/ -- |
|
From: Justin C. <jus...@gm...> - 2025-02-23 13:39:30
|
Hi there, I have a case of vchanger seemingly loading the wrong volume (see the attached director log) the director requests: usbdisk_0002_0016 the vchanger loads: usbdisk_0001_0016 (notice the loaded volume is from magazine/disk 1, but requested was a volume from magazine/disk 2) I have also checked the vchanger log and it is consistent with this observation. vchanger really does set the link to usbdisk_0001_0016 for drive 1 I have also checked ahandful of copy jobs preceding this job and there vchanger was loading the correct volumes. 1) Why might this happen? 2) Could this be a misconfiguration on my end? What might be wrongly configured? 3) Is there anything I can do about it? |
|
From: Justin C. <jus...@gm...> - 2023-10-24 14:09:50
|
Hi there, there seems to be a hidden limit of vchanger being able to register more then 600 volumes with bacula’s Scratch pool. My Scratch pool has MaximumVolumes set to 0 (and I also tried it with 1800), so that should not be the limit vchanger is running into. Any ideas which limit is capping the number of volumes that vchanger can register in the Scratch pool to 600? ATB JC |
|
From: Josh F. <jf...@ja...> - 2023-08-11 13:04:49
|
On 8/10/23 14:05, Steven A. Falco wrote:
> On 8/10/23 11:19 AM, Josh Fisher wrote:
>> ...
>
> I've checked the log, and I had one instance of:
>
> Aug 09 09:49:09: [12299]: WARNING! 'update slots' needed in bconsole
> Aug 09 09:49:09: [12299]: bconsole update slots command success
>
> But after doing the manual "update slots", I don't see any more
> warnings. I don't know why bconsole couldn't be run that one time,
> but I'll keep an eye on it. Maybe I issued it as an unprivileged user
> rather than as root.
Maybe. If it persists, then set leg_level = LOG_DEBUG, which will log
much more detail about the bconsole calls and their return codes. It
should help determine why the bconsole calls fail.
>
> As an aside, looking at bconsole.cpp I'm surprised that the "success"
> message would be printed along with the WARNING line. It might be
> clearer to have the "success" line in an else clause, like:
>
> if (update_slots) {
> tFormat(cmd, "update slots storage=\"%s\" drive=\"0\"",
> conf.storage_name.c_str());
> if(issue_bconsole_command(cmd.c_str())) {
> vlog.Error("WARNING! 'update slots' needed in bconsole");
> } else {
> vlog.Info("bconsole update slots command success");
> }
> }
>
> The same would be true of the label_barcodes a few lines later in the
> file.
It is supposed to be in an elf clause. That is a bug. Thanks. I'll fix it.
>
> I've also attached a trivial patch, because when reading the log I
> noticed that there is a typo which I fixed via
> s/preforming/performing/ in vchanger.cpp (around lines 638-672).
>
> Thanks for the rapid response!
> Steve
Thanks for the patch! I've never noticed. I guess my brain
auto-corrected it.
|
|
From: Steven A. F. <ste...@gm...> - 2023-08-10 18:05:35
|
On 8/10/23 11:19 AM, Josh Fisher wrote:
> On 8/10/23 09:51, Steven A. Falco wrote:
>> I've had a working setup for years, but suddenly I'm getting errors:
>>
>> Fatal error: 3992 Bad autochanger "load Volume v1_0005_0197 Slot 412, Drive 0": ERR=Child exited with code 1.
>> Results=cannot load drive 0 from invalid slot 412
>>
>> bacula indeed thinks the volume is in slot 412, according to the "list media" command:
>>
>> 1,501 | v1_0005_0197 | Append | 1 | 23,539,407,831 | 5 | 3,628,800 | 1 | 412 | 1 | File | 1 | 0 | 2023-08-09 00:54:13 | 3,511,018 |
>>
>> I tried doing "vchanger /etc/vchanger/v1.conf REFRESH" which I thought would update bacula's inventory of the slots, but that doesn't seem effective.
>>
>> If I ask vchanger what it has, using "vchanger /etc/vchanger/v1.conf LIST", I get:
>>
>> 198:v1_0005_0197
>>
>> so vchanger thinks the volume is in slot 198.
>>
>> I was able to get bacula to correct its slots via "update slots", and things are working again, but I'd like to understand how the slots/volumes might have gotten out of sync. Any thoughts on that would be appreciated.
>>
>> Also, is the "update slots" command the right way to recover?
>
>
> Yes, 'update slots' is the right way. It gets out of sync every time a filesystem (virtual magazine), say a removable drive, is attached or detached from the system. Vchanger assigns that filesystem's volume files to slots in the order that they are attached. Once a filesystem is detached, the slots it occupied may be reused. Regardless, when it is again attached, it is likely to be assigned different to a different set of slots.
>
> Ordinarily, vchanger calls out to Bacula via its bconsole command when it detects a change in occupied slots. The REFRESH command simply triggers vchanger to check for slot changes and initiate a sync if needed. The sync is simply a call to bconsole to issue an 'update slots' command.
>
> So, you need to somehow initiate an 'update slots' command whenever a filesystem is attached or detached. You can call vchanger with the REFRESH command, you can go into bconsole and issue it directly, or you can use udev rules to cause udev to automatically launch vchanger with the REFRESH command whenever a filesystem assigned to vchanger is physically attached or detached.
>
> To use udev, there is a script (usually) installed at /usr/bin/vchanger-genudevrules that can be used to generate the udev rules by scanning the magazine= lines in the vchanger config file. Whenever a new filesystem is added or removed from the vchanger config file, those udev rules need to be regenerated It should be used to update a udev rules file, usually in /etc/udev/rules.d. I have mine in /etc/udev/rules.d/96-vchanger.rules.
>
> If the REFRESH command does not seem to actually change the slot number in Bacula, then something is preventing vchanger from launching the bconsole command. Check the vchanger config file. There is a bconsole= parameter that defaults to "bconsole". If the bconsole parameter is empty/blank, then vchanger will log that the update slots is needed, but will not actually call bconsole. Otherwise, if bconsole is not installed in a directory in the PATH environment variable, then it won't find the bconsole binary. Otherwise, there could be a permissions problem. Set log_level = LOG_DEBUG in the vchanger config to get very detailed logging of the process, which should show where it is failing.
>
>
I've checked the log, and I had one instance of:
Aug 09 09:49:09: [12299]: WARNING! 'update slots' needed in bconsole
Aug 09 09:49:09: [12299]: bconsole update slots command success
But after doing the manual "update slots", I don't see any more warnings. I don't know why bconsole couldn't be run that one time, but I'll keep an eye on it. Maybe I issued it as an unprivileged user rather than as root.
As an aside, looking at bconsole.cpp I'm surprised that the "success" message would be printed along with the WARNING line. It might be clearer to have the "success" line in an else clause, like:
if (update_slots) {
tFormat(cmd, "update slots storage=\"%s\" drive=\"0\"", conf.storage_name.c_str());
if(issue_bconsole_command(cmd.c_str())) {
vlog.Error("WARNING! 'update slots' needed in bconsole");
} else {
vlog.Info("bconsole update slots command success");
}
}
The same would be true of the label_barcodes a few lines later in the file.
I've also attached a trivial patch, because when reading the log I noticed that there is a typo which I fixed via s/preforming/performing/ in vchanger.cpp (around lines 638-672).
Thanks for the rapid response!
Steve
|
|
From: Josh F. <jf...@ja...> - 2023-08-10 15:36:06
|
On 8/10/23 09:51, Steven A. Falco wrote: > I've had a working setup for years, but suddenly I'm getting errors: > > Fatal error: 3992 Bad autochanger "load Volume v1_0005_0197 Slot 412, > Drive 0": ERR=Child exited with code 1. > Results=cannot load drive 0 from invalid slot 412 > > bacula indeed thinks the volume is in slot 412, according to the "list > media" command: > > 1,501 | v1_0005_0197 | Append | 1 | 23,539,407,831 | > 5 | 3,628,800 | 1 | 412 | 1 | File | 1 > | 0 | 2023-08-09 00:54:13 | 3,511,018 | > > I tried doing "vchanger /etc/vchanger/v1.conf REFRESH" which I thought > would update bacula's inventory of the slots, but that doesn't seem > effective. > > If I ask vchanger what it has, using "vchanger /etc/vchanger/v1.conf > LIST", I get: > > 198:v1_0005_0197 > > so vchanger thinks the volume is in slot 198. > > I was able to get bacula to correct its slots via "update slots", and > things are working again, but I'd like to understand how the > slots/volumes might have gotten out of sync. Any thoughts on that > would be appreciated. > > Also, is the "update slots" command the right way to recover? Yes, 'update slots' is the right way. It gets out of sync every time a filesystem (virtual magazine), say a removable drive, is attached or detached from the system. Vchanger assigns that filesystem's volume files to slots in the order that they are attached. Once a filesystem is detached, the slots it occupied may be reused. Regardless, when it is again attached, it is likely to be assigned different to a different set of slots. Ordinarily, vchanger calls out to Bacula via its bconsole command when it detects a change in occupied slots. The REFRESH command simply triggers vchanger to check for slot changes and initiate a sync if needed. The sync is simply a call to bconsole to issue an 'update slots' command. So, you need to somehow initiate an 'update slots' command whenever a filesystem is attached or detached. You can call vchanger with the REFRESH command, you can go into bconsole and issue it directly, or you can use udev rules to cause udev to automatically launch vchanger with the REFRESH command whenever a filesystem assigned to vchanger is physically attached or detached. To use udev, there is a script (usually) installed at /usr/bin/vchanger-genudevrules that can be used to generate the udev rules by scanning the magazine= lines in the vchanger config file. Whenever a new filesystem is added or removed from the vchanger config file, those udev rules need to be regenerated It should be used to update a udev rules file, usually in /etc/udev/rules.d. I have mine in /etc/udev/rules.d/96-vchanger.rules. If the REFRESH command does not seem to actually change the slot number in Bacula, then something is preventing vchanger from launching the bconsole command. Check the vchanger config file. There is a bconsole= parameter that defaults to "bconsole". If the bconsole parameter is empty/blank, then vchanger will log that the update slots is needed, but will not actually call bconsole. Otherwise, if bconsole is not installed in a directory in the PATH environment variable, then it won't find the bconsole binary. Otherwise, there could be a permissions problem. Set log_level = LOG_DEBUG in the vchanger config to get very detailed logging of the process, which should show where it is failing. |
|
From: Steven A. F. <ste...@gm...> - 2023-08-10 14:02:35
|
I've had a working setup for years, but suddenly I'm getting errors:
Fatal error: 3992 Bad autochanger "load Volume v1_0005_0197 Slot 412, Drive 0": ERR=Child exited with code 1.
Results=cannot load drive 0 from invalid slot 412
bacula indeed thinks the volume is in slot 412, according to the "list media" command:
1,501 | v1_0005_0197 | Append | 1 | 23,539,407,831 | 5 | 3,628,800 | 1 | 412 | 1 | File | 1 | 0 | 2023-08-09 00:54:13 | 3,511,018 |
I tried doing "vchanger /etc/vchanger/v1.conf REFRESH" which I thought would update bacula's inventory of the slots, but that doesn't seem effective.
If I ask vchanger what it has, using "vchanger /etc/vchanger/v1.conf LIST", I get:
198:v1_0005_0197
so vchanger thinks the volume is in slot 198.
I was able to get bacula to correct its slots via "update slots", and things are working again, but I'd like to understand how the slots/volumes might have gotten out of sync. Any thoughts on that would be appreciated.
Also, is the "update slots" command the right way to recover?
Steve
|
|
From: Marco G. <ga...@li...> - 2023-05-21 06:10:20
|
Mandi! Josh Fisher via Vchanger-users In chel di` si favelave... > Is it possible for you to use a newer version? Not in short time and little effort; there's one director that run 30+ storage daemons, and this need a bit of planning... -- L'Italia ripudia la guerra come mezzo di risoluzione delle controversie internazionali. (art. 11 Costituzione) |
|
From: Josh F. <jf...@ja...> - 2023-05-18 13:03:28
|
On 5/17/23 12:55, Marco Gaiarin wrote: > Mandi! Josh Fisher via Vchanger-users > In chel di` si favelave... > >>> I'll try to post to the main bacula list, please support me there. ;-) >> OK > A week passed, no feedback. I know my english is bad, but seems i was > sufficiently clear... It was clear to me, and I am a native English speaker. I think there was no response because you were very clear and nobody had anything to add or say. > It is worth a try to add a bug reprt on: > https://www.bacula.org/support/bug-reporting/ > > ?! > > > Or the version i use is too old and will be ignored? Thanks. > Is it possible for you to use a newer version? You only need update the Director and Storage daemons. The clients do not have to be updated. I believe that the problem is 100% in the Director, but the Director and Storage daemons must always be the same version. The clients can use an older version than the Director, but not the Storage. |
|
From: Marco G. <ga...@li...> - 2023-05-17 17:10:18
|
Mandi! Josh Fisher via Vchanger-users In chel di` si favelave... >> I'll try to post to the main bacula list, please support me there. ;-) > OK A week passed, no feedback. I know my english is bad, but seems i was sufficiently clear... It is worth a try to add a bug reprt on: https://www.bacula.org/support/bug-reporting/ ?! Or the version i use is too old and will be ignored? Thanks. -- Il Re di Spagna fece vela, verso l'isola incantata pero` quell'isola non c'era, e mai nessuno l'ha trovata (F. Guccini) |
|
From: Josh F. <jf...@ja...> - 2023-05-12 14:47:22
|
On 5/12/23 03:40, Marco Gaiarin wrote: > Mandi! Josh Fisher via Vchanger-users > In chel di` si favelave... > >> Yes. That certainly seems like a logic bug to me. My opinion is that >> Bacula should not try to load a volume that is not in one of the >> changer's slots. I understand why it picks the only available volumes, >> but it should send a operator notice to load the volume. It should not >> be trying to load and use it. > OK, and (i suppose) this can be a 'vchanger' bug, but a bacula logic bug, > right? I don't see that it is a vchanger bug. This problem would also apply to a tape autochanger, I think. Only Bacula can choose which tape to load. In a tape autochanger, the problem would occur when no tapes in any of the slots have status=Append AND the job's pool does contain tapes with status=Append, but those tapes are NOT in a slot. > > I'll try to post to the main bacula list, please support me there. ;-) OK > > > Thanks. > |
|
From: Marco G. <ga...@li...> - 2023-05-12 10:40:14
|
Mandi! Josh Fisher via Vchanger-users In chel di` si favelave... > Yes. That certainly seems like a logic bug to me. My opinion is that > Bacula should not try to load a volume that is not in one of the > changer's slots. I understand why it picks the only available volumes, > but it should send a operator notice to load the volume. It should not > be trying to load and use it. OK, and (i suppose) this can be a 'vchanger' bug, but a bacula logic bug, right? I'll try to post to the main bacula list, please support me there. ;-) Thanks. -- Ognuno vada dove vuole andare, ognuno invecchi come gli pare ma non raccontate a me che cos'e` la LIBERTA`. (F. Guccini) |
|
From: Josh F. <jf...@ja...> - 2023-05-11 14:04:22
|
On 5/11/23 06:59, Marco Gaiarin wrote: > Mandi! Josh Fisher via Vchanger-users > In chel di` si favelave... > >> See my previous post. I believe the update slots is not happening after >> the disk is ejected and BEFORE the job is run. > Seemy previous post, seems get run. ;-) > > >> Also, the below SQL can be put it your query.sql file to define a menu >> item for the bconsole query command that will list volumes that bacula >> thinks are in a slot (or "in changer"). > Interesting... different situation, similar trouble. Volume status: > > *list media pool=PUG-BR-BRPVE2RDXPool > Automatically selected Catalog: BaculaLNF > Using Catalog "BaculaLNF" > +---------+---------------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------+----------+---------------------+-----------+ > | mediaid | volumename | volstatus | enabled | volbytes | volfiles | volretention | recycle | slot | inchanger | mediatype | voltype | volparts | lastwritten | expiresin | > +---------+---------------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------+----------+---------------------+-----------+ > | 95 | BRPVE2RDX_0000_0000 | Used | 1 | 208,849,026 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-26 23:00:36 | 479,584 | > | 96 | BRPVE2RDX_0000_0001 | Used | 1 | 30,271,526 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-23 23:00:20 | 220,368 | > | 97 | BRPVE2RDX_0000_0002 | Used | 1 | 245,449,879,830 | 57 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-21 22:53:45 | 47,173 | > | 98 | BRPVE2RDX_0000_0003 | Used | 1 | 2,728,283 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-27 23:00:11 | 565,959 | > | 99 | BRPVE2RDX_0000_0004 | Used | 1 | 67,134,269,206 | 15 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-21 21:04:17 | 40,605 | > | 100 | BRPVE2RDX_0000_0005 | Used | 1 | 32,143,254 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-22 23:02:44 | 134,112 | > | 101 | BRPVE2RDX_0000_0006 | Used | 1 | 83,933,767 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-27 23:00:29 | 565,977 | > | 102 | BRPVE2RDX_0000_0007 | Used | 1 | 2,101,942 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-22 23:00:21 | 133,969 | > | 103 | BRPVE2RDX_0000_0008 | Used | 1 | 31,871,214 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-23 23:02:01 | 220,469 | > | 104 | BRPVE2RDX_0000_0009 | Used | 1 | 42,334,248,183 | 9 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-23 02:05:27 | 145,075 | > | 175 | BRPVE2RDX_0001_0000 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-16 23:00:25 | 0 | > | 176 | BRPVE2RDX_0001_0001 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-18 23:00:13 | 0 | > | 177 | BRPVE2RDX_0001_0002 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-14 21:03:10 | 0 | > | 178 | BRPVE2RDX_0001_0003 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-17 23:05:50 | 0 | > | 179 | BRPVE2RDX_0001_0004 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-19 23:00:14 | 0 | > | 180 | BRPVE2RDX_0001_0005 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-17 23:00:13 | 0 | > | 181 | BRPVE2RDX_0001_0006 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-19 23:00:32 | 0 | > | 182 | BRPVE2RDX_0001_0007 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-18 23:05:35 | 0 | > | 183 | BRPVE2RDX_0001_0008 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-21 09:10:45 | 0 | > | 184 | BRPVE2RDX_0001_0009 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-20 23:00:13 | 0 | > | 275 | BRPVE2RDX_0002_0000 | Used | 1 | 1,798,243 | 0 | 1,728,000 | 1 | 1 | 1 | RDX | 1 | 0 | 2023-05-09 23:00:12 | 1,602,760 | > | 276 | BRPVE2RDX_0002_0001 | Used | 1 | 1,704,328 | 0 | 1,728,000 | 1 | 2 | 1 | RDX | 1 | 0 | 2023-05-08 23:00:14 | 1,516,362 | > | 277 | BRPVE2RDX_0002_0002 | Used | 1 | 29,739,131 | 0 | 1,728,000 | 1 | 3 | 1 | RDX | 1 | 0 | 2023-05-08 09:30:34 | 1,467,782 | > | 278 | BRPVE2RDX_0002_0003 | Used | 1 | 70,855,889 | 0 | 1,728,000 | 1 | 4 | 1 | RDX | 1 | 1 | 2023-05-09 23:00:28 | 1,602,776 | > | 279 | BRPVE2RDX_0002_0004 | Used | 1 | 2,646,417 | 0 | 1,728,000 | 1 | 5 | 1 | RDX | 1 | 1 | 2023-05-10 23:00:14 | 1,689,162 | > | 280 | BRPVE2RDX_0002_0005 | Used | 1 | 75,205,456 | 0 | 1,728,000 | 1 | 6 | 1 | RDX | 1 | 0 | 2023-05-02 23:00:35 | 997,983 | > | 281 | BRPVE2RDX_0002_0006 | Used | 1 | 49,188,203 | 0 | 1,728,000 | 1 | 7 | 1 | RDX | 1 | 0 | 2023-05-08 09:31:03 | 1,467,811 | > | 282 | BRPVE2RDX_0002_0007 | Used | 1 | 1,974,592 | 0 | 1,728,000 | 1 | 8 | 1 | RDX | 1 | 0 | 2023-05-04 23:00:12 | 1,170,760 | > | 283 | BRPVE2RDX_0002_0008 | Used | 1 | 42,406,838,890 | 9 | 1,728,000 | 1 | 9 | 1 | RDX | 1 | 0 | 2023-05-08 09:35:08 | 1,468,056 | > | 284 | BRPVE2RDX_0002_0009 | Used | 1 | 125,260,576 | 0 | 1,728,000 | 1 | 10 | 1 | RDX | 1 | 1 | 2023-05-08 23:00:32 | 1,516,380 | > | 716 | BRPVE2RDX_0001_0010 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-15 23:00:13 | 0 | > | 717 | BRPVE2RDX_0001_0011 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-15 23:02:20 | 0 | > | 718 | BRPVE2RDX_0001_0012 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-16 02:07:58 | 0 | > | 719 | BRPVE2RDX_0001_0013 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-16 23:01:24 | 0 | > | 720 | BRPVE2RDX_0001_0014 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-14 22:53:33 | 0 | > | 731 | BRPVE2RDX_0000_0010 | Used | 1 | 2,126,555 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-24 23:00:23 | 306,771 | > | 732 | BRPVE2RDX_0000_0011 | Used | 1 | 22,547,597 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-25 23:00:38 | 393,186 | > | 733 | BRPVE2RDX_0000_0012 | Used | 1 | 1,237,550 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-25 23:00:23 | 393,171 | > | 734 | BRPVE2RDX_0000_0013 | Used | 1 | 2,052,329 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-26 23:00:20 | 479,568 | > | 735 | BRPVE2RDX_0000_0014 | Used | 1 | 37,422,681 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-24 23:00:48 | 306,796 | > | 740 | BRPVE2RDX_0002_0010 | Used | 1 | 3,148,955 | 0 | 1,728,000 | 1 | 11 | 1 | RDX | 1 | 0 | 2023-05-02 23:00:36 | 997,984 | > | 741 | BRPVE2RDX_0002_0011 | Used | 1 | 95,135,350 | 0 | 1,728,000 | 1 | 12 | 1 | RDX | 1 | 0 | 2023-05-04 23:00:29 | 1,170,777 | > | 742 | BRPVE2RDX_0002_0012 | Used | 1 | 30,921,050 | 0 | 1,728,000 | 1 | 13 | 1 | RDX | 1 | 0 | 2023-05-03 23:00:16 | 1,084,364 | > | 743 | BRPVE2RDX_0002_0013 | Used | 1 | 245,887,157,874 | 57 | 1,728,000 | 1 | 14 | 1 | RDX | 1 | 0 | 2023-05-05 22:24:18 | 1,255,006 | > | 744 | BRPVE2RDX_0002_0014 | Used | 1 | 121,686,143 | 0 | 1,728,000 | 1 | 15 | 1 | RDX | 1 | 0 | 2023-05-03 23:00:34 | 1,084,382 | > +---------+---------------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------+----------+---------------------+-----------+ > > practically media 3 (2) are loaded, but volumes are all exausted. So bacula > try to use the (just purged) volume in media 2 (1). Yes. That certainly seems like a logic bug to me. My opinion is that Bacula should not try to load a volume that is not in one of the changer's slots. I understand why it picks the only available volumes, but it should send a operator notice to load the volume. It should not be trying to load and use it. > > If i run your query (thanks!): > > root@lnfbacula:/etc/bacula# echo "query 2" | bconsole | grep " BRPVE2" > | 275 | BRPVE2RDX_0002_0000 | 0 | BRPVE2RDX | 1 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 276 | BRPVE2RDX_0002_0001 | 0 | BRPVE2RDX | 2 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 277 | BRPVE2RDX_0002_0002 | 0 | BRPVE2RDX | 3 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 278 | BRPVE2RDX_0002_0003 | 0 | BRPVE2RDX | 4 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 279 | BRPVE2RDX_0002_0004 | 0 | BRPVE2RDX | 5 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 280 | BRPVE2RDX_0002_0005 | 0 | BRPVE2RDX | 6 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 281 | BRPVE2RDX_0002_0006 | 0 | BRPVE2RDX | 7 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 282 | BRPVE2RDX_0002_0007 | 0 | BRPVE2RDX | 8 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 283 | BRPVE2RDX_0002_0008 | 39 | BRPVE2RDX | 9 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 284 | BRPVE2RDX_0002_0009 | 0 | BRPVE2RDX | 10 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 740 | BRPVE2RDX_0002_0010 | 0 | BRPVE2RDX | 11 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 741 | BRPVE2RDX_0002_0011 | 0 | BRPVE2RDX | 12 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 742 | BRPVE2RDX_0002_0012 | 0 | BRPVE2RDX | 13 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 743 | BRPVE2RDX_0002_0013 | 229 | BRPVE2RDX | 14 | PUG-BR-BRPVE2RDXPool | RDX | Used | > | 744 | BRPVE2RDX_0002_0014 | 0 | BRPVE2RDX | 15 | PUG-BR-BRPVE2RDXPool | RDX | Used | > > > and seems all correct, as expected. > |
|
From: Josh F. <jf...@ja...> - 2023-05-11 13:50:10
|
I agree. It all seems correct with vchanger and the update slots is performed as expected. On 5/11/23 06:46, Marco Gaiarin wrote: > 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. > |
|
From: Marco G. <ga...@li...> - 2023-05-11 11:10:28
|
Mandi! Josh Fisher via Vchanger-users In chel di` si favelave... > See my previous post. I believe the update slots is not happening after > the disk is ejected and BEFORE the job is run. Seemy previous post, seems get run. ;-) > Also, the below SQL can be put it your query.sql file to define a menu > item for the bconsole query command that will list volumes that bacula > thinks are in a slot (or "in changer"). Interesting... different situation, similar trouble. Volume status: *list media pool=PUG-BR-BRPVE2RDXPool Automatically selected Catalog: BaculaLNF Using Catalog "BaculaLNF" +---------+---------------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------+----------+---------------------+-----------+ | mediaid | volumename | volstatus | enabled | volbytes | volfiles | volretention | recycle | slot | inchanger | mediatype | voltype | volparts | lastwritten | expiresin | +---------+---------------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------+----------+---------------------+-----------+ | 95 | BRPVE2RDX_0000_0000 | Used | 1 | 208,849,026 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-26 23:00:36 | 479,584 | | 96 | BRPVE2RDX_0000_0001 | Used | 1 | 30,271,526 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-23 23:00:20 | 220,368 | | 97 | BRPVE2RDX_0000_0002 | Used | 1 | 245,449,879,830 | 57 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-21 22:53:45 | 47,173 | | 98 | BRPVE2RDX_0000_0003 | Used | 1 | 2,728,283 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-27 23:00:11 | 565,959 | | 99 | BRPVE2RDX_0000_0004 | Used | 1 | 67,134,269,206 | 15 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-21 21:04:17 | 40,605 | | 100 | BRPVE2RDX_0000_0005 | Used | 1 | 32,143,254 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-22 23:02:44 | 134,112 | | 101 | BRPVE2RDX_0000_0006 | Used | 1 | 83,933,767 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-27 23:00:29 | 565,977 | | 102 | BRPVE2RDX_0000_0007 | Used | 1 | 2,101,942 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-22 23:00:21 | 133,969 | | 103 | BRPVE2RDX_0000_0008 | Used | 1 | 31,871,214 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-23 23:02:01 | 220,469 | | 104 | BRPVE2RDX_0000_0009 | Used | 1 | 42,334,248,183 | 9 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-23 02:05:27 | 145,075 | | 175 | BRPVE2RDX_0001_0000 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-16 23:00:25 | 0 | | 176 | BRPVE2RDX_0001_0001 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-18 23:00:13 | 0 | | 177 | BRPVE2RDX_0001_0002 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-14 21:03:10 | 0 | | 178 | BRPVE2RDX_0001_0003 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-17 23:05:50 | 0 | | 179 | BRPVE2RDX_0001_0004 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-19 23:00:14 | 0 | | 180 | BRPVE2RDX_0001_0005 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-17 23:00:13 | 0 | | 181 | BRPVE2RDX_0001_0006 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-19 23:00:32 | 0 | | 182 | BRPVE2RDX_0001_0007 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-18 23:05:35 | 0 | | 183 | BRPVE2RDX_0001_0008 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-21 09:10:45 | 0 | | 184 | BRPVE2RDX_0001_0009 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-20 23:00:13 | 0 | | 275 | BRPVE2RDX_0002_0000 | Used | 1 | 1,798,243 | 0 | 1,728,000 | 1 | 1 | 1 | RDX | 1 | 0 | 2023-05-09 23:00:12 | 1,602,760 | | 276 | BRPVE2RDX_0002_0001 | Used | 1 | 1,704,328 | 0 | 1,728,000 | 1 | 2 | 1 | RDX | 1 | 0 | 2023-05-08 23:00:14 | 1,516,362 | | 277 | BRPVE2RDX_0002_0002 | Used | 1 | 29,739,131 | 0 | 1,728,000 | 1 | 3 | 1 | RDX | 1 | 0 | 2023-05-08 09:30:34 | 1,467,782 | | 278 | BRPVE2RDX_0002_0003 | Used | 1 | 70,855,889 | 0 | 1,728,000 | 1 | 4 | 1 | RDX | 1 | 1 | 2023-05-09 23:00:28 | 1,602,776 | | 279 | BRPVE2RDX_0002_0004 | Used | 1 | 2,646,417 | 0 | 1,728,000 | 1 | 5 | 1 | RDX | 1 | 1 | 2023-05-10 23:00:14 | 1,689,162 | | 280 | BRPVE2RDX_0002_0005 | Used | 1 | 75,205,456 | 0 | 1,728,000 | 1 | 6 | 1 | RDX | 1 | 0 | 2023-05-02 23:00:35 | 997,983 | | 281 | BRPVE2RDX_0002_0006 | Used | 1 | 49,188,203 | 0 | 1,728,000 | 1 | 7 | 1 | RDX | 1 | 0 | 2023-05-08 09:31:03 | 1,467,811 | | 282 | BRPVE2RDX_0002_0007 | Used | 1 | 1,974,592 | 0 | 1,728,000 | 1 | 8 | 1 | RDX | 1 | 0 | 2023-05-04 23:00:12 | 1,170,760 | | 283 | BRPVE2RDX_0002_0008 | Used | 1 | 42,406,838,890 | 9 | 1,728,000 | 1 | 9 | 1 | RDX | 1 | 0 | 2023-05-08 09:35:08 | 1,468,056 | | 284 | BRPVE2RDX_0002_0009 | Used | 1 | 125,260,576 | 0 | 1,728,000 | 1 | 10 | 1 | RDX | 1 | 1 | 2023-05-08 23:00:32 | 1,516,380 | | 716 | BRPVE2RDX_0001_0010 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-15 23:00:13 | 0 | | 717 | BRPVE2RDX_0001_0011 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-15 23:02:20 | 0 | | 718 | BRPVE2RDX_0001_0012 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-16 02:07:58 | 0 | | 719 | BRPVE2RDX_0001_0013 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-16 23:01:24 | 0 | | 720 | BRPVE2RDX_0001_0014 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-14 22:53:33 | 0 | | 731 | BRPVE2RDX_0000_0010 | Used | 1 | 2,126,555 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-24 23:00:23 | 306,771 | | 732 | BRPVE2RDX_0000_0011 | Used | 1 | 22,547,597 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-25 23:00:38 | 393,186 | | 733 | BRPVE2RDX_0000_0012 | Used | 1 | 1,237,550 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-25 23:00:23 | 393,171 | | 734 | BRPVE2RDX_0000_0013 | Used | 1 | 2,052,329 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-26 23:00:20 | 479,568 | | 735 | BRPVE2RDX_0000_0014 | Used | 1 | 37,422,681 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-24 23:00:48 | 306,796 | | 740 | BRPVE2RDX_0002_0010 | Used | 1 | 3,148,955 | 0 | 1,728,000 | 1 | 11 | 1 | RDX | 1 | 0 | 2023-05-02 23:00:36 | 997,984 | | 741 | BRPVE2RDX_0002_0011 | Used | 1 | 95,135,350 | 0 | 1,728,000 | 1 | 12 | 1 | RDX | 1 | 0 | 2023-05-04 23:00:29 | 1,170,777 | | 742 | BRPVE2RDX_0002_0012 | Used | 1 | 30,921,050 | 0 | 1,728,000 | 1 | 13 | 1 | RDX | 1 | 0 | 2023-05-03 23:00:16 | 1,084,364 | | 743 | BRPVE2RDX_0002_0013 | Used | 1 | 245,887,157,874 | 57 | 1,728,000 | 1 | 14 | 1 | RDX | 1 | 0 | 2023-05-05 22:24:18 | 1,255,006 | | 744 | BRPVE2RDX_0002_0014 | Used | 1 | 121,686,143 | 0 | 1,728,000 | 1 | 15 | 1 | RDX | 1 | 0 | 2023-05-03 23:00:34 | 1,084,382 | +---------+---------------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------+----------+---------------------+-----------+ practically media 3 (2) are loaded, but volumes are all exausted. So bacula try to use the (just purged) volume in media 2 (1). If i run your query (thanks!): root@lnfbacula:/etc/bacula# echo "query 2" | bconsole | grep " BRPVE2" | 275 | BRPVE2RDX_0002_0000 | 0 | BRPVE2RDX | 1 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 276 | BRPVE2RDX_0002_0001 | 0 | BRPVE2RDX | 2 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 277 | BRPVE2RDX_0002_0002 | 0 | BRPVE2RDX | 3 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 278 | BRPVE2RDX_0002_0003 | 0 | BRPVE2RDX | 4 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 279 | BRPVE2RDX_0002_0004 | 0 | BRPVE2RDX | 5 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 280 | BRPVE2RDX_0002_0005 | 0 | BRPVE2RDX | 6 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 281 | BRPVE2RDX_0002_0006 | 0 | BRPVE2RDX | 7 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 282 | BRPVE2RDX_0002_0007 | 0 | BRPVE2RDX | 8 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 283 | BRPVE2RDX_0002_0008 | 39 | BRPVE2RDX | 9 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 284 | BRPVE2RDX_0002_0009 | 0 | BRPVE2RDX | 10 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 740 | BRPVE2RDX_0002_0010 | 0 | BRPVE2RDX | 11 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 741 | BRPVE2RDX_0002_0011 | 0 | BRPVE2RDX | 12 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 742 | BRPVE2RDX_0002_0012 | 0 | BRPVE2RDX | 13 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 743 | BRPVE2RDX_0002_0013 | 229 | BRPVE2RDX | 14 | PUG-BR-BRPVE2RDXPool | RDX | Used | | 744 | BRPVE2RDX_0002_0014 | 0 | BRPVE2RDX | 15 | PUG-BR-BRPVE2RDXPool | RDX | Used | and seems all correct, as expected. -- Il settimo dice non ammazzare se del cielo vuoi esssere degno. Guardatela oggi, questa legge di Dio, tre volte inchiodata nel legno (F. De Andre`) |
|
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) |
|
From: Josh F. <jf...@ja...> - 2023-05-08 12:58:11
|
See my previous post. I believe the update slots is not happening after the disk is ejected and BEFORE the job is run. Also, the below SQL can be put it your query.sql file to define a menu item for the bconsole query command that will list volumes that bacula thinks are in a slot (or "in changer"). # 15 :List Volumes Bacula thinks are in changer SELECT MediaId,VolumeName,VolBytes/(1024*1024*1024) AS GB,Storage.Name AS Storage,Slot,Pool.Name AS Pool,MediaType,VolStatus FROM Media,Pool,Storage WHERE Media.PoolId=Pool.PoolId AND Slot>0 AND InChanger=1 AND Media.StorageId=Storage.StorageId ORDER BY MediaType ASC, Slot ASC; It can be useful to see if bacula thinks the correct volumes are in slots. On 5/8/23 05:44, Marco Gaiarin wrote: > I've tried to restart SD, cleanup all jobs and start from a fresh condition. > > Nope. Still bacula try to mount volume in the wrong media, not in slots, > putting all volumes on error. > > > So the 'virtual changer' metaphore seems to work until you don't have a > purged media in a non-mounted set, because bacula insist to mount it, > putting it on error. > I've tried to google around a bit, but found only some old reminescent post > on bugs of bacula 1.XX i hope solved now. ;-) > > > What i'm missing?! Thanks. > |
|
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. > |
|
From: Marco G. <ga...@li...> - 2023-05-08 10:10:26
|
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 | +---------+---------------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------+----------+---------------------+-----------+ | 45 | SDPVE2RDX_0000_0000 | Used | 1 | 333,592,723 | 0 | 1,728,000 | 1 | 1 | 1 | RDX | 1 | 0 | 2023-04-26 23:02:30 | 738,936 | | 46 | SDPVE2RDX_0000_0001 | Used | 1 | 181,875,638,823 | 42 | 1,728,000 | 1 | 2 | 1 | RDX | 1 | 0 | 2023-04-21 22:02:41 | 303,347 | | 47 | SDPVE2RDX_0000_0002 | Used | 1 | 274,304,626 | 0 | 1,728,000 | 1 | 3 | 1 | RDX | 1 | 0 | 2023-04-27 23:03:04 | 825,370 | | 48 | SDPVE2RDX_0000_0003 | Used | 1 | 136,766,487 | 0 | 1,728,000 | 1 | 4 | 1 | RDX | 1 | 0 | 2023-04-23 23:03:24 | 479,790 | | 49 | SDPVE2RDX_0000_0004 | Used | 1 | 98,558,078 | 0 | 1,728,000 | 1 | 5 | 1 | RDX | 1 | 0 | 2023-04-22 23:03:04 | 393,370 | | 50 | SDPVE2RDX_0000_0005 | Used | 1 | 43,774,768,005 | 10 | 1,728,000 | 1 | 6 | 1 | RDX | 1 | 0 | 2023-04-23 02:07:07 | 404,413 | | 51 | SDPVE2RDX_0000_0006 | Used | 1 | 94,488,618 | 0 | 1,728,000 | 1 | 7 | 1 | RDX | 1 | 0 | 2023-04-24 23:02:16 | 566,122 | | 52 | SDPVE2RDX_0000_0007 | Used | 1 | 116,431,192 | 0 | 1,728,000 | 1 | 8 | 1 | RDX | 1 | 0 | 2023-04-25 23:02:20 | 652,526 | | 53 | SDPVE2RDX_0000_0008 | Disabled | 1 | 234 | 0 | 1,728,000 | 1 | 9 | 1 | RDX | 1 | 0 | | 0 | | 54 | SDPVE2RDX_0000_0009 | Disabled | 1 | 234 | 0 | 1,728,000 | 1 | 10 | 1 | RDX | 1 | 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 | 0 | 2023-04-16 23:02:44 | 0 | | 79 | SDPVE2RDX_0001_0004 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-15 23:03:05 | 0 | | 80 | SDPVE2RDX_0001_0005 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-17 23:01:55 | 0 | | 81 | SDPVE2RDX_0001_0006 | Used | 1 | 381,105,354 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-18 23:03:31 | 47,797 | | 82 | SDPVE2RDX_0001_0007 | Error | 1 | 1 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-14 22:00:20 | 0 | | 83 | SDPVE2RDX_0001_0008 | Disabled | 1 | 234 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | | 0 | | 84 | SDPVE2RDX_0001_0009 | Disabled | 1 | 234 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 1 | 2022-10-12 23:01:43 | 0 | | 166 | SDPVE2RDX_0002_0001 | Used | 1 | 43,483,736,128 | 10 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-30 02:05:27 | 1,009,113 | | 167 | SDPVE2RDX_0002_0002 | Used | 1 | 432,436,677 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-05-02 23:02:13 | 1,257,319 | | 168 | SDPVE2RDX_0002_0003 | Used | 1 | 157,886,453 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-30 23:03:06 | 1,084,572 | | 169 | SDPVE2RDX_0002_0004 | Used | 1 | 234,957,948 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-05-01 23:02:06 | 1,170,912 | | 170 | SDPVE2RDX_0002_0005 | Used | 1 | 291,189,870 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 1 | 2023-05-04 23:01:48 | 1,430,094 | | 171 | SDPVE2RDX_0002_0006 | Used | 1 | 255,584,790 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 1 | 2023-05-03 23:02:15 | 1,343,721 | | 172 | SDPVE2RDX_0002_0007 | Used | 1 | 182,008,772,526 | 42 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-28 22:01:26 | 908,072 | | 173 | SDPVE2RDX_0002_0008 | Disabled | 1 | 234 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | | 0 | | 174 | SDPVE2RDX_0002_0009 | Disabled | 1 | 234 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 1 | 2022-09-23 21:53:46 | 0 | | 295 | SDPVE2RDX_0002_0000 | Used | 1 | 97,465,011 | 0 | 1,728,000 | 1 | 0 | 0 | RDX | 1 | 0 | 2023-04-29 23:02:06 | 998,112 | +---------+---------------------+-----------+---------+-----------------+----------+--------------+---------+------+-----------+-----------+---------+----------+---------------------+-----------+ 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 08-May 09:36 sdpve2-sd JobId 6648: Marking Volume "SDPVE2RDX_0001_0007" in Error in Catalog. 08-May 09:37 lnfbacula-dir JobId 6668: Recycled volume "SDPVE2RDX_0001_0004" 08-May 09:37 sdpve2-sd JobId 6668: Warning: mount.c:215 Open of File device "RDXStorage1" (/var/spool/vchanger/SDPVE2RDX/1) Volume "SDPVE2RDX_0001_0004" failed: ERR=file_dev.c:190 Could not open(/var/spool/vchanger/SDPVE2RDX/1,OPEN_READ_WRITE,0640): ERR=No such file or directory 08-May 09:37 sdpve2-sd JobId 6668: Marking Volume "SDPVE2RDX_0001_0004" in Error in Catalog. 08-May 09:37 lnfbacula-dir JobId 6668: Recycled volume "SDPVE2RDX_0001_0000" 08-May 09:37 sdpve2-sd JobId 6668: Warning: mount.c:215 Open of File device "RDXStorage1" (/var/spool/vchanger/SDPVE2RDX/1) Volume "SDPVE2RDX_0001_0000" failed: ERR=file_dev.c:190 Could not open(/var/spool/vchanger/SDPVE2RDX/1,OPEN_READ_WRITE,0640): ERR=No such file or directory 08-May 09:37 sdpve2-sd JobId 6668: Marking Volume "SDPVE2RDX_0001_0000" in Error in Catalog. 08-May 09:37 lnfbacula-dir JobId 6668: Recycled volume "SDPVE2RDX_0001_0003" 08-May 09:37 sdpve2-sd JobId 6668: Warning: mount.c:215 Open of File device "RDXStorage1" (/var/spool/vchanger/SDPVE2RDX/1) Volume "SDPVE2RDX_0001_0003" failed: ERR=file_dev.c:190 Could not open(/var/spool/vchanger/SDPVE2RDX/1,OPEN_READ_WRITE,0640): ERR=No such file or directory 08-May 09:37 sdpve2-sd JobId 6668: Marking Volume "SDPVE2RDX_0001_0003" in Error in Catalog. if i purge volume in error, at subsequent run bacula put them on error. I've tried to do an: update slots storage=SDPVE2RDX 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? 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. -- chi si convertiva nel novanta ne era dispensato nel novantuno (F. De Andre`) |
|
From: Marco G. <ga...@li...> - 2023-05-08 10:10:22
|
I've tried to restart SD, cleanup all jobs and start from a fresh condition. Nope. Still bacula try to mount volume in the wrong media, not in slots, putting all volumes on error. So the 'virtual changer' metaphore seems to work until you don't have a purged media in a non-mounted set, because bacula insist to mount it, putting it on error. I've tried to google around a bit, but found only some old reminescent post on bugs of bacula 1.XX i hope solved now. ;-) What i'm missing?! Thanks. -- Software is like sex: it's better when it's free. (Linus Torvalds) |
|
From: Justin C. <jus...@gm...> - 2023-05-06 21:54:13
|
Greetings, I still have no solution for this. Maybe some has an idea how I can proceed on this? Best J/C > On 21. Apr 2023, at 20:26, Justin Case <jus...@gm...> wrote: > > Hi altogether, > > with my first 2 HDDs I was able to create volumes with createvol and they were successfully registered with the director so they showed up as volumes in the director. > > I now created some few hundred volume files on a third HDD and it creates the labels, but then the script hangs when its trying to register the volumes with the director. > I also restarted the whole container, removed the volume files and ran createvol again. The same happens. > > Any ideas how to proceed now? > > |
|
From: Marco G. <ga...@li...> - 2023-04-26 12:40:25
|
Mandi! Justin Case In chel di` si favelave... > Any ideas how to proceed now? File permissions are OK?! -- Se Darl McBride [il presidente di SCO] ne fosse incaricato, probabilmente renderebbe anticostituzionale anche il matrimonio, poiché chiaramente attenua la normale natura commerciale dell'interazione umana ed è probabilmente un ostacolo importante alla crescita commerciale della prostituzione. Linus Torvalds |
|
From: Justin C. <jus...@gm...> - 2023-04-21 18:26:49
|
Hi altogether, with my first 2 HDDs I was able to create volumes with createvol and they were successfully registered with the director so they showed up as volumes in the director. I now created some few hundred volume files on a third HDD and it creates the labels, but then the script hangs when its trying to register the volumes with the director. I also restarted the whole container, removed the volume files and ran createvol again. The same happens. Any ideas how to proceed now? |
|
From: Marco G. <ga...@li...> - 2023-04-05 17:40:26
|
Mandi! Josh Fisher via Vchanger-users In chel di` si favelave... >> To me, RDX seems very like any USB disks; i don't know how to debug UDEV >> event, but if you say me how, i can try to look at... > I don't think there is anything to debug. The only difference was that > at the time when the udev script was invoked, the filesystem was > unmounted, yet the device node /dev/sdX was still there. Usually, with a > USB drive, the device node is delete by the OS and that is what triggers > udev. With RDX it seems to be different, maybe because the RDX device is > still plugged in and powered. Only the cartridge was ejected. How do you > usually eject? Do you umount the filesystem first, or just eject the > cartridge? I umount the FS, and then i eject it. But there's no '/dev/rdx' nor permanent device: root@cnpve3:~# df Filesystem 1K-blocks Used Available Use% Mounted on udev 12220504 0 12220504 0% /dev tmpfs 2449644 42276 2407368 2% /run rpool/ROOT/pve-1 450961536 2081408 448880128 1% / tmpfs 12248204 58136 12190068 1% /dev/shm tmpfs 5120 4 5116 1% /run/lock tmpfs 12248204 0 12248204 0% /sys/fs/cgroup rpool 448880256 128 448880128 1% /rpool rpool/data 448880256 128 448880128 1% /rpool/data rpool/ROOT 448880256 128 448880128 1% /rpool/ROOT rpool-backup 52487099648 9174830208 43312269440 18% /rpool-backup /dev/fuse 30720 36 30684 1% /etc/pve 10.10.5.23:/rpool-backup/vz 52487100416 9174830080 43312270336 18% /mnt/pve/nfs-scratch /dev/sdj1 1921720580 607441416 1216587308 34% /mnt/vchanger/4ccfcae1-8a35-4800-96b6-9dce8718569b tmpfs 2449640 0 2449640 0% /run/user/0 root@cnpve3:~# ls -la /dev/rdx* ls: cannot access '/dev/rdx*': No such file or directory root@cnpve3:~# ls -la /dev/sdj* brw-rw---- 1 root disk 8, 144 Mar 31 14:18 /dev/sdj brw-rw---- 1 root disk 8, 145 Mar 31 14:18 /dev/sdj1 root@cnpve3:~# ls -la /dev/disk/by-id/ | grep sdj lrwxrwxrwx 1 root root 9 Mar 31 14:18 usb-HP_RDX_003C75030237-0:0 -> ../../sdj lrwxrwxrwx 1 root root 10 Mar 31 14:18 usb-HP_RDX_003C75030237-0:0-part1 -> ../../sdj1 if i umount and eject it, the main device remains, effectively: root@cnpve3:~# ls -la /dev/rdx* ls: cannot access '/dev/rdx*': No such file or directory root@cnpve3:~# ls -la /dev/sdj* brw-rw---- 1 root disk 8, 144 Apr 5 18:23 /dev/sdj root@cnpve3:~# ls -la /dev/disk/by-id/ | grep sdj lrwxrwxrwx 1 root root 9 Apr 5 18:23 usb-HP_RDX_003C75030237-0:0 -> ../../sdj Interesting also the 'cfdisk' error: root@cnpve3:~# cfdisk /dev/sdj cfdisk: cannot open /dev/sdj: No medium found So, effectively, a device remain. >> 2) so, seems a Bacula bug? If yes, it worth a try to move to bacula list? > Yes. I think so. When Bacula is looking for an available volume for a > job, it at some point tries to make a volume available by recycling old > volumes. If it is able to recycle a volume that the job can use, then it > sees an available volume. When it sees the available volume, it tries to > load it, even if that volume is not in a slot. When it fails to load, it > causes an i/o error (file not found) and that causes Bacula to mark the > volume in error. The bug is that Bacula should not ever try to load a > volume that is not in a slot when reading/writing to an autochanger device. I'll try it. Thanks. -- E quindi vado avanti e non mi svesto, dei panni che son solito portare (F. Guccini) |