The FreeBSD Diary

I am attempting to revive a long unused-tape library. I want it active so I can go away on holiday and not worry about changing tapes. At present, I use a single DLT-7000 drive, which needs a new tape every three or four days. My strategy includes filling each tape, then starting a new one. This approach may or may not be something that is applicable to your needs.

I am using Bacula 3.0.2 here. With PostgreSQL 8.3.7, and mtx version 1.3.11. Just saying.

These are my existing devices before attaching my tape library:

# camcontrol devlist
<QUANTUM DLT7000 1E48>             at scbus1 target 5 lun 0 (sa0,pass0)
<USB 2.0 Storage Device 0100>      at scbus2 target 0 lun 0 (pass1,da0)
<HL-DT-ST DVDRAM GSA-H10A JL02>    at scbus4 target 0 lun 0 (pass2,cd0)

That existing sa0 is used by my Bacula installation. That is important to note, as you will see below.

With SCSI devices, it is important to use a SCSCI card and terminator that is appropriate to the device in question. These choices are outside the scope of this article.

I last tried using this tape library in April 2008 and I failed. The problem was not seeing both the library and the drive at the same time. I found my post to the FreeBSD SCSCI mailing list. But back in 2006, when I first bought the library, it worked just find.

The standard FreeBSD tool for controlling SCSI devices is camcontrol. In this command, I look for what is connected:

# camcontrol devlist
<QUANTUM DLT7000 1E48>             at scbus1 target 5 lun 0 (pass0,sa0)
<USB 2.0 Storage Device 0100>      at scbus2 target 0 lun 0 (pass1,da0)
<HL-DT-ST DVDRAM GSA-H10A JL02>    at scbus4 target 0 lun 0 (pass2,cd0)

After connecting my tape library, I ask camcontrol to scan for the new device, and then list the devices again:

# sudo camcontrol rescan all
Re-scan of bus 0 was successful
Re-scan of bus 1 was successful
Re-scan of bus 2 was successful
Re-scan of bus 3 was successful
Re-scan of bus 4 was successful
Re-scan of bus 5 was successful
Re-scan of bus 6 was successful
# camcontrol devlist
<DEC TZ89     (C) DEC 1837>        at scbus0 target 1 lun 0 (pass3,sa1)
<QUANTUM DLT7000 1E48>             at scbus1 target 5 lun 0 (pass0,sa0)
<USB 2.0 Storage Device 0100>      at scbus2 target 0 lun 0 (pass1,da0)
<HL-DT-ST DVDRAM GSA-H10A JL02>    at scbus4 target 0 lun 0 (pass2,cd0)

As you can see, a new device has arrived, the DC TZ89. Looking back at my original notes on this tape library, you will see the same model number appears there. This looks good so far. And you can also see sa0, the original tape drive, and a new sa1. But the drive in the tape library cannot be found. This reflects the same situation I left in 2008.

At this point (Monday), I spent time over the next two nights finding a solution. It was on Wednesay night that I found a cable combination that worked. The original cabling, which worked is on the left. The new combination is on the right.

After getting the cables right, here are my devices:

# camcontrol devlist
<QUANTUM DLT7000 1E48>             at scbus0 target 5 lun 0 (sa0,pass0)
<DEC TL800    (C) DEC 0326>        at scbus1 target 0 lun 0 (pass1,ch0)
<DEC TZ89     (C) DEC 1837>        at scbus1 target 5 lun 0 (sa1,pass2)
<USB 2.0 Storage Device 0100>      at scbus2 target 0 lun 0 (pass3,da0)
<HL-DT-ST DVDRAM GSA-H10A JL02>    at scbus4 target 0 lun 0 (pass4,cd0)

You may notice that some physical hardware has moved to new logical devices. I always want the standalone DLT drive to be on sa0, and the tape library's drive to be on sa1, regardless of what is attached. This way, Bacula always knows what is where. I did this with the following entries added to /boot/device.hints:

#
# hints to keep Bacula seeing consistent stuff
#
hint.scbus.1.at="ahc0"
hint.scbus.0.at="ahc1"

The next test, writing via tar, was done before I finalized the cables.

Let's try writing to sa1, after we first load in a tape. I did that via the tape library front panel. Later in this article, we'll use the command line. For now, let us walk before we run.

Let's try a very simple backup and restore, using tar. In my case, I have multiple tape drives attached. Be sure to use the right one. I did something like this:

# tar cvf /dev/nsa1 .
a .
a .k5login
a .cshrc
a .login
a .profile
a .history
a .bashrc
a .bash_profile
a .bash_history
a make
a .rnd
a .qt
a .kde
a .ssh
a .ssh/known_hosts
a .kde/share
a .kde/share/config
a make/Makefile
a make/Makefile~
a make/NGAIO
...
...
...

Note: not all output is shown above. It was about 8GB in total.

Now for the restore:

# mkdir /usr/restore-test
# cd /usr/restore-test
# mt -f /dev/nsa1 rewind
# tar xvf /dev/nsa1

[ lots of output here omitted]

After the restore, we need to run a diff:

# diff -ruN ~dan/ /usr/restore-test

My autochanger configurtion is this:

Device {
  Name                    = DLTLIB0
  Description             = Digital DLT MiniLibrary - TL891
  Media Type              = DLT
  Archive Device          = /dev/nsa1

  Autochanger             = YES
  Drive Index             = 0

  Offline On Unmount      = no
  Hardware End of Medium  = no
  BSF at EOM              = yes
  Backward Space Record   = no
  Fast Forward Space File = no
  TWO EOF                 = yes

  Spool Directory         = /home/bacula/spooling-lib
  Maximum Spool Size      = 11759496889
  Maximum Job Spool Size  = 11759496889    # 10GB
}

Autochanger {
  Name            = TapeRobot
  Device          = DLTLIB0
  Changer Device  = /dev/pass1
  Changer Command = "/home/dan/rc-chio-changer %c %o %S %a %d"
}

mtx is a tool for controling SCSI media changer devices. In FreeBSD, it comes as a port at /usr/ports/misc/mtx. Recent versions of Bacula include a wrapper for mtx. mtx-changer is a wrapper for the mtx utility. You can use any wrapper you want. The wrapper acts as a go-between, giving Bacula a simple interface to mtx. There are two parts supplied with Bacula: the mtx-changer script and a configurationfile. Sometimes you need to alter these scripts to suit your OS. If so, I prefer not to alter the package-supplied files in place. I prefer to copy and edit instead:

cp -i /usr/local/share/bacula/mtx-changer      /usr/local/sbin/
cp -i /usr/local/share/bacula/mtx-changer.conf /usr/local/etc/

The first thing to do after copying those files: alter mtx-changer to refer to the new configuration file.

Before we use mtx-wrapper, let us ensure mtx works. We start with a basic simple mtx command.

# mtx -f /dev/pass1 status
  Storage Changer /dev/pass1:1 Drives, 10 Slots ( 0 Import/Export )
Data Transfer Element 0:Empty
      Storage Element 1:Full :VolumeTag=DGG472
      Storage Element 2:Full :VolumeTag=DGG440
      Storage Element 3:Full :VolumeTag=DGG443
      Storage Element 4:Full :VolumeTag=DGG467
      Storage Element 5:Full :VolumeTag=DGG469
      Storage Element 6:Full :VolumeTag=DGG442
      Storage Element 7:Full :VolumeTag=DGG457
      Storage Element 8:Full :VolumeTag=DGG441
      Storage Element 9:Full :VolumeTag=DGG471
      Storage Element 10:Full :VolumeTag=DGG465
#

That is a list of the slots and which tape is in that slot.

Now, I load the tape from slot 3 into the drive (slot 0);

# /usr/local/sbin/mtx-changer /dev/pass1 load 3 /dev/sa0 0
# mtx -f /dev/pass1 status
   Storage Changer /dev/pass1:1 Drives, 10 Slots ( 0 Import/Export )
Data Transfer Element 0:Full (Storage Element 3 Loaded):VolumeTag = DGG443
      Storage Element 1:Full :VolumeTag=DGG472
      Storage Element 2:Full :VolumeTag=DGG440
      Storage Element 3:Empty
      Storage Element 4:Full :VolumeTag=DGG467
      Storage Element 5:Full :VolumeTag=DGG469
      Storage Element 6:Full :VolumeTag=DGG442
      Storage Element 7:Full :VolumeTag=DGG457
      Storage Element 8:Full :VolumeTag=DGG441
      Storage Element 9:Full :VolumeTag=DGG471
      Storage Element 10:Full :VolumeTag=DGG465
#

mtx can move tapes around. Good. The basics are there. think I have proven that my tape library and mtx can successfully communicate. Time to start testing the mtx-changer script.

mtx-changer is a wrapper script. It uses grep and awk to manipulate the output of mtx to present Bacula with a nice simple interface. The use of a wrapper also means that you can customize for your needs. The use of mtx is not mandatory. You can use whatever tool you want; you'll have to customize mtx-changer or write your own wrapper.

Let's use mtx-changer to get a list of the tapes:

# /usr/local/sbin/mtx-changer /dev/pass1 list
1:DGG472
2:DGG440
4:DGG467
5:DGG469
6:DGG442
7:DGG457
8:DGG441
9:DGG471
10:DGG465
3:DGG443

That works, and shows me the same information as above. The slots aren't sorted. That isn't an issue.

What Volume is loaded?

# /usr/local/sbin/mtx-changer /dev/pass1 loaded 0 /dev/sa1 0
3

That tells me slot 3 is loaded. Hmmm, shouldn't that be the Volume? No, checking the script, it clearly says: "loaded which slot is loaded?". OK, next step, how many slots?

# /usr/local/sbin/mtx-changer /dev/pass1 slots 0 /dev/sa1 0
10

Yes, that's right. Good. Let me try unloading:

# /usr/local/sbin/mtx-changer /dev/pass1 unload 3 /dev/sa1 0
Unloading drive 0 into Storage Element 3...done

Good! This all looks very good.

btape is a Bacula utility for testing your tape. I run it on all my drives and with each new configuration.

