Hi all,
I'm hoping someone can help point me in the right direction to get the
btape multivolume fill test to work under bacula-7.4.4. I've got an HP
1/8 G2 Autoloader with an LTO-6 SAS drive running under gentoo linux
with kernel 4.4.39 and the linux st drivers. The firmware on both the
drive and the autoloader are relatively recent.
I'm able to successfully run the batpe test command on a single tape
with the invocation 'btape -c /etc/bacula/bacula-sd.conf /dev/nst0' as
is outlined in the docs and all the autochanger tests function happily
at the end of the normal test cycle and correctly swap tapes between
slots perfectly (output included below).
I'm running into a somewhat odd issue where I'm not able to get the
btape multivolume fill test to complete successfully under 7.4.4, but I
am able to use the exact same bacula-sd.conf file under a build of
5.2.13 which succeeds (in fact, on the same boot with the same device
files and same default st configs).
I've included a copy of the output from the failed multivolume fill run
under 7.4.4 and the successful multivolume fill run under 5.2.13. I've
also included the pertinent sections from the bacula-sd.conf that I've
been using for both runs. Additionally, I've included the output from
sginfo in case there's something in the way the st kernel driver is
configured by default that's incorrect and I'm just not seeing it.
I'm relatively new to bacula and linux tape management in general, so
I'm hoping I've just done something silly and a sage old hand can point
out my obvious mistake.
I did note that there was another user that posted about this exact
problem several months ago on a very similar IBM LTO-6 configuration,
but there wasn't a posted resolution. Here's the relevant thread:
http://www.backupcentral.com/forum/19/271519?sid=e1ed71be5d24670fea367324f317339f
.
The only thing that I see obviously different from the two versions'
btape runs is that 5.2.13 writes the last block at block_num 26144 for
the first tape and 7.4.4 writes its last block at block_num 26147 for
the first tape, which to me signals a possible change in end of tape
management between the two versions (again...I'm not steeped in the
bacula code, but it seems weird to have two different finishing points
on the same hardware and configuration...especially when the successful
one is a couple of blocks shorter).
Any help would be greatly appreciated. Thank You in advance!
~Caribe
-------------------------------------------begin
bacula-sd.conf--------------------------------------------------------------
#
# An HP 1/8 autochanger device with one drive
#
Autochanger {
Name = AutochangerHP
Device = Drive-1
Changer Command = "/usr/libexec/bacula/mtx-changer %c %o %S %a %d"
Changer Device = /dev/sg3
}
Device {
Name = Drive-1 #
Media Type = LTO-6
Archive Device = /dev/nst0
AutomaticMount = yes; # when device opened, read it
AlwaysOpen = yes;
RemovableMedia = yes;
RandomAccess = no;
AutoChanger = yes
Maximum File Size = 5GB
#
# Enable the Alert command only if you have the mtx package loaded
# Note, apparently on some systems, tapeinfo resets the SCSI controller
# thus if you turn this on, make sure it does not reset your SCSI
# controller. I have never had any problems, and smartctl does
# not seem to cause such problems.
#
# Alert Command = "sh -c 'tapeinfo -f %c |grep TapeAlert|cat'"
# If you have smartctl, enable this, it has more info than tapeinfo
Alert Command = "sh -c 'smartctl -H -l error %c'"
}
-------------------------------------------end
bacula-sd.conf----------------------------------------------------------------
--------------------------------------------begin successful 5.2.13
btape output----------------------------------------
Wrote block=38770000, file,blk=126,17624 VolBytes=2,501,130,175,488
rate=151.5 MB/s
Wrote block=38775000, file,blk=126,22624 VolBytes=2,501,452,735,488
rate=151.5 MB/s
25-Jan 22:31 btape JobId 0: End of Volume "TestVolume1" at 126:26144 on
device "Drive-1" (/dev/nst0). Write of 64512 bytes got -1.
25-Jan 22:31 btape JobId 0: Re-read of last block succeeded.
btape: btape.c:2714-0 Last block at: 126:26143 this_dev_block_num=26144
btape: btape.c:2749-0 End of tape 126:0. Volume Bytes=2,501,679,817,728.
Write rate = 151.5 MB/s
25-Jan 22:31 btape JobId 0: End of medium on Volume "TestVolume1"
Bytes=2,501,679,817,728 Blocks=38,778,519 at 25-Jan-2017 22:31.
25-Jan 22:31 btape JobId 0: 3307 Issuing autochanger "unload slot 1,
drive 0" command.
25-Jan 22:32 btape JobId 0: 3304 Issuing autochanger "load slot 2, drive
0" command.
25-Jan 22:33 btape JobId 0: 3305 Autochanger "load slot 2, drive 0",
status is OK.
Wrote Volume label for volume "TestVolume2".
25-Jan 22:33 btape JobId 0: Wrote label to prelabeled Volume
"TestVolume2" on device "Drive-1" (/dev/nst0)
25-Jan 22:33 btape JobId 0: New volume "TestVolume2" mounted on device
"Drive-1" (/dev/nst0) at 25-Jan-2017 22:33.
btape: btape.c:2320-0 Wrote 1000 blocks on second tape. Done.
Done writing 0 records ...
Wrote End of Session label.
btape: btape.c:2389-0 Wrote state file last_block_num1=26143
last_block_num2=1001
btape: btape.c:2407-0
22:33:21 Done filling tapes at 0:1003. Now beginning re-read of first
tape ...
btape: btape.c:2485-0 Enter do_unfill
25-Jan 22:33 btape JobId 0: 3307 Issuing autochanger "unload slot 2,
drive 0" command.
25-Jan 22:34 btape JobId 0: 3304 Issuing autochanger "load slot 1, drive
0" command.
25-Jan 22:35 btape JobId 0: 3305 Autochanger "load slot 1, drive 0",
status is OK.
25-Jan 22:35 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 126:26143
Reading block 26143.
The last block of the first tape matches.
25-Jan 22:36 btape JobId 0: 3307 Issuing autochanger "unload slot 1,
drive 0" command.
25-Jan 22:37 btape JobId 0: 3304 Issuing autochanger "load slot 2, drive
0" command.
25-Jan 22:38 btape JobId 0: 3305 Autochanger "load slot 2, drive 0",
status is OK.
25-Jan 22:38 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:1001
Reading block 1001.
The last block on the second tape matches. Test succeeded.
--------------------------------------------end successful 5.2.13 btape
output------------------------------------------
--------------------------------------------begin failed 7.4.4 btape
output----------------------------------------
Wrote block=38770000, file,blk=501,17999 VolBytes=2,501,130,175,488
rate=127.2 MB/s
Wrote block=38775000, file,blk=501,22999 VolBytes=2,501,452,735,488
rate=127.2 MB/s
26-Jan 17:38 btape JobId 0: End of Volume "TestVolume1" at 501:26148 on
device "Drive-1" (/dev/nst0). Write of 64512 bytes got -1.
26-Jan 17:38 btape JobId 0: Re-read of last block succeeded.
btape: btape.c:2712-0 Last block at: 501:26147 this_dev_block_num=26148
btape: btape.c:2747-0 End of tape 501:0. Volume Bytes=2,501,655,883,776.
Write rate = 127.1 MB/s
26-Jan 17:38 btape JobId 0: End of medium on Volume "TestVolume1"
Bytes=2,501,655,883,776 Blocks=38,778,148 at 26-Jan-2017 17:38.
26-Jan 17:38 btape JobId 0: 3307 Issuing autochanger "unload slot 1,
drive 0" command for vol TestVolume1.
26-Jan 17:39 btape JobId 0: 3304 Issuing autochanger "load slot 2, drive
0" command for vol TestVolume2.
26-Jan 17:40 btape JobId 0: 3305 Autochanger "load slot 2, drive 0",
status is OK for vol TestVolume2.
Wrote Volume label for volume "TestVolume2".
26-Jan 17:40 btape JobId 0: Wrote label to prelabeled Volume
"TestVolume2" on tape device "Drive-1" (/dev/nst0)
26-Jan 17:40 btape JobId 0: New volume "TestVolume2" mounted on device
"Drive-1" (/dev/nst0) at 26-Jan-2017 17:40.
btape: btape.c:2315-0 Wrote 1000 blocks on second tape. Done.
Done writing 0 records ...
Wrote End of Session label.
btape: btape.c:2384-0 Wrote state file last_block_num1=26147
last_block_num2=1001
btape: btape.c:2402-0
17:40:25 Done filling tapes at 0:1003. Now beginning re-read of first
tape ...
btape: btape.c:2480-0 Enter do_unfill
26-Jan 17:40 btape JobId 0: 3307 Issuing autochanger "unload slot 2,
drive 0" command for vol TestVolume1.
26-Jan 17:41 btape JobId 0: 3304 Issuing autochanger "load slot 1, drive
0" command for vol TestVolume1.
26-Jan 17:42 btape JobId 0: 3305 Autochanger "load slot 1, drive 0",
status is OK for vol TestVolume1.
26-Jan 17:42 btape JobId 0: Ready to read from volume "TestVolume1" on
tape 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 501:26147
Reading block 26147.
The blocks differ at byte 0
!!!! The last block written and the block
that was read back differ. The test FAILED !!!!
This must be corrected before you use Bacula
to write multi-tape Volumes.!!!!
26-Jan 17:43 btape JobId 0: 3307 Issuing autochanger "unload slot 1,
drive 0" command for vol TestVolume2.
26-Jan 17:44 btape JobId 0: 3304 Issuing autochanger "load slot 2, drive
0" command for vol TestVolume2.
26-Jan 17:44 btape JobId 0: 3305 Autochanger "load slot 2, drive 0",
status is OK for vol TestVolume2.
26-Jan 17:45 btape JobId 0: Ready to read from volume "TestVolume2" on
tape 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:1001
Reading block 1001.
The blocks differ at byte 0
!!!! The last block written and the block
that was read back differ. The test FAILED !!!!
This must be corrected before you use Bacula
to write multi-tape Volumes.!!!!
btape: btape.c:2407-0 do_unfill failed.
--------------------------------------------end failed 7.4.4 btape
output------------------------------------------
--------------------------------------------begin sginfo
output------------------------------------------
backup ~ # sginfo -a /dev/nst0
INQUIRY response (cmd: 0x12)
----------------------------
Device Type 1
Vendor: HP
Product: Ultrium 6-SCSI
Revision level: 35JW
Serial Number 'G0-F15h'
Read-Write Error Recovery mode page (0x1)
-----------------------------------------
AWRE 0
ARRE 0
TB 0
RC 0
EER 1
PER 0
DTE 0
DCR 0
Read Retry Count 21
Correction Span 0
Head Offset Count 0
Data Strobe Offset Count 0
Write Retry Count 10
Recovery Time Limit (ms) 0
Disconnect-Reconnect mode page (0x2)
------------------------------------
Buffer full ratio 0
Buffer empty ratio 0
Bus Inactivity Limit (SAS: 100us) 1
Disconnect Time Limit 0
Connect Time Limit (SAS: 100us) 0
Maximum Burst Size 0
EMDP 0
Fair Arbitration (fcp:faa,fab,fac) 0
DIMM 0
DTDC 0
First Burst Size 0
Control mode page (0xa)
-----------------------
TST 1
TMF_ONLY 0
D_SENSE 0
GLTSD 0
RLEC 0
Queue Algorithm Modifier 0
QErr 0
DQue [obsolete] 0
TAS 0
RAC 0
UA_INTLCK_CTRL 0
SWP 0
RAERP [obs.] 0
UAAERP [obs.] 0
EAERP [obs.] 0
ATO 0
TAS 1
AUTOLOAD MODE 2
Ready AER Holdoff Period [obs.] 0
Busy Timeout Period 0
Extended self-test completion time 0
Data compression mode page (0xf)
----------------------------------------------------
DCE 1
DCC 1
DDE 1
RED 0
Compression algorithm 1
Decompression algorithm 1
Device configuration mode page (0x10)
----------------------------------------------------
CAF 0
Active format 0
Active partition 0
Write object cbuffer full ratio 0
Read object cbuffer full ratio 0
Wire delay time 300
OBR 0
LOIS 1
RSMK 0
AVC 1
SOCF 0
ROBO 0
REW 0
Gap size 0
EOD defined 0
EEG 1
SEW 0
SWP 0
BAML 0
BAM 0
Object cbuffer size at early warning0
Select data compression algorithm 1
ASOCWP 0
PERSWO 0
PRMWP 0
Medium partition(1) mode page (0x11)
----------------------------------------------------
Maximum additional partitions 3
Additional partitions defined 0
FDP 0
SDP 0
IDP 1
PSUM 3
POFM 1
CLEAR 0
ADDP 0
Medium format recognition 3
Partition units 9
Partition size 2620
Partition size 0
Partition size 0
Partition size 0
SAS logical unit mode page (0x18)
----------------------------------------------------
Transport Layer Retries 1
SAS SSP port control mode page (0x19)
-------------------------------------
Ready LED meaning 0
I_T Nexus Loss time 2000
Initiator response time-out 1000
Power Condition mode page (0x1a)
--------------------------------
Idle 1
Standby 0
Idle Condition counter (100ms) 0
Standby Condition counter (100ms) 0
Informational Exceptions mode page (0x1c)
-----------------------------------------
PERF 0
EBF 0
EWASC 0
DEXCPT 1
TEST 0
EBACKERR 0
LOGERR 0
MRIE 3
Interval Timer 0
Report Count 1
mode page: 0x1d [Medium configuration]
---------------
0x02 0x00
0x03 0x00
0x04 0x01
0x05 0x02
0x06 0x00
0x07 0x00
0x08 0x00
0x09 0x00
0x0a 0x00
0x0b 0x00
0x0c 0x00
0x0d 0x00
0x0e 0x00
0x0f 0x00
0x10 0x00
0x11 0x00
0x12 0x00
0x13 0x00
0x14 0x00
0x15 0x00
0x16 0x00
0x17 0x00
0x18 0x00
0x19 0x00
0x1a 0x00
0x1b 0x00
0x1c 0x00
0x1d 0x00
0x1e 0x00
0x1f 0x00
mode page: 0x3b
---------------
0x02 0x01
0x03 0x00
0x04 0x00
0x05 0x00
0x06 0x48
0x07 0x55
0x08 0x4a
0x09 0x35
0x0a 0x34
0x0b 0x31
0x0c 0x34
0x0d 0x54
0x0e 0x47
0x0f 0x48
mode page: 0x3c
---------------
0x02 0x07
0x03 0x00
0x04 0x00
0x05 0x06
0x06 0x00
0x07 0x14
0x08 0x00
0x09 0x07
0x0a 0x8a
0x0b 0x6f
0x0c 0x01
0x0d 0x06
0x0e 0x00
0x0f 0x00
0x10 0x58
0x11 0x89
0x12 0xe0
0x13 0xdd
0x14 0x10
0x15 0x06
0x16 0x00
0x17 0x0b
0x18 0x2b
0x19 0x19
0x1a 0x00
0x1b 0x00
0x1c 0x18
0x1d 0x06
0x1e 0x00
0x1f 0x00
0x20 0x00
0x21 0x08
0x22 0x52
0x23 0x8f
mode page: 0x3d
---------------
0x02 0x00
0x03 0x00
--------------------------------------------end sginfo
output------------------------------------------
--------------------------------------------begin successful btape test
output--------------------
backup ~ # btape -c /etc/bacula/bacula-sd.conf /dev/nst0
Tape block granularity is 1024 bytes.
btape: butil.c:291-0 Using device: "/dev/nst0" for writing.
btape: btape.c:471-0 open device "Drive-1" (/dev/nst0): OK
*test
=== Write, rewind, and re-read test ===
I'm going to write 10000 records and an EOF
then write 10000 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:1154-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1170-0 Wrote 10000 blocks of 64412 bytes.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1212-0 Rewind OK.
10000 blocks re-read correctly.
Got EOF on tape.
10000 blocks re-read correctly.
=== Test Succeeded. End Write, rewind, and re-read test ===
btape: btape.c:1279-0 Block position test
btape: btape.c:1291-0 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:9999
Block 10000 re-read correctly.
Reposition to file:block 1:0
Block 10001 re-read correctly.
Reposition to file:block 1:600
Block 10601 re-read correctly.
Reposition to file:block 1:9999
Block 20000 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:576-0 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:471-0 open device "Drive-1" (/dev/nst0): OK
btape: btape.c:576-0 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1422-0 Now moving to end of medium.
btape: btape.c:627-0 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:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:576-0 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:576-0 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:813-0 Wrote first record of 64412 bytes.
btape: btape.c:824-0 Wrote second record of 64412 bytes.
btape: btape.c:835-0 Wrote third record of 64412 bytes.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:851-0 Backspaced over EOF OK.
btape: btape.c:856-0 Backspace record OK.
btape: btape.c:873-0
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:576-0 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:1909-0 Wrote one record of 64412 bytes.
btape: btape.c:1911-0 Wrote block to device.
btape: btape.c:606-0 Wrote 1 EOF to "Drive-1" (/dev/nst0)
btape: btape.c:576-0 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1636-0 Now forward spacing 1 file.
We should be in file 1. I am at file 1. This is correct!
btape: btape.c:1648-0 Now forward spacing 2 files.
We should be in file 3. I am at file 3. This is correct!
btape: btape.c:576-0 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1661-0 Now forward spacing 4 files.
We should be in file 4. I am at file 4. This is correct!
btape: btape.c:1679-0 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 2 loaded. I am going to unload it.
3302 Issuing autochanger "unload 2 0" command.
unload status=OK 0
3303 Issuing autochanger "load 1 0" command.
3303 Autochanger "load 1 0" status is OK.
btape: btape.c:471-0 open device "Drive-1" (/dev/nst0): OK
btape: btape.c:1566-0 Rewound "Drive-1" (/dev/nst0)
btape: btape.c:1573-0 Wrote EOF to "Drive-1" (/dev/nst0)
The test autochanger worked!!
--------------------------------------------end successful btape test
output----------------------
------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, SlashDot.org! http://sdm.link/slashdot
_______________________________________________
Bacula-users mailing list
Bacula-users AT lists.sourceforge DOT net
https://lists.sourceforge.net/lists/listinfo/bacula-users
|
