Dear Kern,
Dear Group
I am using bacula 1.36.2-2 on Debian Sarge with HP StorageWorks DAT72
internal tape drive. Everything is working fine, except when one backup
job spans over two tapes. In this situation Bacula destroys second
cartridge. The cartridge is not usable any more even with tar. When I
insert destroyed cartridge in the cartridge door the tape LED is
flashing and after a while it switches off. When I insert good cartridge
the tape LED is flashing and after a while it stays on.
I also tested my tape drive with btape with multiple tape option (It
works fine with simple single tape option.) and bacula again destroyed
cartridges (in this example both). I am attaching log file of this test
(btape-err.txt).
Can anybody help me? I was reading manual and searching the mailing
lists without success.
Thanks in advance,
Matjaz Slibar
ViaLactea:~# btape -c /etc/bacula/bacula-sd.conf /dev/nst0
Tape block granularity is 1024 bytes.
btape: butil.c:258 Using device: "/dev/nst0" for writing.
btape: btape.c:335 open_dev /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:786 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:802 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:811 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:898 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:914 Wrote 1000 blocks of 64412 bytes.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:923 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:435 Rewound /dev/nst0
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:335 open_dev /dev/nst0 OK
btape: btape.c:435 Rewound /dev/nst0
btape: btape.c:1052 Now moving to end of medium.
btape: btape.c:482 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:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:435 Rewound /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:435 Rewound /dev/nst0
btape: btape.c:665 Wrote first record of 64412 bytes.
btape: btape.c:676 Wrote second record of 64412 bytes.
btape: btape.c:687 Wrote third record of 64412 bytes.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:703 Backspaced over EOF OK.
btape: btape.c:708 Backspace record OK.
btape: btape.c:726
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:435 Rewound /dev/nst0
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:1505 Wrote one record of 64412 bytes.
btape: btape.c:1507 Wrote block to device.
btape: btape.c:465 Wrote 1 EOF to /dev/nst0
btape: btape.c:435 Rewound /dev/nst0
btape: btape.c:1266 Now forward spacing 1 file.
We should be in file 1. I am at file 1. This is correct!
btape: btape.c:1278 Now forward spacing 2 files.
We should be in file 3. I am at file 3. This is correct!
btape: btape.c:435 Rewound /dev/nst0
btape: btape.c:1291 Now forward spacing 4 files.
We should be in file 4. I am at file 4. This is correct!
btape: btape.c:1309 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 ===
*
btape: btape.c:2511 is an illegal command
*
btape: btape.c:2511 is an illegal command
*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.
10-Nov 21:56 btape: Labeled new Volume "TestVolume1" on device /dev/nst0.
10-Nov 21:56 btape: Wrote label to prelabeled Volume "TestVolume1" on device "/d
ev/nst0"
Wrote Start of Session label.
Begin writing Bacula records to first tape ...
Wrote blk_block=5000, dev_blk_num=5000 VolBytes=322,495,473 rate=2580.0 KB/s
Wrote blk_block=10000, dev_blk_num=10000 VolBytes=645,055,425 rate=2643.7 KB/s
Wrote blk_block=15000, dev_blk_num=15000 VolBytes=967,615,369 rate=2665.6 KB/s
Flush block, write EOF
Wrote blk_block=20000, dev_blk_num=5000 VolBytes=1,290,175,313 rate=2665.7 KB/s
Wrote blk_block=25000, dev_blk_num=10000 VolBytes=1,612,735,265 rate=2674.5 KB/s
Wrote blk_block=30000, dev_blk_num=15000 VolBytes=1,935,295,209 rate=2680.5 KB/s
Flush block, write EOF
Wrote blk_block=35000, dev_blk_num=5000 VolBytes=2,257,855,161 rate=2647.0 KB/s
Wrote blk_block=40000, dev_blk_num=10000 VolBytes=2,580,415,105 rate=2657.5 KB/s
Wrote blk_block=45000, dev_blk_num=15000 VolBytes=2,902,975,049 rate=2663.3 KB/s
Flush block, write EOF
Wrote blk_block=50000, dev_blk_num=5000 VolBytes=3,225,535,001 rate=2663.5 KB/s
Wrote blk_block=55000, dev_blk_num=10000 VolBytes=3,548,094,945 rate=2667.7 KB/s
Wrote blk_block=60000, dev_blk_num=15000 VolBytes=3,870,654,889 rate=2671.3 KB/s
Flush block, write EOF
Wrote blk_block=65000, dev_blk_num=5000 VolBytes=4,193,214,841 rate=2670.8 KB/s
Wrote blk_block=70000, dev_blk_num=10000 VolBytes=4,515,774,785 rate=2657.9 KB/s
Wrote blk_block=75000, dev_blk_num=15000 VolBytes=4,838,334,737 rate=2661.4 KB/s
Flush block, write EOF
Wrote blk_block=80000, dev_blk_num=5000 VolBytes=5,160,894,681 rate=2661.6 KB/s
Wrote blk_block=85000, dev_blk_num=10000 VolBytes=5,483,454,625 rate=2664.5 KB/s
Wrote blk_block=90000, dev_blk_num=15000 VolBytes=5,806,014,577 rate=2667.0 KB/s
Flush block, write EOF
Wrote blk_block=95000, dev_blk_num=5000 VolBytes=6,128,574,521 rate=2668.1 KB/s
Wrote blk_block=100000, dev_blk_num=10000 VolBytes=6,451,134,473 rate=2670.2
KB/s
Wrote blk_block=105000, dev_blk_num=15000 VolBytes=6,773,694,417 rate=2672.1
KB/s
Flush block, write EOF
Wrote blk_block=110000, dev_blk_num=5000 VolBytes=7,096,254,361 rate=2661.8 KB/s
Wrote blk_block=115000, dev_blk_num=10000 VolBytes=7,418,814,313 rate=2663.8
KB/s
Wrote blk_block=120000, dev_blk_num=15000 VolBytes=7,741,374,257 rate=2665.8
KB/s
Flush block, write EOF
Wrote blk_block=125000, dev_blk_num=5000 VolBytes=8,063,934,209 rate=2665.8 KB/s
Wrote blk_block=130000, dev_blk_num=10000 VolBytes=8,386,494,153 rate=2667.5
KB/s
Wrote blk_block=135000, dev_blk_num=15000 VolBytes=8,709,054,097 rate=2669.0
KB/s
Flush block, write EOF
Wrote blk_block=140000, dev_blk_num=5000 VolBytes=9,031,614,049 rate=2668.9 KB/s
Wrote blk_block=145000, dev_blk_num=10000 VolBytes=9,354,173,993 rate=2662.7
KB/s
Wrote blk_block=150000, dev_blk_num=15000 VolBytes=9,676,733,937 rate=2664.3
KB/s
Flush block, write EOF
Wrote blk_block=155000, dev_blk_num=5000 VolBytes=9,999,293,889 rate=2664.3 KB/s
Wrote blk_block=160000, dev_blk_num=10000 VolBytes=10,321,853,833 rate=2665.8
KB/s
Wrote blk_block=165000, dev_blk_num=15000 VolBytes=10,644,413,785 rate=2667.1
KB/s
Flush block, write EOF
Wrote blk_block=170000, dev_blk_num=5000 VolBytes=10,966,973,729 rate=2667.7
KB/s
Wrote blk_block=175000, dev_blk_num=10000 VolBytes=11,289,533,673 rate=2668.9
KB/s
Wrote blk_block=180000, dev_blk_num=15000 VolBytes=11,612,093,625 rate=2670.1
KB/s
Flush block, write EOF
Wrote blk_block=185000, dev_blk_num=5000 VolBytes=11,934,653,569 rate=2664.0
KB/s
Wrote blk_block=190000, dev_blk_num=10000 VolBytes=12,257,213,521 rate=2665.2
KB/s
Wrote blk_block=195000, dev_blk_num=15000 VolBytes=12,579,773,465 rate=2666.3
KB/s
Flush block, write EOF
Wrote blk_block=200000, dev_blk_num=5000 VolBytes=12,902,333,409 rate=2666.3
KB/s
Wrote blk_block=205000, dev_blk_num=10000 VolBytes=13,224,893,361 rate=2667.4
KB/s
Wrote blk_block=210000, dev_blk_num=15000 VolBytes=13,547,453,305 rate=2668.4
KB/s
Flush block, write EOF
Wrote blk_block=215000, dev_blk_num=5000 VolBytes=13,870,013,249 rate=2668.3
KB/s
Wrote blk_block=220000, dev_blk_num=10000 VolBytes=14,192,573,201 rate=2664.3
KB/s
Wrote blk_block=225000, dev_blk_num=15000 VolBytes=14,515,133,145 rate=2665.3
KB/s
Flush block, write EOF
Wrote blk_block=230000, dev_blk_num=5000 VolBytes=14,837,693,097 rate=2665.3
KB/s
Wrote blk_block=235000, dev_blk_num=10000 VolBytes=15,160,253,041 rate=2666.2
KB/s
Wrote blk_block=240000, dev_blk_num=15000 VolBytes=15,482,812,985 rate=2667.2
KB/s
Flush block, write EOF
Wrote blk_block=245000, dev_blk_num=5000 VolBytes=15,805,372,937 rate=2667.6
KB/s
Wrote blk_block=250000, dev_blk_num=10000 VolBytes=16,127,932,881 rate=2668.4
KB/s
Wrote blk_block=255000, dev_blk_num=15000 VolBytes=16,450,492,833 rate=2669.2
KB/s
Flush block, write EOF
Wrote blk_block=260000, dev_blk_num=5000 VolBytes=16,773,052,777 rate=2664.9
KB/s
Wrote blk_block=265000, dev_blk_num=10000 VolBytes=17,095,612,721 rate=2665.8
KB/s
Wrote blk_block=270000, dev_blk_num=15000 VolBytes=17,418,172,673 rate=2666.6
KB/s
Flush block, write EOF
Wrote blk_block=275000, dev_blk_num=5000 VolBytes=17,740,732,617 rate=2666.6
KB/s
Wrote blk_block=280000, dev_blk_num=10000 VolBytes=18,063,292,561 rate=2667.3
KB/s
Wrote blk_block=285000, dev_blk_num=15000 VolBytes=18,385,852,513 rate=2668.1
KB/s
Flush block, write EOF
Wrote blk_block=290000, dev_blk_num=5000 VolBytes=18,708,412,457 rate=2668.1
KB/s
Wrote blk_block=295000, dev_blk_num=10000 VolBytes=19,030,972,409 rate=2665.0
KB/s
Wrote blk_block=300000, dev_blk_num=15000 VolBytes=19,353,532,353 rate=2665.8
KB/s
Flush block, write EOF
Wrote blk_block=305000, dev_blk_num=5000 VolBytes=19,676,092,297 rate=2665.8
KB/s
Wrote blk_block=310000, dev_blk_num=10000 VolBytes=19,998,652,249 rate=2666.5
KB/s
Wrote blk_block=315000, dev_blk_num=15000 VolBytes=20,321,212,193 rate=2667.2
KB/s
Flush block, write EOF
Wrote blk_block=320000, dev_blk_num=5000 VolBytes=20,643,772,145 rate=2667.5
KB/s
Wrote blk_block=325000, dev_blk_num=10000 VolBytes=20,966,332,089 rate=2668.2
KB/s
Wrote blk_block=330000, dev_blk_num=15000 VolBytes=21,288,892,033 rate=2668.8
KB/s
Flush block, write EOF
Wrote blk_block=335000, dev_blk_num=5000 VolBytes=21,611,451,985 rate=2665.4
KB/s
Wrote blk_block=340000, dev_blk_num=10000 VolBytes=21,934,011,929 rate=2666.1
KB/s
Wrote blk_block=345000, dev_blk_num=15000 VolBytes=22,256,571,881 rate=2666.7
KB/s
Flush block, write EOF
Wrote blk_block=350000, dev_blk_num=5000 VolBytes=22,579,131,825 rate=2666.7
KB/s
Wrote blk_block=355000, dev_blk_num=10000 VolBytes=22,901,691,769 rate=2667.3
KB/s
Wrote blk_block=360000, dev_blk_num=15000 VolBytes=23,224,251,721 rate=2667.9
KB/s
Flush block, write EOF
Wrote blk_block=365000, dev_blk_num=5000 VolBytes=23,546,811,665 rate=2667.9
KB/s
Wrote blk_block=370000, dev_blk_num=10000 VolBytes=23,869,371,609 rate=2665.5
KB/s
Wrote blk_block=375000, dev_blk_num=15000 VolBytes=24,191,931,561 rate=2666.1
KB/s
Flush block, write EOF
Wrote blk_block=380000, dev_blk_num=5000 VolBytes=24,514,491,505 rate=2666.4
KB/s
Wrote blk_block=385000, dev_blk_num=10000 VolBytes=24,837,051,457 rate=2666.9
KB/s
Wrote blk_block=390000, dev_blk_num=15000 VolBytes=25,159,611,401 rate=2667.5
KB/s
Flush block, write EOF
Wrote blk_block=395000, dev_blk_num=5000 VolBytes=25,482,171,345 rate=2667.5
KB/s
Wrote blk_block=400000, dev_blk_num=10000 VolBytes=25,804,731,297 rate=2668.0
KB/s
Wrote blk_block=405000, dev_blk_num=15000 VolBytes=26,127,291,241 rate=2668.5
KB/s
Flush block, write EOF
Wrote blk_block=410000, dev_blk_num=5000 VolBytes=26,449,851,193 rate=2665.8
KB/s
Wrote blk_block=415000, dev_blk_num=10000 VolBytes=26,772,411,137 rate=2666.3
KB/s
Wrote blk_block=420000, dev_blk_num=15000 VolBytes=27,094,971,081 rate=2666.8
KB/s
Flush block, write EOF
Wrote blk_block=425000, dev_blk_num=5000 VolBytes=27,417,531,033 rate=2666.8
KB/s
Wrote blk_block=430000, dev_blk_num=10000 VolBytes=27,740,090,977 rate=2667.3
KB/s
Wrote blk_block=435000, dev_blk_num=15000 VolBytes=28,062,650,921 rate=2667.8
KB/s
Flush block, write EOF
Wrote blk_block=440000, dev_blk_num=5000 VolBytes=28,385,210,873 rate=2668.0
KB/s
Wrote blk_block=445000, dev_blk_num=10000 VolBytes=28,707,770,817 rate=2665.8
KB/s
Wrote blk_block=450000, dev_blk_num=15000 VolBytes=29,030,330,769 rate=2666.3
KB/s
Flush block, write EOF
Wrote blk_block=455000, dev_blk_num=5000 VolBytes=29,352,890,713 rate=2666.5
KB/s
Wrote blk_block=460000, dev_blk_num=10000 VolBytes=29,675,450,657 rate=2667.0
KB/s
Wrote blk_block=465000, dev_blk_num=15000 VolBytes=29,998,010,609 rate=2667.4
KB/s
Flush block, write EOF
Wrote blk_block=470000, dev_blk_num=5000 VolBytes=30,320,570,553 rate=2667.4
KB/s
Wrote blk_block=475000, dev_blk_num=10000 VolBytes=30,643,130,505 rate=2667.9
KB/s
Wrote blk_block=480000, dev_blk_num=15000 VolBytes=30,965,690,449 rate=2668.3
KB/s
Flush block, write EOF
Wrote blk_block=485000, dev_blk_num=5000 VolBytes=31,288,250,393 rate=2666.0
KB/s
Wrote blk_block=490000, dev_blk_num=10000 VolBytes=31,610,810,345 rate=2666.5
KB/s
11-Nov 01:15 btape: End of Volume "TestVolume1" at 32:13153 on device
/dev/nst0. Write of 64512 bytes got -1.
11-Nov 01:15 btape: Re-read of last block succeeded.
btape: btape.c:2236 Last block at: 32:13152 this_dev_block_num=13153
btape: btape.c:2270 End of tape 32:0. VolumeCapacity=31,814,281,161. Write rate
= 2665.0 KB/s
11-Nov 01:15 btape: End of medium on Volume "TestVolume1" Bytes=31,814,281,161
Blocks=493,153 at 11-Nov-2005 01:15.
Mount blank Volume on device /dev/nst0 and press return when ready:
Wrote Volume label for volume "TestVolume2".
dev.c:769 ioctl MTOFFL error on /dev/nst0. ERR=No medium found.
Mount second Volume on device /dev/nst0 and press return when ready:
11-Nov 01:59 btape: Fatal Error at dev.c:295 because:
dev.c:289 stored: unable to open device /dev/nst0: ERR=Input/output error
11-Nov 01:59 btape: btape Fatal error: device.c:317 Unable to open device
/dev/nst0. ERR=dev.c:289 stored: unable to open device /dev/nst0:
ERR=Input/output error
btape: btape.c:2277 Cannot fixup device error. dev.c:289 stored: unable to open
device /dev/nst0: ERR=Input/output error
btape: btape.c:1888 Not OK
11-Nov 01:59 btape: btape Fatal error: Attempt to write on read-only Volume.
11-Nov 01:59 btape: btape Fatal error: Error writing Session label to
TestVolume2: Input/output error
btape: btape.c:1911 Error writting end session label. ERR=dev.c:289 stored:
unable to open device /dev/nst0: ERR=Input/output error
11-Nov 01:59 btape: btape Fatal error: Attempt to write on read-only Volume.
Set ok=false after write_block_to_device.
Wrote End of Session label.
Wrote state file last_block_num1=13152 last_block_num2=13152
Done filling tapes at 0:0. Now beginning re-read of first tape ...
11-Nov 01:59 btape: Fatal Error at dev.c:747 because:
dev.c:746 Bad call to offline_dev. Archive not open
Mount first tape. Press enter when ready:
acquire.c:140 Job 0 canceled.
*
