Re: [Bacula-users] Bacula not loading autochanger (lots more info)

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 454-5900

Still having the same problem, but after seeing the recent thread about req=
uired information I figured I'd best include the form with the information =
requested.

=3D=3D=3D=3D=3D=3D=3D=3D=3D SUPPORT =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=
=3D=3D

Bacula version:	1.38.9  (I had thought earlier it was 1.36.3 due to some in=
accurate documentation left behind by the person who had originally install=
ed it earlier this year, but checked and verified that the installed versio=
n is indeed 1.38.9.)

OS type and version:  Fedora Core 4 (Linux)  Here is output from uname -a:

Linux sandy.siderean.com 2.6.16-1.2115_FC4smp #1 SMP Mon Jun 5 15:01:58 EDT=
 2006 i686 i686 i386 GNU/Linux

How was Bacula built/installed?  Was installed from rpms by a former sysadm=
in from whom I inherited the project.

Concise description of the problem:  Bacula doesn't load tapes into autocha=
nger when it needs them.  Instead it keeps prompting to have them manually =
losded.  Won't even load them with the bconsole mount command.  Just report=
s mount OK and logs message requesting me to mount the tape.  Had previousl=
y posted to the list.  Arno suggested I replace all references to "VXA-Tape=
" with "VXA-Library" in the director configuration.  I've done so, but the =
problem still persists.

Bacula output showing the problem:
*messages
23-Oct 13:14 sandy-dir: Start Backup JobId 234, Job=3DSandy.2006-10-23_13.1=
4.17
23-Oct 13:14 sandy-sd: 3301 Issuing autochanger "loaded drive 0" command.
23-Oct 13:14 sandy-sd: 3302 Autochanger "loaded drive 0", result: nothing l=
oaded.
23-Oct 13:14 sandy-sd: 3301 Issuing autochanger "loaded drive 0" command.
23-Oct 13:14 sandy-sd: 3302 Autochanger "loaded drive 0", result: nothing l=
oaded.
23-Oct 13:14 sandy-sd: Please mount Volume "A0000001" on Storage Device "VX=
A-Drive" (/dev/nst0) for Job Sandy.2006-10-23_13.14.17

Steps to reproduce the problem:
1. Re/Start all 3 bacula daemons.  (They and the MySQL DB are all configure=
d to run as services.)
2. Issue the run command.
3. Select a backup job to run.
4. Once the job has started, check messages.
5. Note that Bacula has requested manual load of volume into drive, rather =
than having the autochanger load the drive as it should.

Other information (optional):
A copy of your config.out file (if built from source):  n/a, not built from=
 source

Tape drive/autochanger (for tape problems):  Exabyte VXA PacketLoader 1x10 =
1U with a single VXA-2 tape drive and 10 slots, the last of which contains =
a cleaning cartridge.

Have you run btape "test" command?  I ran it last week, and remember both t=
he "test" and "autochanger" portions passed.  When I tried the multiple-tap=
e "fill" test it also failed to load the second tape, but per Kern's earlie=
r post to the list I understand this is a known bug in btape which doesn't =
in itself necessarily indicate that Bacula won't work with the autochanger.=

Since I've made a number of configuration changes since then, figured I sho=
uld probably run it again.  Only problem is, the documentation is ambiguous=
 as to exactly what "device_name" to specify on the command line when invok=
ing btape.

If I specify the device file for the autochanger itself, I get

[root@sandy bacula]# btape -c /etc/bacula/bacula-sd.conf -v /dev/sg4
Tape block granularity is 1024 bytes.
btape: butil.c:265 Could not find device "/dev/sg4" in config file /etc/bac=
ula/bacula-sd.conf.
23-Oct 14:19 btape: btape Fatal error: butil.c:154 Cannot find device "/dev=
/sg4" in config file /etc/bacula/bacula-sd.conf.

This even though /dev/sg4 is indeed in the bacula-sd.conf file, as the valu=
e of "Changer Device" in both the Autochanger and Device resources.

So tried giving it the autochanger's resource name instead:

[root@sandy bacula]# btape -c /etc/bacula/bacula-sd.conf -v VXA-Library
Tape block granularity is 1024 bytes.
btape: butil.c:265 Could not find device "VXA-Library" in config file /etc/=
bacula/bacula-sd.conf.
23-Oct 14:20 btape: btape Fatal error: butil.c:154 Cannot find device "VXA-=
Library" in config file /etc/bacula/bacula-sd.conf.

