John,
I changed the mtx-changer.conf file to reflect timeouts. I tried using
and offline sleep and a load sleep both of these produced the same
error.
I also install mt-st to see if that made any difference.
I ran btape with debugging set to 200 to see if that output gave any
extra information.
If I let the tests run all the way through it looks like they complete
successfully but I would prefer if there were no "fatal errors".
Device {
Name = Drive-1 #
Drive Index = 0
Media Type = LTO-4
Device Type = Tape
Archive Device = /dev/nst0
AutomaticMount = yes; # when device opened, read it
AlwaysOpen = yes;
RemovableMedia = yes;
RandomAccess = no;
AutoChanger = yes
LabelMedia = yes; # lets Bacula label unlabeled
media
# Requires Mount = no;
# Maximum Open Wait = 300 # Default value
# Maximum Rewind Wait = 300 # Default value
# Maximum Changer Wait = 120 # default is 120 secs
# Maximum Job Spool Size = 2G # default is unlimited
# Spool Directory = "/export/shared/spool"
Label Type = Bacula
# Check Labels = yes
# LabelMedia = no;
# Hardware End of Medium = No # defaut is Yes
# Fast Forward Space File = No # This line required if above is set
to "No"
# BSF at EOM = no # Default is no
# Two EOF = no
# Volume Poll Interval = 300 # Poll the drive to seek the status
}
Autochanger {
Name = Autochanger
Device = Drive-1
Changer Command = "/root/bacula/etc/mtx-changer %c %o %S %a %d"
Changer Device = /dev/sg3
}
r...@archive:~/bacula/etc# ../bin/btape -c bacula-sd.conf -d 200
/dev/nst0
Tape block granularity is 1024 bytes.
btape: stored_conf.c:701-0 Inserting director res: localhost-mon
btape: jcr.c:834-0 jid=0 leave set_old_job_status=btape: butil.c:285
Using device: "/dev/nst0" for writing.
btape: dev.c:269-0 init_dev: tape=1 dev_name=/dev/nst0
btape: device.c:271-0 start open_output_device()
btape: device.c:290-0 Opening device.
btape: dev.c:345-0 open dev: type=2 dev_name="Drive-1" (/dev/nst0) vol=
mode=OPEN_READ_ONLY
btape: dev.c:394-0 Open dev: device is tape
btape: autochanger.c:303-0 Locking changer Autochanger
05-May 15:15 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0"
command.
btape: autochanger.c:273-0 Run program=/root/bacula/etc/mtx-changer
/dev/sg3 loaded 0 /dev/nst0 0
btape: autochanger.c:275-0 run_prog: /root/bacula/etc/mtx-changer
/dev/sg3 loaded 0 /dev/nst0 0 stat=0 result=3
05-May 15:15 btape JobId 0: 3302 Autochanger "loaded? drive 0", result
is Slot 3.
btape: autochanger.c:312-0 Unlocking changer Autochanger
btape: dev.c:409-0 Try open "Drive-1" (/dev/nst0) mode=OPEN_READ_ONLY
btape: dev.c:431-0 Rewind after open
btape: dev.c:2483-0 In set_os_device_parameters
btape: dev.c:2489-0 Set block size to zero
btape: dev.c:2505-0 MTSETDRVBUFFER
btape: dev.c:483-0 open dev: tape 3 opened
btape: dev.c:358-0 preserve=0x0 fd=3
btape: device.c:296-0 open dev "Drive-1" (/dev/nst0) OK
btape: btape.c:377-0 Opening device
btape: dev.c:336-0 Close fd for mode change.
btape: dev.c:345-0 open dev: type=2 dev_name="Drive-1" (/dev/nst0) vol=
mode=OPEN_READ_WRITE
btape: dev.c:394-0 Open dev: device is tape
btape: dev.c:409-0 Try open "Drive-1" (/dev/nst0) mode=OPEN_READ_WRITE
btape: dev.c:431-0 Rewind after open
btape: dev.c:2483-0 In set_os_device_parameters
btape: dev.c:2489-0 Set block size to zero
btape: dev.c:2505-0 MTSETDRVBUFFER
btape: dev.c:483-0 open dev: tape 3 opened
btape: dev.c:358-0 preserve=0x0 fd=3
btape: btape.c:383 open device "Drive-1" (/dev/nst0): OK
btape: btape.c:311-0 Do tape commands
*fill
This command simulates Bacula writing to a tape.
It requires either one or two blank tapes, which it
will label and write.
If you have an autochanger configured, it will use
the tapes that are in slots 1 and 2, otherwise, you will
be prompted to insert the tapes when necessary.
It will print a status approximately
every 322 MB, and write an EOF every 3.2 GB. If you have
selected the simple test option, after writing the first tape
it will rewind it and re-read the last block written.
If you have selected the multiple tape test, when the first tape
fills, it will ask for a second, and after writing a few more
blocks, it will stop. Then it will begin re-reading the
two tapes.
This may take a long time -- hours! ...
Do you want to run the simplified test (s) with one tape
or the complete multiple tape (m) test: (s/m) s
Simple test (single tape) selected.
btape: btape.c:1876-0 Begin append device="Drive-1" (/dev/nst0)
btape: btape.c:1877-0 MaxVolSize=0
btape: btape.c:2709-0 Enter dir_ask_sysop_to_create_appendable_volume
btape: autochanger.c:133-0 autoload: slot=1 InChgr=1 Vol=TestVolume1
btape: autochanger.c:303-0 Locking changer Autochanger
05-May 15:16 btape JobId 0: 3307 Issuing autochanger "unload slot 3,
drive 0" command.
btape: dev.c:1902-0 close_dev "Drive-1" (/dev/nst0)
btape: dev.c:1892-0 Clear volhdr vol=
btape: autochanger.c:362-0 Run program=/root/bacula/etc/mtx-changer
/dev/sg3 unload 3 /dev/nst0 0
btape: autochanger.c:312-0 Unlocking changer Autochanger
btape: vol_mgr.c:603-0 No vol on dev "Drive-1" (/dev/nst0)
btape: autochanger.c:303-0 Locking changer Autochanger
btape: autochanger.c:190-0 Doing changer load slot 1 "Drive-1"
(/dev/nst0)
05-May 15:16 btape JobId 0: 3304 Issuing autochanger "load slot 1, drive
0" command.
btape: dev.c:1902-0 close_dev "Drive-1" (/dev/nst0)
btape: dev.c:1909-0 device "Drive-1" (/dev/nst0) already closed vol=
btape: autochanger.c:197-0 Run program=/root/bacula/etc/mtx-changer
/dev/sg3 load 1 /dev/nst0 0
05-May 15:17 btape JobId 0: 3305 Autochanger "load slot 1, drive 0",
status is OK.
btape: autochanger.c:202-0 load slot 1, drive 0, status is OK.
btape: autochanger.c:215-0 load slot 1 status=0
btape: autochanger.c:312-0 Unlocking changer Autochanger
btape: autochanger.c:221-0 After changer, status=0
btape: device.c:271-0 start open_output_device()
btape: device.c:290-0 Opening device.
btape: dev.c:345-0 open dev: type=2 dev_name="Drive-1" (/dev/nst0)
vol=TestVolume1 mode=OPEN_READ_ONLY
btape: dev.c:394-0 Open dev: device is tape
btape: dev.c:409-0 Try open "Drive-1" (/dev/nst0) mode=OPEN_READ_ONLY
btape: dev.c:431-0 Rewind after open
btape: dev.c:2483-0 In set_os_device_parameters
btape: dev.c:2489-0 Set block size to zero
btape: dev.c:2505-0 MTSETDRVBUFFER
btape: dev.c:483-0 open dev: tape 3 opened
btape: dev.c:358-0 preserve=0x0 fd=3
btape: device.c:296-0 open dev "Drive-1" (/dev/nst0) OK
btape: dev.c:1690-0 === weof_dev="Drive-1" (/dev/nst0)
05-May 15:17 btape: Fatal Error at dev.c:1705 because:
dev.c:1704 Attempt to WEOF on non-appendable Volume
btape: label.c:304-0 write_volume_label()
btape: label.c:325-0 New VolName=TestVolume1
btape: dev.c:336-0 Close fd for mode change.
btape: dev.c:345-0 open dev: type=2 dev_name="Drive-1" (/dev/nst0)
vol=TestVolume1 mode=OPEN_READ_WRITE
btape: dev.c:394-0 Open dev: device is tape
btape: dev.c:409-0 Try open "Drive-1" (/dev/nst0) mode=OPEN_READ_WRITE
btape: dev.c:431-0 Rewind after open
btape: dev.c:2483-0 In set_os_device_parameters
btape: dev.c:2489-0 Set block size to zero
btape: dev.c:2505-0 MTSETDRVBUFFER
btape: dev.c:483-0 open dev: tape 3 opened
btape: dev.c:358-0 preserve=0x0 fd=3
btape: label.c:334-0 Label type=0
btape: label.c:605-0 Start create_volume_label()
btape: dev.c:1892-0 Clear volhdr vol=
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : TestVolume1
PrevVolName :
VolFile : 0
LabelType : PRE_LABEL
LabelSize : 0
PoolName : Default
MediaType : LTO-4
PoolType : Backup
HostName : archive.mynlv.com
Date label written: 05-May-2009 15:17
btape: label.c:593-0 Created Vol label rec: FI=PRE_LABEL len=167
btape: label.c:369-0 Wrote label of 167 bytes to "Drive-1" (/dev/nst0)
btape: label.c:372-0 Call write_block_to_dev()
btape: label.c:387-0 Wrote block to device
btape: dev.c:1690-0 === weof_dev="Drive-1" (/dev/nst0)
Volume Label:
Id : Bacula 1.0 immortal
VerNo : 11
VolName : TestVolume1
PrevVolName :
VolFile : 1
LabelType : PRE_LABEL
LabelSize : 0
PoolName : Default
MediaType : LTO-4
PoolType : Backup
HostName : archive.mynlv.com
Date label written: 05-May-2009 15:17
btape: label.c:397-0 Call reserve_volume
btape: vol_mgr.c:350-0 enter reserve_volume=TestVolume1 drive="Drive-1"
(/dev/nst0)
btape: vol_mgr.c:269-0 new Vol=TestVolume1 at 68c628 dev="Drive-1"
(/dev/nst0)
btape: vol_mgr.c:457-0 === set in_use. vol=TestVolume1 dev="Drive-1"
(/dev/nst0)
btape: vol_mgr.c:212-0 List end new volume: TestVolume1 in_use=1 on
device "Drive-1" (/dev/nst0)
Wrote Volume label for volume "TestVolume1".
btape: btape.c:1891-0 just before acquire_device
btape: acquire.c:346-0 acquire_append device is tape
btape: btape.c:2667-0 Enter dir_get_volume_info
btape: acquire.c:365-0 device already in append.
btape: btape.c:1898-0 Just after acquire_device_for_append
btape: label.c:707-0 session_label record=683ae0
btape: label.c:752-0 Write sesson_label record JobId=0 FI=SOS_LABEL
SessId=1 Strm=0 len=144 remainder=0
btape: label.c:756-0 Leave write_session_label Block=0d File=1d
Wrote Start of Session label.
15:17:26 Begin writing Bacula records to tape ...
-----Original Message-----
From: John Drescher [mailto:dresche...@gmail.com]
Sent: Thursday, April 30, 2009 1:39 PM
To: Hayden Katzenellenbogen; bacula-users
Subject: Re: [Bacula-users] Btape fill test fatal error WEOF
> Wrote blk_block=13025000, dev_blk_num=1000 VolBytes=840,268,735,488
> rate=68908.4 KB/s
> Wrote blk_block=13030000, dev_blk_num=6000 VolBytes=840,591,295,488
> rate=68906.6 KB/s
> Wrote blk_block=13035000, dev_blk_num=11000 VolBytes=840,913,855,488
> rate=68916.1 KB/s
> Wrote blk_block=13040000, dev_blk_num=500 VolBytes=841,236,415,488
> rate=68919.9 KB/s
> Wrote blk_block=13045000, dev_blk_num=5500 VolBytes=841,558,975,488
> rate=68906.8 KB/s
> Wrote blk_block=13050000, dev_blk_num=10500 VolBytes=841,881,535,488
> rate=68916.3 KB/s
> Wrote blk_block=13055000, dev_blk_num=15500 VolBytes=842,204,095,488
> rate=68925.8 KB/s
> 17:57:33 Flush block, write EOF
> Wrote blk_block=13060000, dev_blk_num=4000 VolBytes=842,526,655,488
> rate=68890.2 KB/s
> 29-Apr 17:57 btape JobId 0: End of Volume "TestVolume1" at 1225:6262
on
> device "Drive-1" (/dev/nst0). Write of 64512 bytes got -1.
> 29-Apr 17:57 btape JobId 0: Re-read of last block succeeded.
> btape: btape.c:2360 Last block at: 1225:6261 this_dev_block_num=6262
> btape: btape.c:2394 End of tape 1225:0.
VolumeCapacity=842,672,581,632.
> Write rate = 68873.9 KB/s
> 29-Apr 17:57 btape JobId 0: End of medium on Volume "TestVolume1"
> Bytes=842,672,581,632 Blocks=13,062,261 at 29-Apr-2009 17:57.
> 29-Apr 17:57 btape JobId 0: 3307 Issuing autochanger "unload slot 1,
> drive 0" command.
> 29-Apr 17:58 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0"
> command.
> 29-Apr 17:58 btape JobId 0: 3302 Autochanger "loaded? drive 0",
result:
> nothing loaded.
> 29-Apr 17:58 btape JobId 0: 3304 Issuing autochanger "load slot 2,
drive
> 0" command.
> 29-Apr 17:59 btape JobId 0: 3305 Autochanger "load slot 2, drive 0",
> status is OK.
> 29-Apr 17:59 btape: Fatal Error at dev.c:1705 because:
> dev.c:1704 Attempt to WEOF on non-appendable Volume
My guess is bacula is trying to write to the tape before it is done
loading. You may need to modify the mtx-changer to ensure the script
does not finish before the tape is fully loaded in the drive.
> Wrote Volume label for volume "TestVolume2".
> 29-Apr 17:59 btape JobId 0: Wrote label to prelabeled Volume
> "TestVolume2" on device "Drive-1" (/dev/nst0)
> 29-Apr 17:59 btape JobId 0: New volume "TestVolume2" mounted on device
> "Drive-1" (/dev/nst0) at 29-Apr-2009 17:59.
> Done writing 0 records ...
> Wrote End of Session label.
> Wrote state file last_block_num1=6261 last_block_num2=11
>
John
------------------------------------------------------------------------------
The NEW KODAK i700 Series Scanners deliver under ANY circumstances! Your
production scanning environment may not be a perfect world - but thanks to
Kodak, there's a perfect scanner to get the job done! With the NEW KODAK i700
Series Scanner you'll get full speed at 300 dpi even with all image
processing features enabled. http://p.sf.net/sfu/kodak-com
_______________________________________________
Bacula-users mailing list
Bacula-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/bacula-users