# btape -c /usr/local/etc/bacula-sd.conf /dev/nsa1
Tape block granularity is 1024 bytes.
btape: butil.c:285 Using device: "/dev/nsa1" for writing.
30-Oct 01:05 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
30-Oct 01:05 btape JobId 0: 3302 Autochanger "loaded? drive 0", result: nothing loaded.
30-Oct 01:05 btape: Fatal Error at device.c:292 because:
dev open failed: dev.c:474 Unable to open device "DLTLIB0" (/dev/nsa1): ERR=Device not configured

30-Oct 01:05 btape JobId 0: Fatal error: butil.c:194 Cannot open "DLTLIB0" (/dev/nsa1)

At first, I thought I had a configuration error. No, this just means you don't have a tape in the drive. Let's load one up:

# /usr/local/sbin/mtx-changer /dev/pass1 load 3 /dev/sa1 0
Loading media from Storage Element 3 into drive 0...done

And we try again:

# btape -c /usr/local/etc/bacula-sd.conf /dev/nsa1
Tape block granularity is 1024 bytes.
btape: butil.c:285 Using device: "/dev/nsa1" for writing.
30-Oct 01:07 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
30-Oct 01:07 btape JobId 0: 3302 Autochanger "loaded? drive 0", result: nothing loaded.
30-Oct 01:07 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
30-Oct 01:07 btape JobId 0: 3302 Autochanger "loaded? drive 0", result: nothing loaded.
btape: btape.c:383 open device "DLTLIB0" (/dev/nsa1): OK
*

OK, now we're in btape. But I see a problem. It thinks nothing is loaded. And I think I know why. Yes, there it is:

Autochanger {
  Name            = TapeRobot
 Device          = DLTLIB0
 Changer Device  = /dev/pass1
 Changer Command = "/home/dan/rc-chio-changer %c %o %S %a %d"
}

My autochanger is using /home/dan/rc-chio-changer, not /usr/local/sbin/mtx-changer. After making the change, you need to restart bacula-sd:

# /usr/local/etc/rc.d/bacula-sd restart
Stopping bacula_sd.
Waiting for PIDS: 34563, 34563, 34563, 34563, 34563, 34563, 34563, 34563.
Starting bacula_sd.

NOTE: when running btape, you must stop bacula-sd. Otherwise, btape will be unable to access the drive.

All that waiting is waiting for the tape drive to rewind. I'm pretty sure that is a configuration issue related to my settings. Now when I try btape:

# btape -c /usr/local/etc/bacula-sd.conf /dev/nsa1
Tape block granularity is 1024 bytes.
btape: butil.c:285 Using device: "/dev/nsa1" for writing.
30-Oct 01:18 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
30-Oct 01:18 btape JobId 0: 3302 Autochanger "loaded? drive 0", result is Slot 3.
btape: btape.c:383 open device "DLTLIB0" (/dev/nsa1): OK
*

Good. Much better. Now for the test:

*test

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

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 ...

btape: btape.c:841 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:857 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:866 Rewind OK.
1000 blocks re-read correctly.
Got EOF on tape.
1000 blocks re-read correctly.
=== Test Succeeded. End Write, rewind, and re-read test ===


=== Write, rewind, and position test ===

I'm going to write 1000 records and an EOF
then write 1000 records and an EOF, then rewind,
and position to a few blocks and verify that it is correct.

This is an *essential* feature ...

btape: btape.c:953 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:969 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:978 Rewind OK.
Reposition to file:block 0:4
Block 5 re-read correctly.
Reposition to file:block 0:200
Block 201 re-read correctly.
Reposition to file:block 0:999
Block 1000 re-read correctly.
Reposition to file:block 1:0
Block 1001 re-read correctly.
Reposition to file:block 1:600
Block 1601 re-read correctly.
Reposition to file:block 1:999
Block 2000 re-read correctly.
=== Test Succeeded. End Write, rewind, and re-read test ===



=== Append files test ===

This test is essential to Bacula.

I'm going to write one record  in file 0,
                   two records in file 1,
             and three records in file 2

btape: btape.c:485 Rewound "DLTLIB0" (/dev/nsa1)
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:383 open device "DLTLIB0" (/dev/nsa1): OK
btape: btape.c:485 Rewound "DLTLIB0" (/dev/nsa1)
btape: btape.c:1107 Now moving to end of medium.
btape: btape.c:536 Moved to end of medium.
We should be in file 3. I am at file 3. This is correct!

Now the important part, I am going to attempt to append to the tape.

btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:485 Rewound "DLTLIB0" (/dev/nsa1)
Done appending, there should be no I/O errors

Doing Bacula scan of blocks:
1 block of 64448 bytes in file 1
End of File mark.
2 blocks of 64448 bytes in file 2
End of File mark.
3 blocks of 64448 bytes in file 3
End of File mark.
1 block of 64448 bytes in file 4
End of File mark.
Total files=4, blocks=7, bytes = 451,136
End scanning the tape.
We should be in file 4. I am at file 4. This is correct!

The above Bacula scan should have output identical to what follows.
Please double check it ...
=== Sample correct output ===
1 block of 64448 bytes in file 1
End of File mark.
2 blocks of 64448 bytes in file 2
End of File mark.
3 blocks of 64448 bytes in file 3
End of File mark.
1 block of 64448 bytes in file 4
End of File mark.
Total files=4, blocks=7, bytes = 451,136
=== End sample correct output ===

