Hi,
I'm seeing a rather surprising message during the fill test in btape about
writing an EOF on a tape failing: "dev.c:1662 Attempt to WEOF on
non-appendable Volume"
This message is being generated during the fill test of btape,
specifically after the tape has been changed by the mtx-changer script.
The message in full is as follows:
21-Jan 23:15 btape JobId 0: End of medium on Volume "TestVolume1"
Bytes=106,505,634,816 Blocks=1,650,943 at 21-Jan-2009 23:1$
21-Jan 23:15 btape JobId 0: 3307 Issuing autochanger "unload slot 1, drive 0"
command.
21-Jan 23:16 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
21-Jan 23:16 btape JobId 0: 3302 Autochanger "loaded? drive 0", result: nothing
loaded.
21-Jan 23:16 btape JobId 0: 3304 Issuing autochanger "load slot 2, drive 0"
command.
21-Jan 23:17 btape JobId 0: 3305 Autochanger "load slot 2, drive 0", status is
OK.
21-Jan 23:17 btape: Fatal Error at dev.c:1663 because:
dev.c:1662 Attempt to WEOF on non-appendable Volume
Wrote Volume label for volume "TestVolume2".
21-Jan 23:17 btape JobId 0: Wrote label to prelabeled Volume "TestVolume2" on
device "Drive-1" (/dev/nst0)
21-Jan 23:17 btape JobId 0: New volume "TestVolume2" mounted on device
"Drive-1" (/dev/nst0) at 21-Jan-2009 23:17.
Done writing 0 records ...
The drive in question is a Seagate Ultrium LTO-1 drive, the autochanger is
a StorageTek L40 as can be seen by the lsscsi output.
[root@amanda ~]# lsscsi
[0:0:0:0] tape SEAGATE ULTRIUM06242-XXX 1536 /dev/st0
[0:0:2:0] mediumx STK L40 0215 -
[1:0:1:0] tape SEAGATE ULTRIUM06242-XXX 1536 /dev/st1
[root@amanda ~]#
The message about appending data failing is a bit surprising however as
the normal btape test output succeeds in appending data.
Any suggestions what went wrong? Or it the fatal error generated wrongly?
regards,
andreas
For completeness, the output of the btape test, the btape auto and the
btape fill runs are included:
###
### btape test run
###
[root@amanda ~]# btape -c /etc/bacula/bacula-sd.conf /dev/nst0
Tape block granularity is 1024 bytes.
btape: butil.c:285 Using device: "/dev/nst0" for writing.
21-Jan 20:56 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
21-Jan 20:57 btape JobId 0: 3302 Autochanger "loaded? drive 0", result is Slot
2.
btape: btape.c:372 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:831 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:847 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:856 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:943 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:959 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:968 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:475 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:372 open device "Drive-1" (/dev/nst0): OK
btape: btape.c:475 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1097 Now moving to end of medium.
btape: btape.c:526 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:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:475 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:475 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:710 Wrote first record of 64412 bytes.
btape: btape.c:721 Wrote second record of 64412 bytes.
btape: btape.c:732 Wrote third record of 64412 bytes.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:748 Backspaced over EOF OK.
btape: btape.c:753 Backspace record OK.
btape: btape.c:771
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:475 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1577 Wrote one record of 64412 bytes.
btape: btape.c:1579 Wrote block to device.
btape: btape.c:505 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:475 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1311 Now forward spacing 1 file.
We should be in file 1. I am at file 1. This is correct!
btape: btape.c:1323 Now forward spacing 2 files.
We should be in file 3. I am at file 3. This is correct!
btape: btape.c:475 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1336 Now forward spacing 4 files.
We should be in file 4. I am at file 4. This is correct!
btape: btape.c:1354 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): n
* quit
[root@amanda ~]# /usr/libexec/bacula/mtx-changer /dev/sg1 unload 2 /dev/nst0 0
Unloading Data Transfer Element into Storage Element 2...done
[root@amanda ~]# /usr/libexec/bacula/mtx-changer /dev/sg1 load 1 /dev/nst0 0
###
### btape autochanger test
###
[root@amanda ~]# btape -c /etc/bacula/bacula-sd.conf /dev/nst0
Tape block granularity is 1024 bytes.
btape: butil.c:285 Using device: "/dev/nst0" for writing.
21-Jan 21:07 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
21-Jan 21:07 btape JobId 0: 3302 Autochanger "loaded? drive 0", result is Slot
1.
btape: btape.c:372 open device "Drive-1" (/dev/nst0): OK
* auto
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:372 open device "Drive-1" (/dev/nst0): OK
btape: btape.c:1241 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1248 Wrote EOF to "Drive-1" (/dev/nst0)
The test autochanger worked!!
* quit
###
### btape fill test
###
[root@amanda ~]# btape -c /etc/bacula/bacula-sd.conf /dev/nst0
Tape block granularity is 1024 bytes.
btape: butil.c:285 Using device: "/dev/nst0" for writing.
21-Jan 21:20 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
f21-Jan 21:20 btape JobId 0: 3302 Autochanger "loaded? drive 0", result is Slot
1.
btape: btape.c:372 open device "Drive-1" (/dev/nst0): OK
*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.
21:21:06 Begin writing Bacula records to first tape ...
Wrote blk_block=5000, dev_blk_num=4999 VolBytes=322,495,488 rate=18970.3 KB/s
###
### [... lots of writes ...]
###
Wrote blk_block=1650000, dev_blk_num=2500 VolBytes=106,444,735,488 rate=15487.4
KB/s
21-Jan 23:15 btape JobId 0: End of Volume "TestVolume1" at 155:3444 on device
"Drive-1" (/dev/nst0). Write of 64512 bytes got -1.
21-Jan 23:15 btape JobId 0: Re-read of last block succeeded.
btape: btape.c:2349 Last block at: 155:3443 this_dev_block_num=3444
btape: btape.c:2383 End of tape 155:0. VolumeCapacity=106,505,634,816. Write
rate = 15471.5 KB/s
21-Jan 23:15 btape JobId 0: End of medium on Volume "TestVolume1"
Bytes=106,505,634,816 Blocks=1,650,943 at 21-Jan-2009 23:15.
21-Jan 23:15 btape JobId 0: 3307 Issuing autochanger "unload slot 1, drive 0"
command.
21-Jan 23:16 btape JobId 0: 3301 Issuing autochanger "loaded? drive 0" command.
21-Jan 23:16 btape JobId 0: 3302 Autochanger "loaded? drive 0", result: nothing
loaded.
21-Jan 23:16 btape JobId 0: 3304 Issuing autochanger "load slot 2, drive 0"
command.
21-Jan 23:17 btape JobId 0: 3305 Autochanger "load slot 2, drive 0", status is
OK.
21-Jan 23:17 btape: Fatal Error at dev.c:1663 because:
dev.c:1662 Attempt to WEOF on non-appendable Volume
Wrote Volume label for volume "TestVolume2".
21-Jan 23:17 btape JobId 0: Wrote label to prelabeled Volume "TestVolume2" on
device "Drive-1" (/dev/nst0)
21-Jan 23:17 btape JobId 0: New volume "TestVolume2" mounted on device
"Drive-1" (/dev/nst0) at 21-Jan-2009 23:17.
Done writing 0 records ...
Wrote End of Session label.
Wrote state file last_block_num1=3443 last_block_num2=11
23:17:49 Done filling tapes at 0:13. Now beginning re-read of first tape...
21-Jan 23:17 btape JobId 0: 3307 Issuing autochanger "unload slot 2, drive 0"
command.
21-Jan 23:18 btape JobId 0: 3304 Issuing autochanger "load slot 1, drive 0"
command.
21-Jan 23:19 btape JobId 0: 3305 Autochanger "load slot 1, drive 0", status is
OK.
21-Jan 23:19 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 155:3443
Reading block 3443.
The last block of the first tape matches.
21-Jan 23:21 btape JobId 0: 3307 Issuing autochanger "unload slot 1, drive 0"
command.
21-Jan 23:22 btape JobId 0: 3304 Issuing autochanger "load slot 2, drive 0"
command.
21-Jan 23:22 btape JobId 0: 3305 Autochanger "load slot 2, drive 0", status is
OK.
21-Jan 23:23 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.
*
------------------------------------------------------------------------------
This SF.net email is sponsored by:
SourcForge Community
SourceForge wants to tell your story.
http://p.sf.net/sfu/sf-spreadtheword
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users
|
