Can't get drives to work with CommVault Simpana backup.

classic Classic list List threaded Threaded
24 messages Options
12
Reply | Threaded
Open this post in threaded view
|

Can't get drives to work with CommVault Simpana backup.

egraeler
All,

I'm trying to get a vtl running on linux using the CommVault Simpana backup, but the tapes fail to mount in the drives.  Apparently the CommVault code is detecting that the drives have encryption capabilities and try to turn off the HW encryption which causes an error and thus the tape fails to mount.

I enabled the verbosity of the mhvtl as well as turned on the debugging.  Here is the section of the /var/log/messages from then I initiate a tape erase through the interface on the simpana server.  I also have included the section of the log from CommVault showing an error when trying to disable the HW encryption.  Is there a way to disable encryption on the VTL drives?

Have I encountered a bug in the VTL drive driver?  Any help would be appreciated.
Thanks!
Ernie

Contents of /var/log/messages:

Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_log_sense: LOG SENSE: Sending supported pages
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2386), sz: 13, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2387) 4d 00 6e 00 00 00 00 04 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: LOG SENSE (2387) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_log_sense: LOG SENSE: TapeAlert page
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_log_sense:  Returning TapeAlert flags: 0x0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: setTapeAlert: Setting TapeAlert flags 0x00000000 00000000
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2387), sz: 324, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2388) 1b 00 00 00 01 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Loading Tape (2388) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: read_header: Reading header 0 at offset 0, type: END OF DATA
Nov  8 17:02:50 lx64mag2 vtltape[31424]: rewind_tape: Media is writable
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2388), sz: 0, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2389) 00 00 00 00 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Test Unit Ready (2389) : Yes
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2389), sz: 0, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2390) 1a 00 0f 00 80 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: MODE SENSE (2390) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense:  Mode Sense 6 byte version
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense:  Page Control  : Current configuration(0x0)
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense:  Page Code     : 0xf
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense:  Disable Block Descriptor => No
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense:  Allocation len: 128
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense: pcode: 0x0f
Nov  8 17:02:50 lx64mag2 vtltape[31424]: find_pcode: Entered: pcode 0xf
Nov  8 17:02:50 lx64mag2 vtltape[31424]: find_pcode: (0xf): match pcode 15
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2390), sz: 28, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2391) 15 10 00 00 0c 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: MODE SELECT (2391) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: retrieve_CDB_data: retrieving 12 bytes from kernel
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2391), sz: 0, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2392) 01 00 00 00 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Rewinding (2392) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: read_header: Reading header 0 at offset 0, type: END OF DATA
Nov  8 17:02:50 lx64mag2 vtltape[31424]: rewind_tape: Media is writable
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2392), sz: 0, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2393) 4d 00 40 00 00 00 00 00 80 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: LOG SENSE (2393) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_log_sense: LOG SENSE: Sending supported pages
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2393), sz: 13, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2394) 00 00 00 00 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Test Unit Ready (2394) : Yes
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2394), sz: 0, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2395) 4d 00 40 00 00 00 00 00 80 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: LOG SENSE (2395) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_log_sense: LOG SENSE: Sending supported pages
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2395), sz: 13, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2396) 4d 00 6e 00 00 00 00 04 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: LOG SENSE (2396) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_log_sense: LOG SENSE: TapeAlert page
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_log_sense:  Returning TapeAlert flags: 0x0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: setTapeAlert: Setting TapeAlert flags 0x00000000 00000000
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2396), sz: 324, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2397) 1b 00 00 00 01 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Loading Tape (2397) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: read_header: Reading header 0 at offset 0, type: END OF DATA
Nov  8 17:02:50 lx64mag2 vtltape[31424]: rewind_tape: Media is writable
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2397), sz: 0, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2398) 00 00 00 00 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Test Unit Ready (2398) : Yes
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2398), sz: 0, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2399) 01 00 00 00 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Rewinding (2399) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: read_header: Reading header 0 at offset 0, type: END OF DATA
Nov  8 17:02:50 lx64mag2 vtltape[31424]: rewind_tape: Media is writable
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2399), sz: 0, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2400) 1a 00 0f 00 80 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: MODE SENSE (2400) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense:  Mode Sense 6 byte version
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense:  Page Control  : Current configuration(0x0)
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense:  Page Code     : 0xf
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense:  Disable Block Descriptor => No
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense:  Allocation len: 128
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_mode_sense: pcode: 0x0f
Nov  8 17:02:50 lx64mag2 vtltape[31424]: find_pcode: Entered: pcode 0xf
Nov  8 17:02:50 lx64mag2 vtltape[31424]: find_pcode: (0xf): match pcode 15
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2400), sz: 28, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2401) 15 10 00 00 0c 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: MODE SELECT (2401) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: retrieve_CDB_data: retrieving 12 bytes from kernel
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2401), sz: 0, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2402) a2 20 00 01 00 00 00 00 02 00 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Security Protocol In (2402) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: lookup_sp_specific: Lookup 1
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spin_page_20: Tape Data Encyrption Out Support Page
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Returning 6 bytes
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2402), sz: 6, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2403) a2 20 00 10 00 00 00 00 02 00 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Security Protocol In (2403) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: lookup_sp_specific: Lookup 16
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spin_page_20: Data Encryption Capabilities page
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spin_page_20: Drive type: LTO4, Media type: LTO4 Data
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spin_page_20: LTO4 drive
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spin_page_20: LTO4 Medium
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Returning 44 bytes
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2403), sz: 44, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2404) a2 20 00 10 00 00 00 00 02 00 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Security Protocol In (2404) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: lookup_sp_specific: Lookup 16
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spin_page_20: Data Encryption Capabilities page
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spin_page_20: Drive type: LTO4, Media type: LTO4 Data
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spin_page_20: LTO4 drive
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spin_page_20: LTO4 Medium
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Returning 44 bytes
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2404), sz: 44, sam_status: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2405) b5 20 00 10 00 00 00 00 00 34 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Security Protocol Out (2405) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: mkSenseBuf: Sense buf: 0x617370
Nov  8 17:02:50 lx64mag2 vtltape[31424]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [05 20 00]
Nov  8 17:02:50 lx64mag2 vtltape[31424]: retrieve_CDB_data: retrieving 52 bytes from kernel
Nov  8 17:02:50 lx64mag2 vtltape[31424]: lookup_sp_specific: Lookup 16
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spout: Tape Data Encryption, Data Encryption Capabilities page,  alloc len: 0x34, inc_512: Unset
Nov  8 17:02:50 lx64mag2 vtltape[31424]: resp_spout: Encrypt mode: 0 Decrypt mode: 0, ukad len: 0 akad len: 0
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Returning 0 bytes

Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2405), sz: 0, sam_status: 2
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: [Key/ASC/ASCQ] [05 20 00]
Nov  8 17:02:50 lx64mag2 vtltape[31424]: CDB (2406) 17 00 00 00 00 00
Nov  8 17:02:50 lx64mag2 vtltape[31424]: processCommand: Release (2406) **
Nov  8 17:02:50 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2406), sz: 0, sam_status: 0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: CDB (2407) 12 00 00 00 24 00
Nov  8 17:02:51 lx64mag2 vtltape[31424]: processCommand: INQUIRY (2407) **
Nov  8 17:02:51 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2407), sz: 66, sam_status: 0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: CDB (2408) 12 01 80 00 80 00
Nov  8 17:02:51 lx64mag2 vtltape[31424]: processCommand: INQUIRY (2408) **
Nov  8 17:02:51 lx64mag2 vtltape[31424]: spc_inquiry: Page code 0x80
Nov  8 17:02:51 lx64mag2 vtltape[31424]: spc_inquiry: Found page 0x80
Nov  8 17:02:51 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2408), sz: 14, sam_status: 0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: CDB (2409) 12 01 80 00 80 00
Nov  8 17:02:51 lx64mag2 vtltape[31424]: processCommand: INQUIRY (2409) **
Nov  8 17:02:51 lx64mag2 vtltape[31424]: spc_inquiry: Page code 0x80
Nov  8 17:02:51 lx64mag2 vtltape[31424]: spc_inquiry: Found page 0x80
Nov  8 17:02:51 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2409), sz: 14, sam_status: 0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: CDB (2410) 16 00 00 00 00 00
Nov  8 17:02:51 lx64mag2 vtltape[31424]: processCommand: Reserve (2410) **
Nov  8 17:02:51 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2410), sz: 0, sam_status: 0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: CDB (2411) 00 00 00 00 00 00
Nov  8 17:02:51 lx64mag2 vtltape[31424]: processCommand: Test Unit Ready (2411) : Yes
Nov  8 17:02:51 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2411), sz: 0, sam_status: 0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: CDB (2412) 1b 00 00 00 00 00
Nov  8 17:02:51 lx64mag2 vtltape[31424]: processCommand: Unloading Tape (2412)  **
Nov  8 17:02:51 lx64mag2 vtltape[31424]: updateMAM: updateMAM(0)
Nov  8 17:02:51 lx64mag2 vtltape[31424]: find_pcode: Entered: pcode 0x1d
Nov  8 17:02:51 lx64mag2 vtltape[31424]: find_pcode: (0x1d): match pcode 29
Nov  8 17:02:51 lx64mag2 vtltape[31424]: clearWORM: WORM mode page cleared
Nov  8 17:02:51 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2412), sz: 0, sam_status: 0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: CDB (2413) 4d 00 40 00 00 00 00 00 80 00
Nov  8 17:02:51 lx64mag2 vtltape[31424]: processCommand: LOG SENSE (2413) **
Nov  8 17:02:51 lx64mag2 vtltape[31424]: resp_log_sense: LOG SENSE: Sending supported pages
Nov  8 17:02:51 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2413), sz: 13, sam_status: 0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: CDB (2414) 4d 00 6e 00 00 00 00 04 00 00
Nov  8 17:02:51 lx64mag2 vtltape[31424]: processCommand: LOG SENSE (2414) **
Nov  8 17:02:51 lx64mag2 vtltape[31424]: resp_log_sense: LOG SENSE: TapeAlert page
Nov  8 17:02:51 lx64mag2 vtltape[31424]: resp_log_sense:  Returning TapeAlert flags: 0x0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: setTapeAlert: Setting TapeAlert flags 0x00000000 00000000
Nov  8 17:02:51 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2414), sz: 324, sam_status: 0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: CDB (2415) 4d 00 6e 00 00 00 00 04 00 00
Nov  8 17:02:51 lx64mag2 vtltape[31424]: processCommand: LOG SENSE (2415) **
Nov  8 17:02:51 lx64mag2 vtltape[31424]: resp_log_sense: LOG SENSE: TapeAlert page
Nov  8 17:02:51 lx64mag2 vtltape[31424]: resp_log_sense:  Returning TapeAlert flags: 0x0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: setTapeAlert: Setting TapeAlert flags 0x00000000 00000000
Nov  8 17:02:51 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2415), sz: 324, sam_status: 0
Nov  8 17:02:51 lx64mag2 vtltape[31424]: CDB (2416) 17 00 00 00 00 00
Nov  8 17:02:51 lx64mag2 vtltape[31424]: processCommand: Release (2416) **
Nov  8 17:02:51 lx64mag2 vtltape[31424]: completeSCSICommand: OP s/n: (2416), sz: 0, sam_status: 0
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: CDB (2417) 00 00 00 00 00 00
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: processCommand: Test Unit Ready : Returning =>  Yes
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: completeSCSICommand: OP s/n: (2417), sz: 0, sam_status: 0
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: CDB (2418) 00 00 00 00 00 00
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: processCommand: Test Unit Ready : Returning =>  Yes
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: completeSCSICommand: OP s/n: (2418), sz: 0, sam_status: 0
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: CDB (2419) 00 00 00 00 00 00
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: processCommand: Test Unit Ready : Returning =>  Yes
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: completeSCSICommand: OP s/n: (2419), sz: 0, sam_status: 0
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: CDB (2420) a5 00 01 00 00 01 04 00 00 00 00 00
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: processCommand: MOVE MEDIUM **
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: Moving from slot 1 to Slot 1024 using transport 256, Invert media: no
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: slot2struct: slot2struct: Storage 1024
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: is_map_slot: slot type 2
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: is_map_slot: slot type 2
Nov  8 17:02:52 lx64mag2 vtllibrary[31803]: completeSCSICommand: OP s/n: (2420), sz: 0, sam_status: 0
Nov  8 17:02:52 lx64mag2 vtltape[31424]: processMessageQ: Q snd_id 30 msg : unload
Nov  8 17:02:52 lx64mag2 vtltape[31424]: unloadTape: Tape not mounted
Nov  8 17:02:52 lx64mag2 vtltape[31424]: processMessageQ: Library requested tape unload