If the above scan output is not identical to the
sample output, you MUST correct the problem
or Bacula will not be able to write multiple Jobs to
the tape.

Skipping read backwards test because BSR turned off.


=== Forward space files test ===

This test is essential to Bacula.

I'm going to write five files then test forward spacing

btape: btape.c:485 Rewound "DLTLIB0" (/dev/nsa1)
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:1587 Wrote one record of 64412 bytes.
btape: btape.c:1589 Wrote block to device.
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:515 Wrote 1 EOF to "DLTLIB0" (/dev/nsa1)
btape: btape.c:485 Rewound "DLTLIB0" (/dev/nsa1)
btape: btape.c:1321 Now forward spacing 1 file.
We should be in file 1. I am at file 1. This is correct!
btape: btape.c:1333 Now forward spacing 2 files.
We should be in file 3. I am at file 3. This is correct!
btape: btape.c:485 Rewound "DLTLIB0" (/dev/nsa1)
btape: btape.c:1346 Now forward spacing 4 files.
We should be in file 4. I am at file 4. This is correct!

btape: btape.c:1364 Now forward spacing 1 more file.
We should be in file 5. I am at file 5. This is correct!

=== End Forward space files test ===


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):

All is well. Let's test the autochanger.

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


=== Autochanger test ===

3301 Issuing autochanger "loaded" command.
Slot 3 loaded. I am going to unload it.
3302 Issuing autochanger "unload 3 0" command.
unload status=OK 0
3303 Issuing autochanger "load 1 0" command.
3303 Autochanger "load 1 0" status is OK.
btape: btape.c:383 open device "DLTLIB0" (/dev/nsa1): OK
btape: btape.c:1251 Rewound "DLTLIB0" (/dev/nsa1)
btape: btape.c:1258 Wrote EOF to "DLTLIB0" (/dev/nsa1)

The test autochanger worked!!

*

Well, that looks pretty good.

While I was watching game 2 of the World Series, I tried out some tape manipulation. I started getting some errors that drove me batty for a while.

# /usr/local/sbin/mtx-changer /dev/pass1 load 1 /dev/sa1 0
Drive 0 Full (Storage Element 1 loaded)
# /usr/local/sbin/mtx-changer /dev/pass1 unload 0 /dev/sa1 0
Unloading drive 0 into Storage Element 0...mtx: Request Sense: Long Report=yes
mtx: Request Sense: Valid Residual=no
mtx: Request Sense: Error Code=70 (Current)
mtx: Request Sense: Sense Key=Hardware Error
mtx: Request Sense: FileMark=no
mtx: Request Sense: EOM=no
mtx: Request Sense: ILI=no
mtx: Request Sense: Additional Sense Code = 15
mtx: Request Sense: Additional Sense Qualifier = 01
mtx: Request Sense: BPV=no
mtx: Request Sense: Error in CDB=no
mtx: Request Sense: SKSV=no
MOVE MEDIUM from Element Address 240 to 0 Failed

Eh? What's this? I can load, but I cannot unload? What's going on? I tried various things, even adjusting the cables. Eventually I figured it out. I stopped bacula-sd. Then everything was fine. Just in case that helps.

I do not know if the above events are related to these messages. I suspect they are, but was unable to reproduce:

Nov  1 03:14:11 ngaio kernel: (sa1:ahc0:0:5:0): PREVENT ALLOW MEDIUM REMOVAL. CDB: 1e 0 0 0 0 0 
Nov  1 03:14:11 ngaio kernel: (sa1:ahc0:0:5:0): CAM Status: SCSI Status Error
Nov  1 03:14:11 ngaio kernel: (sa1:ahc0:0:5:0): SCSI Status: Check Condition
Nov  1 03:14:11 ngaio kernel: (sa1:ahc0:0:5:0): UNIT ATTENTION asc:28,0
Nov  1 03:14:11 ngaio kernel: (sa1:ahc0:0:5:0): Not ready to ready change, medium may have changed
Nov  1 03:14:11 ngaio kernel: (sa1:ahc0:0:5:0): Unretryable error
Nov  1 03:14:11 ngaio kernel: (sa1:ahc0:0:5:0): removing device entry
Nov  1 03:14:11 ngaio kernel: sa1 at ahc0 bus 0 target 5 lun 0
Nov  1 03:14:11 ngaio kernel: sa1: <DEC TZ89     (C) DEC 1837> Removable Sequential Access SCSI-2 device 
Nov  1 03:14:11 ngaio kernel: sa1: 20.000MB/s transfers (10.000MHz, offset 8, 16bit)

My next step is labeling the tapes in the library:

*label barcodes
Automatically selected Catalog: MyCatalog
Using Catalog "MyCatalog"
The defined Storage resources are:
     1: File
     2: FileRemote
     3: FileRemoteTLS
     4: DLT
     5: TapeLibrary
     6: DLTRemote
     7: DLTRemoteTLS
