I will answer to myself, because this may happen to others, and although the
answer is
simple enough, it's a problem that Bacula would never catch by design.
When using a tape changer, Bacula has to talk to two different devices to
gather
information: /dev/changer and /dev/tapename[index]
The Device{} section in bacula-sd.conf ties the changer's device index with the
actual
device. If the device number changes (as it was in my case), bacula-sd will ask
the
changer to load a tape into a slot, and the device for status. Since they could
never
match, then bacula asks to load a tape in a slot where the exact same tape is
already loaded.
In short: checking that a device is where it *should* be may be the answer to
your problem
as well.
On 6/26/09 6:24 PM, Nico Halpern wrote:
> Some additional info: btape also does not know what to do with the next
> tape:
>
> Wrote blk_block=1590000, dev_blk_num=2930 VolBytes=416,808,697,856
> rate=60990.4 KB/s
> Wrote blk_block=1595000, dev_blk_num=302 VolBytes=418,119,417,856
> rate=61003.7 KB/s
> Wrote blk_block=1600000, dev_blk_num=1488 VolBytes=419,430,137,856
> rate=60999.1 KB/s
> 16:07:09 Flush block, write EOF
> Wrote blk_block=1605000, dev_blk_num=1186 VolBytes=420,740,857,856
> rate=60985.8 KB/s
> 26-Jun 16:07 btape JobId 0: End of Volume "TestVolume1" at 453:0 on
> device "TSDrive0" (/dev/IBMtape1n). Write of 262144 bytes got -1.
> 26-Jun 16:07 btape JobId 0: Error: Backspace record at EOT failed.
> ERR=Input/output error
> btape: btape.c:2349 Last block at: 452:3813 this_dev_block_num=3814
> btape: btape.c:2383 End of tape 453:-1. VolumeCapacity=421,429,772,288.
> Write rate = 60970.7 KB/s
> 26-Jun 16:07 btape JobId 0: End of medium on Volume "TestVolume1"
> Bytes=421,429,772,288 Blocks=1,607,627 at 26-Jun-2009 16:07.
> 26-Jun 16:07 btape JobId 0: 3307 Issuing autochanger "unload slot 1,
> drive 0" command.
> 26-Jun 16:08 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0"
> command.
> 26-Jun 16:09 btape JobId 0: 3302 Autochanger "loaded? drive 0", result:
> nothing loaded.
> 26-Jun 16:09 btape JobId 0: 3304 Issuing autochanger "load slot 2, drive
> 0" command.
> 26-Jun 16:10 btape JobId 0: 3305 Autochanger "load slot 2, drive 0",
> status is OK.
> 26-Jun 16:10 btape: Fatal Error at dev.c:1663 because:
> dev.c:1662 Attempt to WEOF on non-appendable Volume
> Wrote Volume label for volume "TestVolume2".
> 26-Jun 16:10 btape JobId 0: Wrote label to prelabeled Volume
> "TestVolume2" on device "TSDrive0" (/dev/IBMtape1n)
> 26-Jun 16:10 btape JobId 0: New volume "TestVolume2" mounted on device
> "TSDrive0" (/dev/IBMtape1n) at 26-Jun-2009 16:10.
> Done writing 0 records ...
> Wrote End of Session label.
> Wrote state file last_block_num1=3813 last_block_num2=11
>
>
> 16:10:22 Done filling tapes at 0:13. Now beginning re-read of first tape ...
> 26-Jun 16:10 btape JobId 0: 3307 Issuing autochanger "unload slot 2,
> drive 0" command.
> 26-Jun 16:11 btape JobId 0: 3304 Issuing autochanger "load slot 1, drive
> 0" command.
> 26-Jun 16:12 btape JobId 0: 3305 Autochanger "load slot 1, drive 0",
> status is OK.
> 26-Jun 16:12 btape JobId 0: 3307 Issuing autochanger "unload slot 1,
> drive 0" command.
> 26-Jun 16:13 btape JobId 0: Warning: acquire.c:260 Wrong Volume mounted
> on device "TSDrive0" (/dev/IBMtape1n): Wanted TestVolume1 have TestVolume2
> 26-Jun 16:13 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0"
> command.
> 26-Jun 16:13 btape JobId 0: 3302 Autochanger "loaded? drive 0", result:
> nothing loaded.
> 26-Jun 16:13 btape JobId 0: 3304 Issuing autochanger "load slot 1, drive
> 0" command.
> 26-Jun 16:14 btape JobId 0: 3305 Autochanger "load slot 1, drive 0",
> status is OK.
> 26-Jun 16:14 btape JobId 0: 3307 Issuing autochanger "unload slot 1,
> drive 0" command.
> 26-Jun 16:15 btape JobId 0: Warning: acquire.c:260 Wrong Volume mounted
> on device "TSDrive0" (/dev/IBMtape1n): Wanted TestVolume1 have TestVolume2
> dev.c:1662 Attempt to WEOF on non-appendable Volume
> Mount Volume "TestVolume1" on device "TSDrive0" (/dev/IBMtape1n) and
> press return when ready:
>
>
> On 6/26/09 12:07 PM, Nico Halpern wrote:
>> Greetings,
>>
>> I have been banging my head against the wall for a few days now. I am
>> hoping someone can point me in the right direction.
>>
>> For about 3 or 4 days now, Bacula refuses to mount tapes and use them.
>> If I start a job manually, the tape will mount, and the backup will not
>> start. The interesting part is that bacula-dir is blocked waiting for
>> the tape it just mounted!. "Status jobs" returns:
>>
>> Device "TSDrive0" (/dev/IBMtape1n) is mounted with:
>> Volume: A00014L3
>> Pool: Default
>> Media type: LTO3
>> Device is BLOCKED waiting for mount of volume "A00004L3",
>> Pool: Default
>> Media type: LTO3
>> Slot 22 is loaded in drive 0.
>> Total Bytes Read=65,536 Blocks Read=1 Bytes/block=65,536
>> Positioned at File=0 Block=0
>>
>> mtx tells me:
>> Data Transfer Element 0:Full (Storage Element 22 Loaded):VolumeTag =
>> A00004L3
>>
>>
>> If I somehow umount/remount the tape, and get it to start correctly,
>> bacula will write to the end of the tape, and repeat the process for the
>> next tape:
>>
>> auto-mount correct tape, block waiting for tape to be mounted. This
>> obviously happens with any tape status (Purged, Recycled, Append). In
>> fact if the tape has been pruned/purged, bacula will mount the tape,
>> recycle it, and then block.
>>
>> Any ideas of what could have gone wrong here?
>>
>> Thank you!
>>
>>
>> Details:
>> Drive: IBMTS3310
>> Host: CentOS 5.2 x86_64
>> Version: v2.4.4
>> lin_tape: 1.19
>>
>
>
--
Nico Halpern
UNIX Systems Administrator
Wireless Generation
p: +1-212-796-2200 x5163 m: +1-646-300-1944
j: nhalp...@im.wgen.net aim: nhwgen
------------------------------------------------------------------------------
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