This despite the fact that "VXA-Library" is also indeed in the bacula-sd.co=
nf file as the value of the "Name" directive in the autochanger resource.

If I give it the name of the drive's resource it gets in, but fails to load=
 the tape when I run test:

[root@sandy bacula]# btape -c /etc/bacula/bacula-sd.conf -v VXA-Drive
Tape block granularity is 1024 bytes.
btape: butil.c:272 Using device: "VXA-Drive" for writing.
23-Oct 14:42 btape: 3301 Issuing autochanger "loaded drive 0" command.
23-Oct 14:42 btape: 3302 Autochanger "loaded drive 0", result: nothing load=
ed.
23-Oct 14:42 btape: 3301 Issuing autochanger "loaded drive 0" command.
23-Oct 14:42 btape: 3302 Autochanger "loaded drive 0", result: nothing load=
ed.
btape: btape.c:338 open device "VXA-Drive" (/dev/nst0): OK
*test

=3D=3D=3D Write, rewind, and re-read test =3D=3D=3D

I'm going to write 1000 records and an EOF
then write 1000 records and an EOF, then rewind,
and re-read the data to verify that it is correct.

This is an *essential* feature ...

23-Oct 14:43 btape: 3301 Issuing autochanger "loaded drive 0" command.
23-Oct 14:43 btape: 3302 Autochanger "loaded drive 0", result: nothing load=
ed.
btape: btape.c:775 Bad status from rewind. ERR=3Ddev.c:678 Rewind error on =
"VXA-Drive" (/dev/nst0). ERR=3DNo medium found.

Curiously enough, though, if I run the "autochanger" test it loads the tape=
 just fine!

*autochanger

Ah, I see you have an autochanger configured.
To test the autochanger you must have a blank tape
 that I can write on in Slot 1.

Do you wish to continue with the Autochanger test? (y/n): y

=3D=3D=3D Autochanger test =3D=3D=3D

3301 Issuing autochanger "loaded" command.
Nothing loaded in the drive. OK.
3303 Issuing autochanger "load 1 0" command.
3303 Autochanger "load 1 0" status is OK.
23-Oct 14:45 btape: 3301 Issuing autochanger "loaded drive 0" command.
23-Oct 14:45 btape: 3302 Autochanger "loaded drive 0", result is Slot 1.
btape: btape.c:338 open device "VXA-Drive" (/dev/nst0): OK
btape: btape.c:1206 Rewound "VXA-Drive" (/dev/nst0)
btape: btape.c:1213 Wrote EOF to "VXA-Drive" (/dev/nst0)

The test autochanger worked!!

I get pretty much the same results if I invoke btape with the drive's physi=
cal device name /dev/nst0.  The "test" test only works if a tape is already=
 loaded in the drive, but the "autochanger" tape loads a tape if the drive =
is empty.

Looking back on it, I think I must have had a tape already loaded in the dr=
ive when I ran the initial tests last week.

Database problems: what database are you using?  Probably not a database pr=
oblem, but database is MySQL
What is the database version?  4.1.19

If the output involves configuration files, consider attaching
bacula-dir.conf, bacula-fd.conf, and bacula-sd.conf if necessary,
appropriate.

Here are the relevent sections of the bacula-sd.conf and bacula-dir.conf, w=
ith passwords removed, and also the modified section of mtx-changer:

>From bacula-sd.conf:
********************

Autochanger {
 Name =3D VXA-Library
 Device =3D VXA-Drive
 Changer Command =3D "/etc/bacula/mtx-changer %c %o %S %a %d"
 Changer Device =3D /dev/sg4
}

Device {
 Name                    =3D VXA-Drive
 Media Type              =3D VXA-2
 Archive Device          =3D /dev/nst0
 Autochanger             =3D YES
 Drive Index             =3D 0
 Changer Device          =3D /dev/sg4
 Offline On Unmount      =3D no
 Hardware End of Medium  =3D no
 BSF at EOM              =3D yes
 Backward Space Record   =3D yes
 Fast Forward Space File =3D yes
 TWO EOF                 =3D yes
}

>From bacula-dir.conf:
*********************

Storage {
   Name =3D VXA-Library
   Address =3D sandy.siderean.com
   Password =3D <removed>
   Device =3D VXA-Library
   MediaType =3D VXA-2
   Autochanger =3D yes
}

Modified portion of mtx-changer script:
***************************************

# Increase the sleep time if you have a slow device
# or remove the sleep and add the following:
      wait_for_drive $device
      sleep 15
      exit $rtn
      ;;

   list)
      debug "Doing mtx -f $ctl -- to list volumes"
      make_temp_file