Select Storage resource (1-7): 5
Connecting to Storage daemon TapeLibrary at bacula.unixathome.org:9103 ...
3306 Issuing autochanger "slots" command.
Device "DLTLIB0" has 0 slots.
No slots in changer to scan.

Well. This is annoying. It seems to be a simple problem though. No slots. let's try it from the command line:

# /usr/local/sbin/mtx-changer /dev/pass1 slots
10

So.. mtx-changer is putting out the right stuff. What's wrong? I should have guessed. But it took me putting things into debug mode to find out:

# /usr/local/sbin/bacula-sd -d 800 -u bacula -g bacula -v -c /usr/local/etc/bacula-sd.conf -f
bacula-sd: lex.c:186-0 Open config file: /usr/local/etc/bacula-sd.conf
bacula-sd: parse_conf.c:943-0 calling handler for name
bacula-sd: parse_conf.c:943-0 calling handler for sdport
bacula-sd: parse_conf.c:943-0 calling handler for workingdirectory
bacula-sd: parse_conf.c:943-0 calling handler for piddirectory
bacula-sd: parse_conf.c:943-0 calling handler for tlsenable

[ .... lots of output omitted ... ]

[ here is where I issued the command: label barcodes storage="DigitalTapeLibrary" ]

bacula-sd: dircmd.c:232-0 Do command: autochanger
bacula-sd: dircmd.c:596-0 Try changer device DEC TZ89
bacula-sd: dircmd.c:612-0 Found changer device DEC TZ89
bacula-sd: dircmd.c:625-0 Found device DEC TZ89
bacula-sd: block.c:133-0 Returning new block=80c12a8
bacula-sd: acquire.c:651-0 JobId=0 enter attach_dcr_to_dev
bacula-sd: autochanger.c:303-0 Locking changer DEC TL800
bacula-sd: autochanger.c:678-0 omsg=/usr/local/sbin/mtx-changer /dev/pass1 slots 0 /dev/nsa1 0
bacula-sd: watchdog.c:193-0 Registered watchdog 80c1398, interval 300<NULL>
bacula-sd: autochanger.c:579-0 <stored: slots=bacula-sd: bpipe.c:220-0 Wait for 38764 opt=1
bacula-sd: bpipe.c:232-0 Got wpid=0 status=-1067026034 ERR=none
bacula-sd: bpipe.c:220-0 Wait for 38764 opt=1
bacula-sd: bpipe.c:228-0 Got break wpid=38764 status=51200 ERR=none
bacula-sd: bpipe.c:246-0 Non-zero status 200 returned from child.
bacula-sd: bpipe.c:249-0 child status=200
bacula-sd: watchdog.c:213-0 Unregistered watchdog 80c1398
bacula-sd: bpipe.c:264-0 returning stat=200,268435656
bacula-sd: autochanger.c:312-0 Unlocking changer DEC TL800
bacula-sd: acquire.c:662-0 Enter detach_dcr_from_dev
bacula-sd: message.c:420-0 Close_msg jcr=80b5418
bacula-sd: message.c:420-0 Close_msg jcr=0
bacula-sd: mem_pool.c:370-0 garbage collect memory pool

I have highlighted the key lines in bold. First, you can see the correct command being issued. Then, you can see the status being returned. That's when it clicked: permissions. I run bacula-sd as bacula:bacula, as you can see above. Now, look at the permissions pm /usr/local/sbin/mtx-changer:

$ ls -l /usr/local/sbin/mtx-changer
-rwxr-xr--  1 root  wheel  5221 Oct 30 00:52 /usr/local/sbin/mtx-changer

DOH! root:wheel. A quick chmod will fix that:

$ sudo chown root:operator /usr/local/sbin/mtx-changer
Password:
$ ls -l /usr/local/sbin/mtx-changer
-rwxr-xr--  1 root  operator  5221 Oct 30 00:52 /usr/local/sbin/mtx-changer
$

Why operator? On FreeBSD, tape drives are chown root:operator. And the bacula user is a member of the operator group. Now, let's try that command again:

*label barcodes storage="DigitalTapeLibrary"
Connecting to Storage daemon DigitalTapeLibrary at bacula.unixathome.org:9103 ...
3306 Issuing autochanger "slots" command.
Device "DEC TL800" has 0 slots.
No slots in changer to scan.
*

Hmmm, it must be something else. Let's see the bacula-sd debug output again:

