[Bacula-users] Btape fill test fatal error WEOF

Hello List members,

I am new to Bacula and this mailing list. I have tried to do as much due
diligence as possible before crafting this e-mail.

Tape Drive is a Dell TL-2000 with a single drive FC-Channel Interface.
Using LTO-4 tapes
Qlogic QLE220 HBA adapter

Server is running Ubuntu Server x64 8.04 LTS.

I first installed Bacula using the Ubuntu binaries this installed
version 2.2.8. I ran through all the recommended tests using btape. The
btape test ran flawlessly but the fill test over multiple tapes had the
WEOF errors. I decided to upgrade to the most current version.

I downloaded Bacula 3.0.0 (I will upgrade to 3.0.1 later today). I
compiled and installed it with the following options

CFLAGS="-g -Wall" ./configure \
  --sbindir=$HOME/bacula/bin \
  --sysconfdir=$HOME/bacula/etc \
  --disable-ipv6 \
  --enable-largefile \
  --enable-smartalloc \
  --with-sqlite3=$HOME/depkgs/sqlite3 \
  --with-working-dir=$HOME/bacula/working \
  --with-pid-dir=$HOME/bacula/bin/run \
  --with-subsys-dir=$HOME/bacula/bin/run/subsys \
  --enable-conio \
  --with-smtp-host=smtp.nextlevelinternet.com \
  --with-job-email=server-admins AT nextlevelinternet DOT com \
  --with-dump-email=server-admins AT nextlevelinternet DOT com \
  --without-openssl

exit 0

I used the depkgs for SQLite3 and MTX.

What I would like to know is the  "Attempt to WEOF on non-appendable
Volume" error really a fatal error. The tests seem to have completed
successfully. I got this error in both 2.2.8 and now 3.0.0. I have run
the test multiple times over the passed week.

I have even performed the following on each tape before trying the test
again

   mt -f /dev/st0 rewind
   mt -f /dev/st0 weof


Below are the outputs from the btape test and btape fill tests I ran.

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

root@archive:~/bacula/etc# ../bin/btape -c bacula-sd.conf /dev/nst0
Tape block granularity is 1024 bytes.
btape: butil.c:285 Using device: "/dev/nst0" for writing.
29-Apr 14:28 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0"
command.
29-Apr 14:28 btape JobId 0: 3302 Autochanger "loaded? drive 0", result
is Slot 1.
btape: btape.c:383 open device "Drive-1" (/dev/nst0): OK
*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:842 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:858 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:867 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:954 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:970 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:979 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:486 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:383 open device "Drive-1" (/dev/nst0): OK
btape: btape.c:486 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1108 Now moving to end of medium.
btape: btape.c:537 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:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:486 Rewound "Drive-1" (/dev/nst0)
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.


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

I'm going to write three records and an EOF
then backup over the EOF and re-read the last record.
Bacula does this after writing the last block on the
tape to verify that the block was written correctly.

This is not an *essential* feature ...

btape: btape.c:486 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:721 Wrote first record of 64412 bytes.
btape: btape.c:732 Wrote second record of 64412 bytes.
btape: btape.c:743 Wrote third record of 64412 bytes.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:759 Backspaced over EOF OK.
btape: btape.c:764 Backspace record OK.
btape: btape.c:782 
Block re-read correct. Test succeeded!
=== End Write, backup, and re-read test ===



=== Forward space files test ===

This test is essential to Bacula.

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

btape: btape.c:486 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1588 Wrote one record of 64412 bytes.
btape: btape.c:1590 Wrote block to device.
btape: btape.c:516 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:486 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1322 Now forward spacing 1 file.
We should be in file 1. I am at file 1. This is correct!
btape: btape.c:1334 Now forward spacing 2 files.
We should be in file 3. I am at file 3. This is correct!
btape: btape.c:486 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1347 Now forward spacing 4 files.
We should be in file 4. I am at file 4. This is correct!

btape: btape.c:1365 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): y


=== Autochanger test ===

3301 Issuing autochanger "loaded" command.
Slot 1 loaded. I am going to unload it.
3302 Issuing autochanger "unload 1 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 "Drive-1" (/dev/nst0): OK
btape: btape.c:1252 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1259 Wrote EOF to "Drive-1" (/dev/nst0)

The test autochanger worked!!

*quit

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


*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) m
Multiple tape test selected.
Wrote Volume label for volume "TestVolume1".
Wrote Start of Session label.
14:33:51 Begin writing Bacula records to first tape ...
Wrote blk_block=5000, dev_blk_num=4999 VolBytes=322,495,488 rate=80623.9
KB/s
Wrote blk_block=10000, dev_blk_num=9999 VolBytes=645,055,488
rate=92150.8 KB/s
Wrote blk_block=15000, dev_blk_num=14999 VolBytes=967,615,488
rate=96761.5 KB/s
Wrote blk_block=20000, dev_blk_num=4499 VolBytes=1,290,175,488
rate=86011.7 KB/s
Wrote blk_block=25000, dev_blk_num=9499 VolBytes=1,612,735,488
rate=76796.9 KB/s
Wrote blk_block=30000, dev_blk_num=14499 VolBytes=1,935,295,488
rate=80637.3 KB/s
14:34:18 Flush block, write EOF

...snip....


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


17:59:11 Done filling tapes at 0:13. Now beginning re-read of first tape
...
29-Apr 17:59 btape JobId 0: 3307 Issuing autochanger "unload slot 2,
drive 0" command.
29-Apr 17:59 btape JobId 0: 3304 Issuing autochanger "load slot 1, drive
0" command.
29-Apr 18:00 btape JobId 0: 3305 Autochanger "load slot 1, drive 0",
status is OK.
29-Apr 18:00 btape JobId 0: Ready to read from volume "TestVolume1" on
device "Drive-1" (/dev/nst0).
Rewinding.
Reading the first 10000 records from 0:0.
10000 records read now at 1:5084
Reposition from 1:5084 to 1225:6261
Reading block 6261.

The last block of the first tape matches.

29-Apr 18:01 btape JobId 0: 3307 Issuing autochanger "unload slot 1,
drive 0" command.
29-Apr 18:01 btape JobId 0: 3304 Issuing autochanger "load slot 2, drive
0" command.
29-Apr 18:02 btape JobId 0: 3305 Autochanger "load slot 2, drive 0",
status is OK.
29-Apr 18:02 btape JobId 0: Ready to read from volume "TestVolume2" on
device "Drive-1" (/dev/nst0).
Reposition from 0:0 to 0:1
Reading block 1.

The first block on the second tape matches.

Reposition from 0:2 to 0:11
Reading block 11.

The last block on the second tape matches. Test succeeded.

*

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

Any help would be greatly appreciated.

Thanks
H


------------------------------------------------------------------------------
Register Now & Save for Velocity, the Web Performance & Operations 
Conference from O'Reilly Media. Velocity features a full day of 
expert-led, hands-on workshops and two days of sessions from industry 
leaders in dedicated Performance & Operations tracks. Use code vel09scf 
and Save an extra 15% before 5/3. http://p.sf.net/sfu/velocityconf
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users