# Enable the following if you are using barcodes and need an inventory
#     $(MTX) -f $ctl inventory
#      ${MTX} -f $ctl status >${TMPFILE}
#      rtn=3D$?
#      cat ${TMPFILE} | grep " *Storage Element [0-9]*:.*Full" | awk "{prin=
t \$3 \\
$4}" | sed "s/Full *\(:VolumeTag=3D\)*//"
#      cat ${TMPFILE} | grep "^Data Transfer Element [0-9]*:Full (Storage E=
lement \
[0-9]" | awk '{printf "%s:%s\n",$7,$10}'
#      rm -f ${TMPFILE} >/dev/null 2>&1
#
# If you have a VXA PacketLoader and the above does not work, try
#  turning it off and enabling the following line.
     ${MTX} -f $ctl status | grep " *Storage Element [0-9]*:.*Full" | sed "=
s/*Stor\
age Element //" | sed "s/Full :VolumeTag=3D//"
      exit $rtn
      ;;

This is after I implemented Arno's earlier suggestion to replace references=
 to "VXA-Tape" with "VXA-Library" and also some other suggestions for this =
type of problem that I found in earlier threads in the list archives.

I also noticed in an earlier thread about a similar problem back in March o=
f this year, Arno suggested that running the "update slots" command might h=
elp. =

AL> It is possible that the catalog doesn't have any information about volu=
mes
AL> available in the autochanger. The easiest resolution in that case is di=
ong
AL> an 'update slots [scan] storage=3DAutoloader' in a Bacula console.

This sounded useful, so gave it a try and got the following bizarre output:=

*update slots
Using default Catalog name=3DMyCatalog DB=3Dbacula
Automatically selected Storage: VXA-Library
Connecting to Storage daemon VXA-Library at sandy.siderean.com:9103 ...
Connecting to Storage daemon VXA-Library at sandy.siderean.com:9103 ...
3306 Issuing autochanger "slots" command.
Device "VXA-Library" has 10 slots.
Connecting to Storage daemon VXA-Library at sandy.siderean.com:9103 ...
3301 Issuing autochanger "loaded drive 0" command.
3302 Autochanger "loaded drive 0", result: nothing loaded.
3306 Issuing autochanger "list" command.
Invalid Slot number:       Storage Element 1:A0000001
Invalid Slot number:       Storage Element 2:A0000002
Invalid Slot number:       Storage Element 3:A0000003
Invalid Slot number:       Storage Element 4:A0000004
Invalid Slot number:       Storage Element 5:A0000005
Invalid Slot number:       Storage Element 6:A0000006
Invalid Slot number:       Storage Element 7:A0000007
Invalid Slot number:       Storage Element 9:A0000009
Invalid Slot number:       Storage Element 10:CLNA0001
No Volumes found to label, or no barcodes.

Note that it skips from slot 7 to slot 9 without any mantion of slot 8 desp=
ite the fact that slot 8 exists, contains a tape labelled A0000008, and can=
 be successfully loaded and unloaded by mtx-changer.  Clearly it sees that =
the drive has 10 slots, why can't it number them correctly?  Is this someth=
ing I have to configure somewhere?

John J. Felczak
Build & Integration Manager
Siderean Software, Inc.

----------------------------------------------------------------------

Here's Arno's reply to my original post, included for purposes of thread co=
ntinuity...

Message: 7
Date: Sat, 21 Oct 2006 21:12:15 +0200
From: Arno Lehmann <al...@it...>
Subject: Re: [Bacula-users] Bacula not loading autochanger
To: "bac...@li..."
	<bac...@li...>
Message-ID: <453...@it...>
Content-Type: text/plain; charset=3DISO-8859-1; format=3Dflowed

Hi,

On 10/21/2006 4:15 AM, John Felczak wrote:
> Bacula 1.36.3 on Fedora Core 4

Consider upgrading to 1.38. It has some enhancements, and it is much more l=
ikely to get qualified support as many list users dropped 1.36 quite a whil=
e ago...

> Exabyte VXA Packetloader 1x10 1U
>
> Bacula seems able to successfully query this autochanger if it's loaded, =
and I can unload it using the unmount command in bconsole, but instead of l=
oading the drive when running a backup or restore job, it prompts for a man=
ual mount:
>
> 20-Oct 13:59 sandy-sd: 3301 Issuing autochanger "loaded drive 0" command.=

> 20-Oct 13:59 sandy-sd: 3302 Autochanger "loaded drive 0", result: nothing=
 loaded.
> 20-Oct 13:59 sandy-sd: RestoreFiles.2006-10-20_13.55.44 Warning: acquire.=
c:146 Couldn't rewind device "VXA-Drive" (/dev/nst0): ERR=3Ddev.c:678 Rewin=
d error on "VXA-Drive" (/dev/nst0). ERR=3DNo medium found.
>
> 20-Oct 13:59 sandy-sd: Please mount Volume "A0000001" on Storage =

> Device "VXA-Drive" (/dev/nst0) for Job RestoreFiles.2006-10-20_13.55.44 2=
0-Oct 14:01 sandy-sd: 3301 Issuing autochanger "loaded drive 0" command.
> 20-Oct 14:01 sandy-sd: 3302 Autochanger "loaded drive 0", result: nothing=
 loaded.
> 20-Oct 14:01 sandy-sd: RestoreFiles.2006-10-20_13.55.44 Warning: acquire.=
c:146 Couldn't rewind device "VXA-Drive" (/dev/nst0): ERR=3Ddev.c:678 Rewin=
d error on "VXA-Drive" (/dev/nst0). ERR=3DNo medium found.
>
> 20-Oct 14:01 sandy-sd: Please mount Volume "A0000001" on Storage =

> Device "VXA-Drive" (/dev/nst0) for Job =

> RestoreFiles.2006-10-20_13.55.44
>
> Here are the storage definitions from my bacula-sd.conf:
>
> Autochanger {
>  Name =3D "VXA-Library"
>  Device =3D "VXA-Drive"
>  Changer Command =3D "/etc/bacula/mtx-changer %c %o %S %a %d"
>  Changer Device =3D /dev/sg4
> }

Interesting. Are you sure you run 1.36, not 1.38? IIRC, the Autochanger res=
ource was only implemented with 1.38...

> Device {
>  Maximum Changer Wait =3D 120
>  Name =3D "VXA-Drive"
>  Archive Device =3D /dev/nst0
>  Device Type =3D Tape
>  Media Type =3D "VXA-2"
>  Autochanger =3D Yes
>  Changer Device =3D /dev/sg4
>  Drive Index =3D 0
>  Autoselect =3D yes
>  AlwaysOpen =3D yes
>  Removable Media =3D yes
>  Random Access =3D no
>  Label Media =3D yes
>  Automatic Mount =3D yes;
> }
>
> Isn't that what autochangers are supposed to be for?
>
> BTW, I can load, unload, and do any of the various tape library operation=
s from mtx-changer at the command line.  The btape test and btape autochang=
er test both pass.  The btape multiple tape fill command also fails to load=
 the drive, but from what I've seen on the list that's a known btape bug, a=
nd shouldn't prevent bacula from properly using the autochanger the way it =
doesn't seem to be doing.
>
> If I try unmount and mount commands from bconsole I get the following:
>
> *unmount
> Automatically selected Storage: VXA-Tape

Ah, that's it... it seems like your director configuration doesn't know abo=
ut VXA-Library but only references VXA-Tape... If you actually have a
1.38 version running reference the Autochanger device wherever possible, i.=
e. everywhere except where you really know why you want a drive, not the au=
tochanger, addressed.

> Connecting to Storage daemon VXA-Tape at sandy.siderean.com:9103 ...
> 3301 Issuing autochanger "loaded drive 0" command.
> 3302 Autochanger "loaded drive 0", result is Slot 8.
> 3307 Issuing autochanger "unload slot 8, drive 0" command.
> 3001 Device "VXA-Drive" (/dev/nst0) unmounted.
>
>
> *mount
> Automatically selected Storage: VXA-Tape
> 3301 Issuing autochanger "loaded drive 0" command.
> 3302 Autochanger "loaded drive 0", result: nothing loaded.
> 3301 Issuing autochanger "loaded drive 0" command.
> 3302 Autochanger "loaded drive 0", result: nothing loaded.
> 3905 Device "VXA-Drive" (/dev/nst0) open but no Bacula volume is mounted.=

> If this is not a blank tape, try unmounting and remounting the Volume.
>
> So bacula seems to know how to unload the drive but not how to load it, a=
nd there doesn't seem to be any "load" command I can use to tell bconsole t=
o load the tape either.

No, there's no load command or anything... you can, to contibue your backup=
s for example :-) unmount the drive from bconsole, use mtx to load the next=
 tape, and then mount from bconsole.

>
> Ideas, anyone?

Sure, and I hope they help you.

Arno