Contents of CommVault library log (CVMA.log):

31943 4095c940 11/08 17:02:50 1163  SERVICE  [109544/0/0          ]  Received CVMA_ERASE_MEDIA_REQ.
31943 417be940 11/08 17:02:50 1163 Device [scsidev@scsi2:0.9.0] - Instantiating the CvTapePT class .......
31943 417be940 11/08 17:02:50 1163 Device [scsidev@scsi2:0.9.0] - The drive supports data encryption
31943 417be940 11/08 17:02:50 1163 Device [scsidev@scsi2:0.9.0] - Sense Code: Status = 0xff, ASC = 0xff, ASCQ = 0xff - Reserved: Vendor-specific code
31943 417be940 11/08 17:02:50 1163  OML      [109544/0/0          ]  :CvTapeOMLLib.cpp:564: Failed to disable Data Encryption, VolId=0 error= Sense Code: Status = 0xff, ASC = 0xff, ASCQ = 0xff - Reserved: Vendor-specific code
31943 417be940 11/08 17:02:50 1163  WORKER   [109544/0/0          ]  Failed to Write media erase label after the Erase media, Lib9_Drive1, path- scsidev@scsi2:0.9.0. Error = 764

31943 417be940 11/08 17:02:50 1163  WORKER   [109544/0/0          ]  CVMMClient API for sendEraseMediaResponse from Lib9_Drive1 completed. Status = 0
31943 412b9940 11/08 17:02:51 1163  SERVICE  [109544/0/0#Lib9_Drive1]  Received CVMA_DCP_UNLOAD_REQ.
31943 417be940 11/08 17:02:51 1163  WORKER   [109544/0/0#Lib9_Drive1]  Going to run phase 3 Drive Command for request id 109544/0/0#Lib9_Drive1, Lib9_Drive1, path- scsidev@scsi2:0.9.0
31943 417be940 11/08 17:02:51 1163  WORKER   [109544/0/0#Lib9_Drive1]  Succesfully completed phase 3 Drive Command for request id 109544/0/0#Lib9_Drive1, Lib9_Drive1, path- scsidev@scsi2:0.9.0
31943 417be940 11/08 17:02:51 1163 Device [scsidev@scsi2:0.9.0] - Instantiating the CvTapePT class .......
31943 417be940 11/08 17:02:51 1163  WORKER   [109544/0/0#Lib9_Drive1]  Serial number XYZZY_B1 for Lib9_Drive1, path- scsidev@scsi2:0.9.0 Matched succesfully.
31943 417be940 11/08 17:02:51 1163  WORKER   [109544/0/0#Lib9_Drive1]  Completed SCSI2 Reservation for host Id [14], drive id [30].
31943 417be940 11/08 17:02:51 1163  WORKER   [109544/0/0#Lib9_Drive1]  Going to unload media for request id 109544/0/0#Lib9_Drive1, Lib9_Drive1, path- scsidev@scsi2:0.9.0
31943 417be940 11/08 17:02:51 1163  WORKER   [109544/0/0#Lib9_Drive1]  Unload media for Lib9_Drive1, path- scsidev@scsi2:0.9.0 Completed succesfully
31943 417be940 11/08 17:02:51 1163  WORKER   [109544/0/0#Lib9_Drive1]  Going to run phase 4 Drive Command for request id 109544/0/0#Lib9_Drive1, Lib9_Drive1, path- scsidev@scsi2:0.9.0
31943 417be940 11/08 17:02:51 1163  WORKER   [109544/0/0#Lib9_Drive1]  Succesfully completed phase 4 Drive Command for request id 109544/0/0#Lib9_Drive1, Lib9_Drive1, path- scsidev@scsi2:0.9.0
31943 417be940 11/08 17:02:51 1163  WORKER   [109544/0/0#Lib9_Drive1]  CVMMClient API for sendDcpUnLoadResponse from Lib9_Drive1 completed
31943 4095c940 11/08 17:02:52 1163  SERVICE  [109544/0/0#Lib9_Drive1]  Received CVMA_UNMOUNT_REQ.
31943 417be940 11/08 17:02:52 1163  WORKER   [109544/0/0#Lib9_Drive1]  Going to UNMOUNT  for Library9 from drive [Lib9_Drive1] Address: [1] to slot [slot 1] Address: [1024] for Bar code  E03001L4 and Side name A_213
31943 417be940 11/08 17:02:52 1163  WORKER   [109544/0/0#Lib9_Drive1]  Succesfully dispatched UNMOUNT Command to Library Handler for Library Controller 9, Library9
31943 413cd940 11/08 17:02:52 ####  RECEIVER [109544/0/0#Lib9_Drive1]  CVMMClient API for sendLMSUnMountResponse  RequestID= 109544/0/0#Lib9_Drive1, from Library9 completed


nia
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

nia
Administrator
egraeler wrote
 Is there a way to disable encryption on the VTL drives?
I think all you have to do for that is remove the option:

 ENCRYPTION: LTO_4

Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

Mark Harvey
Administrator
In reply to this post by egraeler
Sounds like a bug to me.

Thanks for the report.

I'll review the information this evening and see what's not being done at the mhvtl end of the world.

Cheers
Mark
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

Mark Harvey
Administrator
p.s. One 'work around' would be to re-define the drive as 'LTO1'  (ULT3580-TD1) in device.conf
And update library_contents.XX and replace trailing 'L4' with 'L1'

CommVault should not attempt to try encryption with LTO-1 drives :)

Cheers
Mark
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

egraeler
Thanks for the reply!  I'll give that a shot and will let you know the outcome.

Ernie
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

egraeler
No Luck...   apparently the CommVault code still queries the device which is reporting the encryption is supported.  :(

3859 41a70940 11/09 10:02:57 1173 Device [scsidev@scsi2:0.10.0] - Instantiating the CvTapePT class .......
3859 41a70940 11/09 10:02:57 1173 Device [scsidev@scsi2:0.10.0] - The drive supports data encryption
3859 41a70940 11/09 10:02:57 1173 Device [scsidev@scsi2:0.10.0] - Sense Code: Status = 0xff, ASC = 0xff, ASCQ = 0xff - Reserved: Vendor-specific code
3859 41a70940 11/09 10:02:57 1173  OML      [113909/0/0          ]  :CvTapeOMLLib.cpp:564: Failed to disable Data Encryption, VolId=0 error= Sense Code: Status = 0xff, ASC = 0xff, ASCQ = 0xff - Reserved: Vendor-specific code
3859 41a70940 11/09 10:02:57 1173  WORKER   [113909/0/0          ]  Failed to Write media erase label after the Erase media, Lib10_Drive2, path- scsidev@scsi2:0.10.0. Error = 764

From /var/log/messages I still see:

Nov  9 10:02:57 lx64mag2 vtltape[3410]: read_header: Reading header 0 at offset 0, type: END OF DATA
Nov  9 10:02:57 lx64mag2 vtltape[3410]: rewind_tape: Media is writable
Nov  9 10:02:57 lx64mag2 vtltape[3410]: completeSCSICommand: OP s/n: (6781), sz: 0, sam_status: 0
Nov  9 10:02:57 lx64mag2 vtltape[3410]: CDB (6782) 1a 00 0f 00 80 00
Nov  9 10:02:57 lx64mag2 vtltape[3410]: processCommand: MODE SENSE (6782) **
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_mode_sense:  Mode Sense 6 byte version
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_mode_sense:  Page Control  : Current configuration(0x0)
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_mode_sense:  Page Code     : 0xf
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_mode_sense:  Disable Block Descriptor => No
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_mode_sense:  Allocation len: 128
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_mode_sense: pcode: 0x0f
Nov  9 10:02:57 lx64mag2 vtltape[3410]: find_pcode: Entered: pcode 0xf
Nov  9 10:02:57 lx64mag2 vtltape[3410]: find_pcode: (0xf): match pcode 15
Nov  9 10:02:57 lx64mag2 vtltape[3410]: completeSCSICommand: OP s/n: (6782), sz: 28, sam_status: 0
Nov  9 10:02:57 lx64mag2 vtltape[3410]: CDB (6783) 15 10 00 00 0c 00
Nov  9 10:02:57 lx64mag2 vtltape[3410]: processCommand: MODE SELECT (6783) **
Nov  9 10:02:57 lx64mag2 vtltape[3410]: retrieve_CDB_data: retrieving 12 bytes from kernel
Nov  9 10:02:57 lx64mag2 vtltape[3410]: completeSCSICommand: OP s/n: (6783), sz: 0, sam_status: 0
Nov  9 10:02:57 lx64mag2 vtltape[3410]: CDB (6784) a2 20 00 01 00 00 00 00 02 00 00 00
Nov  9 10:02:57 lx64mag2 vtltape[3410]: processCommand: Security Protocol In (6784) **
Nov  9 10:02:57 lx64mag2 vtltape[3410]: lookup_sp_specific: Lookup 1
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_spin_page_20: Tape Data Encyrption Out Support Page
Nov  9 10:02:57 lx64mag2 vtltape[3410]: processCommand: Returning 6 bytes
Nov  9 10:02:57 lx64mag2 vtltape[3410]: completeSCSICommand: OP s/n: (6784), sz: 6, sam_status: 0
Nov  9 10:02:57 lx64mag2 vtltape[3410]: CDB (6785) a2 20 00 10 00 00 00 00 02 00 00 00
Nov  9 10:02:57 lx64mag2 vtltape[3410]: processCommand: Security Protocol In (6785) **
Nov  9 10:02:57 lx64mag2 vtltape[3410]: lookup_sp_specific: Lookup 16
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_spin_page_20: Data Encryption Capabilities page
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_spin_page_20: Drive type: LTO1, Media type: LTO1 Data
Nov  9 10:02:57 lx64mag2 vtltape[3410]: processCommand: Returning 44 bytes
Nov  9 10:02:57 lx64mag2 vtltape[3410]: completeSCSICommand: OP s/n: (6785), sz: 44, sam_status: 0
Nov  9 10:02:57 lx64mag2 vtltape[3410]: CDB (6786) a2 20 00 10 00 00 00 00 02 00 00 00
Nov  9 10:02:57 lx64mag2 vtltape[3410]: processCommand: Security Protocol In (6786) **
Nov  9 10:02:57 lx64mag2 vtltape[3410]: lookup_sp_specific: Lookup 16
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_spin_page_20: Data Encryption Capabilities page
Nov  9 10:02:57 lx64mag2 vtltape[3410]: resp_spin_page_20: Drive type: LTO1, Media type: LTO1 Data
Nov  9 10:02:57 lx64mag2 vtltape[3410]: processCommand: Returning 44 bytes
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

Mark Harvey
Administrator
Thanks for the update.

I'll post a patch which will 'disable' the SCSI Security Protocol IN/OUT commands as a quick work-around.

I'm in the process of separating the 'personality' of each drive type into it's own plug-in module.

Once this is done, it will be easy to isolate supported SCSI OP codes / device type. Not easy in the current implementation..

Cheers
Mark
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

egraeler
Sweet...   Thanks!
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

Mark Harvey
Administrator
Can you please test/try this version.

I've added checks for SECURITY PROTOCOL IN/OUT for drive types:
Ultrium-4, Ultrium-5, T10000A, T10000B and 3592E05 and 3592E06.
Other drive types will get a 'OP CODE NOT SUPPORTED'.

p.s. I've also found a very suspicious piece of code around SP OUT. Can you also check CommVault against the ULT3582-TD4 drive type (or any of the above drive types that support SPIN/SPOUT).

mhvtl-2010-11-10.tgz

Many thanks
Mark
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

egraeler
Excellent!   I'm currently working on other stuff, but hopefully have some time later today to test this.  I'll let you know how I make out.
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

egraeler
Hmm...  set it up using LTO4 as suggested but still getting the same mount error.  I need to enable debugging and try this again, as well as trying to configure as an LTO1 drive again.  As soon as I get a chance to run this again with the debugging I'll upload the log pieces.

Thanks!
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

Mark Harvey
Administrator
Thanks for the the testing.

Can you try with LTO1, LTO2 or LTO3 ?

These should report back that they don't support the Security Protocol IN / Security Protocol OUT and (fingers crossed) CommVault will continue.

I'll incorporate some extra logging to enable the collection of the data CommVault is sending so I can better understand what it wants

Cheers
Mark
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

egraeler
That's next on my list of things to try.  It was a crazy day at work today (I do SW support...  It seems that everything always happens right before the weekend!)  Hopefully Monday AM will be somewhat quiet and I'll have some time to test this.  When I do, I'll let you know the results.

Thanks!
Ernie
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

Mark Harvey
Administrator
Re: I do SW support...

Me too.
I know where your coming from :)
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

egraeler
Hi Mark,

I tried the new code...  but the outcome is still the same.  Attached is the latest error with the drive configured as LTO1.

I'll reset it as LTO4 and will attach that in another post.  Let me know if there is anything else you would like me to try.  I first thought that after I recompiled the code that I didn't rmmod the mhvtl module, so that is what I just tried (To make sure everything was unloaded and stopped) I then reran both makes (On the kernel and the daemons) and re-ran the test.

Here it the log snippets from /var/log/messages as well as the log from the CV media agent:
Info from /var/log/messages:

Nov 15 14:23:52 lx64mag2 vtltape[19837]: completeSCSICommand: OP s/n: (223), sz: 28, sam_status: 0
Nov 15 14:23:52 lx64mag2 kernel: mhvtl: CDB (224) 6 bytes
Nov 15 14:23:52 lx64mag2 kernel:  15 10 00 00 0c 00
Nov 15 14:23:52 lx64mag2 vtltape[19837]: CDB (224) 15 10 00 00 0c 00
Nov 15 14:23:52 lx64mag2 vtltape[19837]: processCommand: MODE SELECT (224) **
Nov 15 14:23:52 lx64mag2 vtltape[19837]: retrieve_CDB_data: retrieving 12 bytes from kernel
Nov 15 14:23:52 lx64mag2 vtltape[19837]: completeSCSICommand: OP s/n: (224), sz: 0, sam_status: 0
Nov 15 14:23:52 lx64mag2 kernel: mhvtl: CDB (225) 12 bytes
Nov 15 14:23:52 lx64mag2 kernel:  a2 20 00 01 00 00 00 00 02 00 00 00
Nov 15 14:23:52 lx64mag2 vtltape[19837]: CDB (225) a2 20 00 01 00 00 00 00 02 00 00 00
Nov 15 14:23:52 lx64mag2 vtltape[19837]: processCommand: Security Protocol In (225) **
Nov 15 14:23:52 lx64mag2 vtltape[19837]: lookup_sp_specific: Lookup 1
Nov 15 14:23:52 lx64mag2 vtltape[19837]: resp_spin_page_20: Tape Data Encyrption Out Support Page
Nov 15 14:23:52 lx64mag2 vtltape[19837]: processCommand: Returning 6 bytes
Nov 15 14:23:52 lx64mag2 vtltape[19837]: completeSCSICommand: OP s/n: (225), sz: 6, sam_status: 0
Nov 15 14:23:52 lx64mag2 kernel: mhvtl: CDB (226) 12 bytes
Nov 15 14:23:52 lx64mag2 vtltape[19837]: CDB (226) a2 20 00 10 00 00 00 00 02 00 00 00
Nov 15 14:23:52 lx64mag2 kernel:  a2 20 00 10 00 00 00 00 02 00 00 00
Nov 15 14:23:52 lx64mag2 vtltape[19837]: processCommand: Security Protocol In (226) **
Nov 15 14:23:52 lx64mag2 vtltape[19837]: lookup_sp_specific: Lookup 16
Nov 15 14:23:52 lx64mag2 vtltape[19837]: resp_spin_page_20: Data Encryption Capabilities page
Nov 15 14:23:52 lx64mag2 vtltape[19837]: resp_spin_page_20: Drive type: LTO1, Media type: LTO1 Data
Nov 15 14:23:52 lx64mag2 vtltape[19837]: processCommand: Returning 44 bytes
Nov 15 14:23:52 lx64mag2 vtltape[19837]: completeSCSICommand: OP s/n: (226), sz: 44, sam_status: 0
Nov 15 14:23:52 lx64mag2 kernel: mhvtl: CDB (227) 12 bytes
Nov 15 14:23:52 lx64mag2 kernel:  a2 20 00 10 00 00 00 00 02 00 00 00
Nov 15 14:23:52 lx64mag2 vtltape[19837]: CDB (227) a2 20 00 10 00 00 00 00 02 00 00 00
Nov 15 14:23:52 lx64mag2 vtltape[19837]: processCommand: Security Protocol In (227) **
Nov 15 14:23:52 lx64mag2 vtltape[19837]: lookup_sp_specific: Lookup 16
Nov 15 14:23:52 lx64mag2 vtltape[19837]: resp_spin_page_20: Data Encryption Capabilities page
Nov 15 14:23:52 lx64mag2 vtltape[19837]: resp_spin_page_20: Drive type: LTO1, Media type: LTO1 Data
Nov 15 14:23:52 lx64mag2 vtltape[19837]: processCommand: Returning 44 bytes
Nov 15 14:23:52 lx64mag2 vtltape[19837]: completeSCSICommand: OP s/n: (227), sz: 44, sam_status: 0
Nov 15 14:23:52 lx64mag2 kernel: mhvtl: CDB (228) 12 bytes
Nov 15 14:23:52 lx64mag2 kernel:  b5 20 00 10 00 00 00 00 00 34 00 00
Nov 15 14:23:52 lx64mag2 vtltape[19837]: CDB (228) b5 20 00 10 00 00 00 00 00 34 00 00
Nov 15 14:23:52 lx64mag2 vtltape[19837]: processCommand: Security Protocol Out (228) **
Nov 15 14:23:52 lx64mag2 vtltape[19837]: mkSenseBuf: Sense buf: 0x617370
Nov 15 14:23:52 lx64mag2 vtltape[19837]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [05 20 00]
Nov 15 14:23:52 lx64mag2 vtltape[19837]: retrieve_CDB_data: retrieving 52 bytes from kernel
Nov 15 14:23:52 lx64mag2 vtltape[19837]: lookup_sp_specific: Lookup 16
Nov 15 14:23:52 lx64mag2 vtltape[19837]: resp_spout: Tape Data Encryption, Data Encryption Capabilities page,  alloc len: 0x34, inc_512: Unset
Nov 15 14:23:52 lx64mag2 vtltape[19837]: resp_spout: Encrypt mode: 0 Decrypt mode: 0, ukad len: 0 akad len: 0
Nov 15 14:23:52 lx64mag2 vtltape[19837]: processCommand: Returning 0 bytes
Nov 15 14:23:52 lx64mag2 vtltape[19837]: completeSCSICommand: OP s/n: (228), sz: 0, sam_status: 2
Nov 15 14:23:52 lx64mag2 vtltape[19837]: completeSCSICommand: [Key/ASC/ASCQ] [05 20 00]
Nov 15 14:23:52 lx64mag2 kernel: mhvtl: CDB (229) 6 bytes
Nov 15 14:23:52 lx64mag2 vtltape[19837]: CDB (229) 17 00 00 00 00 00
Nov 15 14:23:52 lx64mag2 kernel:  17 00 00 00 00 00


Log file from CV agent:
20256 40863940 11/15 14:23:51 1254 Device [scsidev@scsi3:0.10.0] - Instantiating the CvTapePT class .......
20256 40863940 11/15 14:23:52 1254 Device [scsidev@scsi3:0.10.0] - The drive supports data encryption
20256 40863940 11/15 14:23:52 1254 Device [scsidev@scsi3:0.10.0] - Sense Code: Status = 0xff, ASC = 0xff, ASCQ = 0xff - Reserved: Vendor-specific code
20256 40863940 11/15 14:23:52 1254  OML      [150599/0/0          ]  :CvTapeOMLLib.cpp:564: Failed to disable Data Encryption, VolId=0 error= Sense Code: Status = 0xff, ASC = 0xff, ASCQ = 0xff - Reserved: Vendor-specific code
20256 40863940 11/15 14:23:52 1254  WORKER   [150599/0/0          ]  Failed to Write media erase label after the Erase media, Lib14_Drive2, path- scsidev@scsi3:0.10.0. Error = 764
20256 40863940 11/15 14:23:52 1254  WORKER   [150599/0/0          ]  CVMMClient API for sendEraseMediaResponse from Lib14_Drive2 completed. Status = 0
20256 413f3940 11/15 14:23:53 1254  SERVICE  [150599/0/0#Lib14_Drive2]  Received CVMA_DCP_UNLOAD_REQ.
20256 42219940 11/15 14:23:53 1254  WORKER   [150599/0/0#Lib14_Drive2]  Going to run phase 3 Drive Command for request id 150599/0/0#Lib14_Drive2, Lib14_Drive2, path- scsidev@scsi3:0.10.0
20256 42219940 11/15 14:23:53 1254  WORKER   [150599/0/0#Lib14_Drive2]  Succesfully completed phase 3 Drive Command for request id 150599/0/0#Lib14_Drive2, Lib14_Drive2, path- scsidev@scsi3:0.10.0

I'm going to reset the drives back to LTO4 and try that again as well...  (After confirming that the module DID unload from the kernel)
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

egraeler
Just managed to reset the library and drives to LTO4...   Here are the log bits from that attempt:

CV-MA.log:
21396 4215d940 11/15 15:14:33 1261  SERVICE  [150877/0/0          ]  Received CVMA_ERASE_MEDIA_REQ.
21396 41fda940 11/15 15:14:33 1261 Device [scsidev@scsi3:0.10.0] - Instantiating the CvTapePT class .......
21396 41fda940 11/15 15:14:33 1261 Device [scsidev@scsi3:0.10.0] - The drive supports data encryption
21396 41fda940 11/15 15:14:33 1261 Device [scsidev@scsi3:0.10.0] - Sense Code: Status = 0xff, ASC = 0xff, ASCQ = 0xff - Reserved: Vendor-specific code
21396 41fda940 11/15 15:14:33 1261  OML      [150877/0/0          ]  :CvTapeOMLLib.cpp:564: Failed to disable Data Encryption, VolId=0 error= Sense Code: Status = 0xff, ASC = 0xff, ASCQ = 0xff - Reserved: Vendor-specific code
21396 41fda940 11/15 15:14:33 1261  WORKER   [150877/0/0          ]  Failed to Write media erase label after the Erase media, Lib14_Drive2, path- scsidev@scsi3:0.10.0. Error = 764
21396 41fda940 11/15 15:14:33 1261  WORKER   [150877/0/0          ]  CVMMClient API for sendEraseMediaResponse from Lib14_Drive2 completed. Status = 0
21396 416da940 11/15 15:14:34 1261  SERVICE  [150877/0/0#Lib14_Drive2]  Received CVMA_DCP_UNLOAD_REQ.
21396 41fda940 11/15 15:14:34 1261  WORKER   [150877/0/0#Lib14_Drive2]  Going to run phase 3 Drive Command for request id 150877/0/0#Lib14_Drive2, Lib14_Drive2, path- scsidev@scsi3:0.10.0
21396 41fda940 11/15 15:14:34 1261  WORKER   [150877/0/0#Lib14_Drive2]  Succesfully completed phase 3 Drive Command for request id 150877/0/0#Lib14_Drive2, Lib14_Drive2, path- scsidev@scsi3:0.10.0


from /var/log/messages:
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: MODE SENSE (888) **
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_mode_sense:  Mode Sense 6 byte version
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_mode_sense:  Page Control  : Current configuration(0x0)
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_mode_sense:  Page Code     : 0xf
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_mode_sense:  Disable Block Descriptor => No
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_mode_sense:  Allocation len: 128
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_mode_sense: pcode: 0x0f
Nov 15 15:14:33 lx64mag2 vtltape[22904]: find_pcode: Entered: pcode 0xf
Nov 15 15:14:33 lx64mag2 vtltape[22904]: find_pcode: (0xf): match pcode 15
Nov 15 15:14:33 lx64mag2 vtltape[22904]: completeSCSICommand: OP s/n: (888), sz: 28, sam_status: 0
Nov 15 15:14:33 lx64mag2 kernel: mhvtl: CDB (889) 6 bytes
Nov 15 15:14:33 lx64mag2 vtltape[22904]: CDB (889) 15 10 00 00 0c 00
Nov 15 15:14:33 lx64mag2 kernel:  15 10 00 00 0c 00
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: MODE SELECT (889) **
Nov 15 15:14:33 lx64mag2 vtltape[22904]: retrieve_CDB_data: retrieving 12 bytes from kernel
Nov 15 15:14:33 lx64mag2 vtltape[22904]: completeSCSICommand: OP s/n: (889), sz: 0, sam_status: 0
Nov 15 15:14:33 lx64mag2 kernel: mhvtl: CDB (890) 12 bytes
Nov 15 15:14:33 lx64mag2 vtltape[22904]: CDB (890) a2 20 00 01 00 00 00 00 02 00 00 00
Nov 15 15:14:33 lx64mag2 kernel:  a2 20 00 01 00 00 00 00 02 00 00 00
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: Security Protocol In (890) **
Nov 15 15:14:33 lx64mag2 vtltape[22904]: lookup_sp_specific: Lookup 1
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spin_page_20: Tape Data Encyrption Out Support Page
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: Returning 6 bytes
Nov 15 15:14:33 lx64mag2 vtltape[22904]: completeSCSICommand: OP s/n: (890), sz: 6, sam_status: 0
Nov 15 15:14:33 lx64mag2 kernel: mhvtl: CDB (891) 12 bytes
Nov 15 15:14:33 lx64mag2 kernel:  a2 20 00 10 00 00 00 00 02 00 00 00
Nov 15 15:14:33 lx64mag2 vtltape[22904]: CDB (891) a2 20 00 10 00 00 00 00 02 00 00 00
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: Security Protocol In (891) **
Nov 15 15:14:33 lx64mag2 vtltape[22904]: lookup_sp_specific: Lookup 16
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spin_page_20: Data Encryption Capabilities page
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spin_page_20: Drive type: LTO4, Media type: LTO4 Data
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spin_page_20: LTO4 drive
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spin_page_20: LTO4 Medium
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: Returning 44 bytes
Nov 15 15:14:33 lx64mag2 vtltape[22904]: completeSCSICommand: OP s/n: (891), sz: 44, sam_status: 0
Nov 15 15:14:33 lx64mag2 kernel: mhvtl: CDB (892) 12 bytes
Nov 15 15:14:33 lx64mag2 kernel:  a2 20 00 10 00 00 00 00 02 00 00 00
Nov 15 15:14:33 lx64mag2 vtltape[22904]: CDB (892) a2 20 00 10 00 00 00 00 02 00 00 00
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: Security Protocol In (892) **
Nov 15 15:14:33 lx64mag2 vtltape[22904]: lookup_sp_specific: Lookup 16
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spin_page_20: Data Encryption Capabilities page
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spin_page_20: Drive type: LTO4, Media type: LTO4 Data
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spin_page_20: LTO4 drive
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spin_page_20: LTO4 Medium
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: Returning 44 bytes
Nov 15 15:14:33 lx64mag2 vtltape[22904]: completeSCSICommand: OP s/n: (892), sz: 44, sam_status: 0
Nov 15 15:14:33 lx64mag2 kernel: mhvtl: CDB (893) 12 bytes
Nov 15 15:14:33 lx64mag2 kernel:  b5 20 00 10 00 00 00 00 00 34 00 00
Nov 15 15:14:33 lx64mag2 vtltape[22904]: CDB (893) b5 20 00 10 00 00 00 00 00 34 00 00
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: Security Protocol Out (893) **
Nov 15 15:14:33 lx64mag2 vtltape[22904]: mkSenseBuf: Sense buf: 0x617370
Nov 15 15:14:33 lx64mag2 vtltape[22904]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [05 20 00]
Nov 15 15:14:33 lx64mag2 vtltape[22904]: retrieve_CDB_data: retrieving 52 bytes from kernel
Nov 15 15:14:33 lx64mag2 vtltape[22904]: lookup_sp_specific: Lookup 16
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spout: Tape Data Encryption, Data Encryption Capabilities page,  alloc len: 0x34, inc_512: Unset
Nov 15 15:14:33 lx64mag2 vtltape[22904]: resp_spout: Encrypt mode: 0 Decrypt mode: 0, ukad len: 0 akad len: 0
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: Returning 0 bytes
Nov 15 15:14:33 lx64mag2 vtltape[22904]: completeSCSICommand: OP s/n: (893), sz: 0, sam_status: 2
Nov 15 15:14:33 lx64mag2 vtltape[22904]: completeSCSICommand: [Key/ASC/ASCQ] [05 20 00]
Nov 15 15:14:33 lx64mag2 kernel: mhvtl: CDB (894) 6 bytes
Nov 15 15:14:33 lx64mag2 vtltape[22904]: CDB (894) 17 00 00 00 00 00
Nov 15 15:14:33 lx64mag2 kernel:  17 00 00 00 00 00
Nov 15 15:14:33 lx64mag2 vtltape[22904]: processCommand: Release (894) **
Nov 15 15:14:33 lx64mag2 vtltape[22904]: completeSCSICommand: OP s/n: (894), sz: 0, sam_status: 0
Nov 15 15:14:34 lx64mag2 kernel: mhvtl: CDB (895) 6 bytes


Again...  thanks for taking the time to look at this!   Anything that you can provide will be appreciated.
Ernie
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

Mark Harvey
Administrator
OK, just re-tried using a device configured as :
   ======= /etc/mhvtl/device.conf ==========
Drive: 18 CHANNEL: 00 TARGET: 12 LUN: 00
 Library ID: 10 Slot: 08
 Vendor identification: IBM
 Product identification: ULT3580-TD1
 Product revision level: 550V
 Unit serial number: XYZZY_B8
 NAA: 10:22:33:44:ab:00:12:00
 Compression: factor 1 enabled 1
 READ_WRITE: LTO_1
   ======= end /etc/mhvtl/device.conf ==========

I added a couple of extra messages (diff at bottom of message) that should not have changed the outcome.

Did you try this with an Ultrium 1/2/3 configured drive ?
Did you install from the tar ball in the earlier posting in this thread ?
Did you re-start the vtltape daemons ?


# sg_raw -v /dev/sg9 a2 20 00 01 00 00 00 00 02 00 00 00
    cdb to send: a2 20 00 01 00 00 00 00 02 00 00 00
SCSI Status: Check Condition

Sense Information:
 Fixed format, current;  Sense key: Illegal Request
 Additional sense: Invalid command operation code
  Info fld=0x0 [0]
 Raw sense data (in hex):
        f0 00 05 00 00 00 00 1e  00 00 00 00 20 00 00 00
        00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00

Nov 16 15:59:06 zaphodvm vtltape[17904]: CDB (482) a2 20 00 01 00 00 00 00 02 00 00 00
Nov 16 15:59:06 zaphodvm vtltape[17904]: processCommand: Security Protocol In (482) **
Nov 16 15:59:06 zaphodvm vtltape[17904]: resp_spin: Encryption NOT supported
Nov 16 15:59:06 zaphodvm vtltape[17904]: mkSenseBuf: Sense buf: 0x80627a0
Nov 16 15:59:06 zaphodvm vtltape[17904]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [05 20 00]
Nov 16 15:59:06 zaphodvm vtltape[17904]: processCommand: Returning 0 bytes
Nov 16 15:59:06 zaphodvm vtltape[17904]: completeSCSICommand: OP s/n: (482), sz: 0, sam_status: 2
Nov 16 15:59:06 zaphodvm vtltape[17904]: completeSCSICommand: [Key/ASC/ASCQ] [05 20 00]



# sg_raw -v /dev/sg9 b5 20 00 10 00 00 00 00 00 34 00 00
    cdb to send: b5 20 00 10 00 00 00 00 00 34 00 00
SCSI Status: Check Condition

Sense Information:
 Fixed format, current;  Sense key: Illegal Request
 Additional sense: Invalid command operation code
  Info fld=0x0 [0]
 Raw sense data (in hex):
        f0 00 05 00 00 00 00 1e  00 00 00 00 20 00 00 00
        00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00

Nov 16 16:00:28 zaphodvm vtltape[17904]: CDB (483) b5 20 00 10 00 00 00 00 00 34 00 00
Nov 16 16:00:28 zaphodvm vtltape[17904]: processCommand: Security Protocol Out (483) **
Nov 16 16:00:28 zaphodvm vtltape[17904]: retrieve_CDB_data: retrieving 52 bytes from kernel
Nov 16 16:00:28 zaphodvm vtltape[17904]: resp_spout: Encryption NOT supported
Nov 16 16:00:28 zaphodvm vtltape[17904]: mkSenseBuf: Sense buf: 0x80627a0
Nov 16 16:00:28 zaphodvm vtltape[17904]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [05 20 00]
Nov 16 16:00:28 zaphodvm vtltape[17904]: processCommand: Returning 0 bytes


$ git diff
diff --git a/usr/vtltape.c b/usr/vtltape.c
index 9820632..ec818ec 100644
--- a/usr/vtltape.c
+++ b/usr/vtltape.c
@@ -1647,8 +1647,10 @@ static int resp_spin(struct scsi_cmd *cmd)
        case drive_3592_E06:
        case drive_10K_A:
        case drive_10K_B:
+               MHVTL_DBG(2, "Encryption supported, continuing");
                break;
        default:
+               MHVTL_DBG(2, "Encryption NOT supported");
                mkSenseBuf(ILLEGAL_REQUEST, E_INVALID_OP_CODE, sam_stat);
                return SAM_STAT_CHECK_CONDITION;
        }
@@ -1689,8 +1691,10 @@ static int resp_spout(struct scsi_cmd *cmd)
        case drive_3592_E06:
        case drive_10K_A:
        case drive_10K_B:
+               MHVTL_DBG(2, "Encryption supported, continuing");
                break;
        default:
+               MHVTL_DBG(2, "Encryption NOT supported");
                mkSenseBuf(ILLEGAL_REQUEST, E_INVALID_OP_CODE, sam_stat);
                return SAM_STAT_CHECK_CONDITION;
        }
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

egraeler
Hi Mark,

I thought that it looked funny...  as there really was no difference in the behavior.  I just downloaded the tar file again...  I then unpacked the tar and went to the usr directory and grep'd for the string "Encryption supported, continuing" from vtltape.c and that string is not there...  I'm not sure I got the new code. ?

Here is what I did:
[root@lx64mag2 usr]# pwd
/root/mhvtl-0.18/usr
[root@lx64mag2 usr]# ls
ait4_pm.o             make_vtl_media.in    ssc.c             vtllib.h
be_byteshift.h        mktape.c             ssc.h             vtllibrary.c
build_library_config  q.c                  t10000_pm.o       vtltape.c
default_ssc_pm.o      q.h                  tapeexerciser.c   vtltape.c.orig
dump_messageQ.c       scsi.h               ult3580-td4_pm.o  vtltape.c.rej
dump_tape.c           security_protocol.h  ult3580-td5_pm.o  vtltape.h
ibm_3592_E06_pm.o     smc.c                vtlcart.c         vtltape.pem
list.h                smc.h                vtlcart_v1.c
Makefile              spc.c                vtlcmd.c
make_scsi_dev         spc.h                vtllib.c
[root@lx64mag2 usr]# grep "Encryption supported, continuing" vtltape.c
[root@lx64mag2 usr]#
[root@lx64mag2 usr]# grep "Encryption NOT supported" vtltape.c
[root@lx64mag2 usr]#


Can you please check the file you posted earlier?  I'm not sure I got the changes...

Thanks!
Ernie
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

Mark Harvey
Administrator
A couple of things..

The directory listing you presented is the 0.19beta1 release which did NOT include the changes to Security Protocol IN/OUT handling.

0.19beta2 does, but has other issues (segfault's).

I've just uploaded a 0.18-12 release which does include selective support for SPIN/SPOUT handling.

Can you please try the 0.18-12 release and advise on success/failure of this ?

Cheers
Mark
Regards from Australia
Mark Harvey
Reply | Threaded
Open this post in threaded view
|

Re: Can't get drives to work with CommVault Simpana backup.

egraeler
Good news!   I grabbed that version and using the LTO4 drives, I am now able to mount and erase the tapes!  I just tested a 4 stream backup & restore of one of my small oracle databases, and achieved 100% success!   :)  

I even managed to get about 40GB/Hr throughput  (10GB per drive)  Not bad considering everything I have is running in a virtual environment!  

I'm going to also set up an LTO1 library to make sure that is also working OK as well.  I'll let you know how it goes.

Thanks again for all the work you've done on this!  I have a nice little environment to run tests and demos with.  Next thing I'll try is to set up iscsi.

Ernie
12