bacula-sd: dircmd.c:232-0 Do command: autochanger
bacula-sd: dircmd.c:596-0 Try changer device DEC TZ89
bacula-sd: dircmd.c:612-0 Found changer device DEC TZ89
bacula-sd: dircmd.c:625-0 Found device DEC TZ89
bacula-sd: block.c:133-0 Returning new block=80c12a8
bacula-sd: acquire.c:651-0 JobId=0 enter attach_dcr_to_dev
bacula-sd: autochanger.c:303-0 Locking changer DEC TL800
bacula-sd: autochanger.c:678-0 omsg=/usr/local/sbin/mtx-changer /dev/pass1 slots 0 /dev/nsa1 0
bacula-sd: watchdog.c:193-0 Registered watchdog 80c1398, interval 300<NULL>
bacula-sd: autochanger.c:579-0 <stored: slots=touch: /var/db/bacula/mtx.log: Permission denied
bacula-sd: bpipe.c:220-0 Wait for 40757 opt=1
bacula-sd: bpipe.c:232-0 Got wpid=0 status=-1067026034 ERR=none
bacula-sd: bpipe.c:220-0 Wait for 40757 opt=1
bacula-sd: bpipe.c:228-0 Got break wpid=40757 status=0 ERR=none
bacula-sd: bpipe.c:249-0 child status=0
bacula-sd: watchdog.c:213-0 Unregistered watchdog 80c1398
bacula-sd: bpipe.c:264-0 returning stat=0,0
bacula-sd: autochanger.c:312-0 Unlocking changer DEC TL800
bacula-sd: acquire.c:662-0 Enter detach_dcr_from_dev
bacula-sd: message.c:420-0 Close_msg jcr=80b5418
bacula-sd: message.c:420-0 Close_msg jcr=0
bacula-sd: mem_pool.c:370-0 garbage collect memory pool

Still a permissions problem. This time, it's the log file, which was created root:wheel (when I was running mtx-changer from the command line). Now let's change that:

$ ls -l /var/db/bacula/mtx.log
-rw-r--r--  1 root  bacula  124204 Nov  1 20:44 /var/db/bacula/mtx.log
$ chmod g+w /var/db/bacula/mtx.log
$ ls -l /var/db/bacula/mtx.log
-rw-rw-r--  1 root  bacula  124204 Nov  1 20:44 /var/db/bacula/mtx.log
$

And trying again, with the exact same ouptut, I saw this error in the log output:

bacula-sd: dircmd.c:232-0 Do command: autochanger
bacula-sd: dircmd.c:596-0 Try changer device DEC TZ89
bacula-sd: dircmd.c:612-0 Found changer device DEC TZ89
bacula-sd: dircmd.c:625-0 Found device DEC TZ89
bacula-sd: block.c:133-0 Returning new block=80c12a8
bacula-sd: acquire.c:651-0 JobId=0 enter attach_dcr_to_dev
bacula-sd: autochanger.c:303-0 Locking changer DEC TL800
bacula-sd: autochanger.c:678-0 omsg=/usr/local/sbin/mtx-changer /dev/pass1 slots 0 /dev/nsa1 0
bacula-sd: watchdog.c:193-0 Registered watchdog 80c1398, interval 300>NULL<
bacula-sd: autochanger.c:579-0 <stored: slots=cannot open SCSI device '/dev/pass1' - Permission denied
bacula-sd: bpipe.c:220-0 Wait for 43030 opt=1
bacula-sd: bpipe.c:232-0 Got wpid=0 status=-1067026034 ERR=none
bacula-sd: bpipe.c:220-0 Wait for 43030 opt=1
bacula-sd: bpipe.c:228-0 Got break wpid=43030 status=0 ERR=none
bacula-sd: bpipe.c:249-0 child status=0
bacula-sd: watchdog.c:213-0 Unregistered watchdog 80c1398
bacula-sd: bpipe.c:264-0 returning stat=0,0
bacula-sd: autochanger.c:312-0 Unlocking changer DEC TL800
bacula-sd: acquire.c:662-0 Enter detach_dcr_from_dev
bacula-sd: message.c:420-0 Close_msg jcr=80b5418
bacula-sd: message.c:420-0 Close_msg jcr=0
bacula-sd: mem_pool.c:370-0 garbage collect memory pool

OK, now another permissions issue, this time on /dev/pass1. While looking around, I discovered I had this same issue before. Look for Permissions issues in my previous Tape Library article. Indeed, this time, the permissions were:

crw-------  1 root  operator    0, 162 Oct 30 13:01 /dev/pass1

The operator groups has no rights whatsoever. Rather than issuing a chown on a device, I elected to use the tools at hand. I altered /etc/devfs.conf to contain these lines:

own pass1 root:operator
perm pass1 0660

After restarting devfs (/etc/rc.d/devfs restart), I had these new permissions:

crw-rw----  1 root  operator    0, 162 Oct 30 13:01 /dev/pass1

Trying my command [yet] again:

*label barcodes storage="DigitalTapeLibrary"
Connecting to Storage daemon DigitalTapeLibrary at bacula.unixathome.org:9103 ...
3306 Issuing autochanger "slots" command.
Device "DEC TL800" has 10 slots.
Connecting to Storage daemon DigitalTapeLibrary at bacula.unixathome.org:9103 ...
3306 Issuing autochanger "list" command.
The following Volumes will be labeled:
Slot  Volume
==============
   1  DGG472
   2  DGG440
   3  DGG443
   4  DGG467
   5  DGG469
   6  DGG442
   7  DGG457
   8  DGG441
   9  DGG471
  10  DGG465
Do you want to label these Volumes? (yes|no):

Good. More progress. For completeness, here is the debug output:

