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@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/bacula-users