bacula-sd: dircmd.c:232-0 Do command: autochanger
bacula-sd: dircmd.c:596-0 Try changer device DEC TZ89
bacula-sd: dircmd.c:612-0 Found changer device DEC TZ89
bacula-sd: dircmd.c:625-0 Found device DEC TZ89
bacula-sd: block.c:133-0 Returning new block=80c12a8
bacula-sd: acquire.c:651-0 JobId=0 enter attach_dcr_to_dev
bacula-sd: autochanger.c:303-0 Locking changer DEC TL800
bacula-sd: autochanger.c:678-0 omsg=/usr/local/sbin/mtx-changer /dev/pass1 list 0 /dev/nsa1 0
bacula-sd: watchdog.c:193-0 Registered watchdog 80c1398, interval 300<NULL>
bacula-sd: autochanger.c:566-0 <stored: 1:DGG472

bacula-sd: autochanger.c:566-0 <stored: 2:DGG440

bacula-sd: autochanger.c:566-0 <stored: 3:DGG443

bacula-sd: autochanger.c:566-0 <stored: 4:DGG467

bacula-sd: autochanger.c:566-0 <stored: 5:DGG469

bacula-sd: autochanger.c:566-0 <stored: 6:DGG442

bacula-sd: autochanger.c:566-0 <stored: 7:DGG457

bacula-sd: autochanger.c:566-0 <stored: 8:DGG441

bacula-sd: autochanger.c:566-0 <stored: 9:DGG471

bacula-sd: autochanger.c:566-0 <stored: 10:DGG465

bacula-sd: bpipe.c:220-0 Wait for 47124 opt=1
bacula-sd: bpipe.c:228-0 Got break wpid=47124 status=0 ERR=none
bacula-sd: bpipe.c:249-0 child status=0
bacula-sd: watchdog.c:213-0 Unregistered watchdog 80c1398
bacula-sd: bpipe.c:264-0 returning stat=0,0
bacula-sd: autochanger.c:312-0 Unlocking changer DEC TL800
bacula-sd: acquire.c:662-0 Enter detach_dcr_from_dev
bacula-sd: message.c:420-0 Close_msg jcr=80b5418
bacula-sd: message.c:420-0 Close_msg jcr=0
bacula-sd: mem_pool.c:370-0 garbage collect memory pool

Ahh, good, now, let's reply yes and let Bacula do the labelling for me.

Do you want to label these Volumes? (yes|no): yes
Defined Pools:
     1: Default
     2: FilePool
Select the Pool (1-2): 1
Connecting to Storage daemon DigitalTapeLibrary at bacula.unixathome.org:9103 ...
Sending label command for Volume "DGG472" Slot 1 ...
3301 Issuing autochanger "loaded? drive 0" command.
3302 Autochanger "loaded? drive 0", result: nothing loaded.
3304 Issuing autochanger "load slot 1, drive 0" command.
3305 Autochanger "load slot 1, drive 0", status is OK.
3000 OK label. VolBytes=64512 DVD=0 Volume="DGG472" Device="DEC TZ89" (/dev/nsa1)
Catalog record for Volume "DGG472", Slot 1  successfully created.
Sending label command for Volume "DGG440" Slot 2 ...
3307 Issuing autochanger "unload slot 1, drive 0" command.
3304 Issuing autochanger "load slot 2, drive 0" command.
3305 Autochanger "load slot 2, drive 0", status is OK.
3920 Cannot label Volume because it is already labeled: "DGG440"
Label command failed for Volume DGG440.
Sending label command for Volume "DGG443" Slot 3 ...
3307 Issuing autochanger "unload slot 2, drive 0" command.
3304 Issuing autochanger "load slot 3, drive 0" command.
3305 Autochanger "load slot 3, drive 0", status is OK.
3000 OK label. VolBytes=64512 DVD=0 Volume="DGG443" Device="DEC TZ89" (/dev/nsa1)
Catalog record for Volume "DGG443", Slot 3  successfully created.
Sending label command for Volume "DGG467" Slot 4 ...
3307 Issuing autochanger "unload slot 3, drive 0" command.
3304 Issuing autochanger "load slot 4, drive 0" command.
3305 Autochanger "load slot 4, drive 0", status is OK.
3920 Cannot label Volume because it is already labeled: "DGG467"
Label command failed for Volume DGG467.
Sending label command for Volume "DGG469" Slot 5 ...
3307 Issuing autochanger "unload slot 4, drive 0" command.
3304 Issuing autochanger "load slot 5, drive 0" command.
3305 Autochanger "load slot 5, drive 0", status is OK.
3920 Cannot label Volume because it is already labeled: "DGG469"
Label command failed for Volume DGG469.
Sending label command for Volume "DGG442" Slot 6 ...
3307 Issuing autochanger "unload slot 5, drive 0" command.
3304 Issuing autochanger "load slot 6, drive 0" command.
3305 Autochanger "load slot 6, drive 0", status is OK.
3920 Cannot label Volume because it is already labeled: "DGG442"
Label command failed for Volume DGG442.
Sending label command for Volume "DGG457" Slot 7 ...
3307 Issuing autochanger "unload slot 6, drive 0" command.
3304 Issuing autochanger "load slot 7, drive 0" command.
3305 Autochanger "load slot 7, drive 0", status is OK.
3920 Cannot label Volume because it is already labeled: "DGG457"
Label command failed for Volume DGG457.
Sending label command for Volume "DGG441" Slot 8 ...
3307 Issuing autochanger "unload slot 7, drive 0" command.
3304 Issuing autochanger "load slot 8, drive 0" command.
3305 Autochanger "load slot 8, drive 0", status is OK.
3920 Cannot label Volume because it is already labeled: "DGG441"
Label command failed for Volume DGG441.
Sending label command for Volume "DGG471" Slot 9 ...
3307 Issuing autochanger "unload slot 8, drive 0" command.
3304 Issuing autochanger "load slot 9, drive 0" command.
3305 Autochanger "load slot 9, drive 0", status is OK.
3920 Cannot label Volume because it is already labeled: "DGG471"
Label command failed for Volume DGG471.
Sending label command for Volume "DGG465" Slot 10 ...
3307 Issuing autochanger "unload slot 9, drive 0" command.
3304 Issuing autochanger "load slot 10, drive 0" command.
3305 Autochanger "load slot 10, drive 0", status is OK.
block.c:275 Volume data error at 0:0! Wanted ID: "BB02", got "". Buffer discarded.
3000 OK label. VolBytes=64512 DVD=0 Volume="DGG465" Device="DEC TZ89" (/dev/nsa1)
Catalog record for Volume "DGG465", Slot 10  successfully created.
*

That is an interesting line near the end. I'm not sure at all what that error relates to. Not to mention all the tapes which already had labels. These labels were most likely added years ago during my previous testing with this library.

I will remove those labels and start with them blank. This will be a good exercise in shell scriping and a good workout for the tape libary.

When you wish to remove the labels from a Bacula labelled tape, the process is pretty fast. It is described in the Bacula FAQ under the heading My Catalog is Full of Test Runs, How Can I Start Over?. The short answer is: write an EOF marker to the tape. All you need to do is insert the tape, and issue these commands, where /dev/sa1 is your tape drive:

mt -f /dev/sa1 rewind
mt -f /dev/sa1 weof

Since I have a tape library, I will write a short shell script to cycle through the tapes.

$ cat ~/bin/erase-tapes
#!/bin/sh

NUMSLOTS=10
FIRSTSLOT=1

CHANGER=/dev/pass4
TAPEDRIVE=/dev/sa1

MTXCHANGER=/usr/local/sbin/mtx-changer
MT=/usr/bin/mt

SLOTS=`jot ${NUMSLOTS} ${FIRSTSLOT} ${NUMSLOTS}`

# or you could this: provided by Marcin Haba 
# SLOTS=`${MTXCHANGER} ${CHANGER} list | awk -F ':' '{print $1}'` 

# unload any existing tape


for slot in ${SLOTS}
do
  echo ${slot}
  # load
  ${MTXCHANGER} ${CHANGER} load ${slot} ${TAPEDRIVE} 0

  # erase
  ${MT} -f ${TAPEDRIVE} rewind
  ${MT} -f ${TAPEDRIVE} weof
  # unload
  ${MTXCHANGER} ${CHANGER} unload ${slot} ${TAPEDRIVE} 0
done

Some details:

• NUMSLOTS=10 - this is the number of slots in my tape library.
• FIRSTSLOT=1 - the first slot to deal with
• CHANGER=/dev/pass4 - the device for the tape changer
• TAPEDRIVE=/dev/sa1 - the device for the tape drive
• MTXCHANGER=/usr/local/sbin/mtx-changer - the path to my mtx-changer script
• MT=/usr/bin/mt - the path to the mt(1) binary
• SLOTS=`jot ${NUMSLOTS} ${FIRSTSLOT} ${NUMSLOTS}` - this generates a sequence of 1..10 (for my ten slots)

The output looks like this:

[dan@ngaio:~/bin] $ sudo ~/bin/erase-tapes
Password:
1
Loading media from Storage Element 1 into drive 0...done
Unloading drive 0 into Storage Element 1...done
2
Loading media from Storage Element 2 into drive 0...done
Unloading drive 0 into Storage Element 2...done
3
Loading media from Storage Element 3 into drive 0...done
Unloading drive 0 into Storage Element 3...done
4
Loading media from Storage Element 4 into drive 0...done
Unloading drive 0 into Storage Element 4...done
5
Loading media from Storage Element 5 into drive 0...done
Unloading drive 0 into Storage Element 5...done
6
Loading media from Storage Element 6 into drive 0...done
Unloading drive 0 into Storage Element 6...done
7
Loading media from Storage Element 7 into drive 0...done
Unloading drive 0 into Storage Element 7...done
8
Loading media from Storage Element 8 into drive 0...done
Unloading drive 0 into Storage Element 8...done
9
Loading media from Storage Element 9 into drive 0...done
Unloading drive 0 into Storage Element 9...done
10
Loading media from Storage Element 10 into drive 0...done
Unloading drive 0 into Storage Element 10...done
[dan@ngaio:~/bin] $

That's it for now. This is a fairly length article. It dealt mainly with getting mtx-changer working properly and outlines some of the problems you may encounter. Hopefully, it will help you get your tape changing up and running. My next goal: get this tape library working with Bacula. That is what I will work on next. Best wishes and have fun.