mhvtl 0.18-16, ArcServe r15 SP1, unable to backup

[petergrace]

Hi All,

I have setup mhvtl in a test environment with ArcServe, serving the changer and two tape drives via tgtd to a windows server using Windows built-in iscsi initiator.

ArcServe detects the changer fine and will even label media.  However, when I attempt to run a backup, I get an error from ArcServe that it "Failed to position the media."

I have included the error messages below in hopes someone might be able to shed some light.  As I had seen that other users were having issues with block sizes, I have configured ArcServe to use 65536 byte blocksize.  It has not changed the behavior as far as I can tell, the same error pops up regardless.

Thanks in advance,
Pete

----ARCSERVE ERROR----

E3895              TGSLCARCSERV01         06/20/2011 07:47:00 AM 21                Failed to position the media. (Media=TG0000L4, Serial Number=TG0000L4, ID=5B26, Sequence Number=1, Error Message=CONTROLLER FAILURE or HARDWARE ERROR)

---- dump_tape -f TG0000L4 ----

PCL is : TG0000L4
Media density code: 0x46
Media type code   : 0x08
Media description : Ultrium 4/16T
Tape Capacity     : 104857600000
Total num of filemarks: 1
Hdr:   Compressed data(0b), sz    376/65536 , Blk No.: 0, data 0
Hdr:         Filemark(03), sz             0, Blk No.: 1, data 376
Hdr:      End of Data(05), sz             0, Blk No.: 2, data 376

---- VTL syslog ----

Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: CDB (3724) 00 60 00 00 00 00
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: spc_tur: ** Test Unit Ready : Returning =>  (3724) Online **
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: completeSCSICommand: OP s/n: (3724), sz: 0, sam_status: 0
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: CDB (3725) 00 60 00 00 00 00
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: spc_tur: ** Test Unit Ready : Returning =>  (3725) Online **
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: completeSCSICommand: OP s/n: (3725), sz: 0, sam_status: 0
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: CDB (3726) 00 60 00 00 00 00
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: spc_tur: ** Test Unit Ready : Returning =>  (3726) Online **
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: completeSCSICommand: OP s/n: (3726), sz: 0, sam_status: 0
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: CDB (3727) 00 60 00 00 00 00
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: spc_tur: ** Test Unit Ready : Returning =>  (3727) Online **
Jun 20 07:53:48 tgslcvtl01 vtllibrary[18417]: completeSCSICommand: OP s/n: (3727), sz: 0, sam_status: 0
Jun 20 07:53:49 tgslcvtl01 vtltape[18306]: CDB (3728) 00 20 00 00 00 00
Jun 20 07:53:49 tgslcvtl01 vtltape[18306]: ssc_tur: Test Unit Ready (3728) ** : Yes
Jun 20 07:53:49 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3728), sz: 0, sam_status: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: CDB (3729) 00 20 00 00 00 00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_tur: Test Unit Ready (3729) ** : Yes
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3729), sz: 0, sam_status: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: CDB (3730) 4c 02 c0 00 00 00 00 00 00 00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_log_select: LOG SELECT (3730) **
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3730), sz: 0, sam_status: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: CDB (3731) 1a 00 00 00 0c 00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense: MODE SENSE (3731) **
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense:  Mode Sense 6 byte version
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense:  Page Control  : Current configuration(0x0)
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense:  Page Code     : 0x0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense:  Disable Block Descriptor => No
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense:  Allocation len: 12
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense: pcode: 0x00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3731), sz: 12, sam_status: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: CDB (3732) 1a 00 00 00 0c 00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense: MODE SENSE (3732) **
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense:  Mode Sense 6 byte version
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense:  Page Control  : Current configuration(0x0)
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense:  Page Code     : 0x0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense:  Disable Block Descriptor => No
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense:  Allocation len: 12
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: spc_mode_sense: pcode: 0x00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3732), sz: 12, sam_status: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: CDB (3733) 00 20 00 00 00 00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_tur: Test Unit Ready (3733) ** : Yes
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3733), sz: 0, sam_status: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: CDB (3734) 00 20 00 00 00 00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_tur: Test Unit Ready (3734) ** : Yes
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3734), sz: 0, sam_status: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: CDB (3735) 01 00 00 00 00 00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_rewind: Rewinding (3735) **
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: read_header: Reading header 0 at offset 0, type: DATA, size: 65536
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: rewind_tape: Media is writable
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3735), sz: 0, sam_status: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: CDB (3736) 34 00 00 00 00 00 00 00 00 00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_read_position: Read Position (3736) **
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: resp_read_position: Positioned at block 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3736), sz: 20, sam_status: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: CDB (3737) 11 01 00 0f a0 00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_space: SPACE (3737) ** forward 4000 filemarks
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: read_header: Reading header 2 at offset 376, type: END OF DATA, size: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: mkSenseBuf: Sense buf: 0x8064370
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [08 00 05]
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3737), sz: 0, sam_status: 0
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: CDB (3738) 34 00 00 00 00 00 00 00 00 00
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_read_position: Read Position (3738) **
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: resp_read_position: Positioned at block 2
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3738), sz: 20, sam_status: 0
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: CDB (3739) 00 20 00 00 00 00
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: ssc_tur: Test Unit Ready (3739) ** : Yes
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3739), sz: 0, sam_status: 0
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: CDB (3740) 00 20 00 00 00 00
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: ssc_tur: Test Unit Ready (3740) ** : Yes
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3740), sz: 0, sam_status: 0
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: CDB (3741) 00 20 00 00 00 00
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: ssc_tur: Test Unit Ready (3741) ** : Yes
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3741), sz: 0, sam_status: 0
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: CDB (3742) 01 00 00 00 00 00
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: ssc_rewind: Rewinding (3742) **
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: read_header: Reading header 0 at offset 0, type: DATA, size: 65536
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: rewind_tape: Media is writable
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3742), sz: 0, sam_status: 0
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: CDB (3743) 34 00 00 00 00 00 00 00 00 00
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: ssc_read_position: Read Position (3743) **
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: resp_read_position: Positioned at block 0
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3743), sz: 20, sam_status: 0
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: CDB (3744) 11 01 00 0f a0 00
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: ssc_space: SPACE (3744) ** forward 4000 filemarks
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: read_header: Reading header 2 at offset 376, type: END OF DATA, size: 0
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: mkSenseBuf: Sense buf: 0x8064370
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [08 00 05]
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3744), sz: 0, sam_status: 0
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: CDB (3745) 34 00 00 00 00 00 00 00 00 00
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: ssc_read_position: Read Position (3745) **
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: resp_read_position: Positioned at block 2
Jun 20 07:53:53 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3745), sz: 20, sam_status: 0
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: CDB (3746) 4d 00 43 00 00 00 00 00 40 00
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: resp_log_sense: LOG SENSE (3746) **
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: resp_log_sense: LOG SENSE: Read error page
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3746), sz: 96, sam_status: 0
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: CDB (3747) 00 20 00 00 00 00
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: ssc_tur: Test Unit Ready (3747) ** : Yes
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3747), sz: 0, sam_status: 0
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: CDB (3748) 01 00 00 00 00 00
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: ssc_rewind: Rewinding (3748) **
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: read_header: Reading header 0 at offset 0, type: DATA, size: 65536
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: rewind_tape: Media is writable
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3748), sz: 0, sam_status: 0
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: CDB (3749) 34 00 00 00 00 00 00 00 00 00
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: ssc_read_position: Read Position (3749) **
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: resp_read_position: Positioned at block 0
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3749), sz: 20, sam_status: 0
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: CDB (3750) b8 64 00 01 00 01 00 00 00 80 00 00
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status: READ ELEMENT STATUS (3750) **
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status:  Element type(4) => Data Transfer Elements
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status:   Starting Element Address: 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status:   Number of Elements      : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status:   Allocation length       : 128
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status:   Device ID: No, voltag: No
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_page: Element type: Data Transfer (drive) Element, min: 1 num: 2
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_page: max_count: 1, max_bytes: 128
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_page: avail: 2, count: 1, space: 7 *cur_count: 0
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_page_hdr: Element Status Page Header: 04 00 00 10 00 00 00 10
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_page: Slot: 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_descriptor: Slot location: 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_descriptor: DVCID: 0, VOLTAG: 0, Index: 12
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_descriptor: Returning 16 bytes
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: num_available_elements: Determing 1 element of type 4 starting at 1, returning 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr: Building READ ELEMENT STATUS Header struct
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:  Starting slot: 1, number of configured slots: 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:  Element Status Data HEADER: 00 01 00 01 00 00 00 18
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:  Decoded:
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:   First element Address    : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:   Number elements reported : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:   Total byte count         : 24
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status: Returning 32 bytes
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status: Element Status Data
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   First element reported       : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Number of elements available : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Byte count of report         : 24
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status: Element Status Page
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Element Type code            : 4
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Primary Vol Tag              : No
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Alt Vol Tag                  : No
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Element descriptor length    : 16
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Byte count of descriptor data: 16
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status: Element Descriptor(s) : Num of Elements 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:  Debug.... i = 0, len = 16
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Element Address             : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Status                      : 0x09
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Medium type                 : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Source Address              : 1024
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:  Identification Descriptor
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Code Set                     : 0x00
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Identifier type              : 0x00
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Identifier length            : 0
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: completeSCSICommand: OP s/n: (3750), sz: 32, sam_status: 0
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: CDB (3751) b8 64 00 01 00 01 00 00 00 80 00 00
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status: READ ELEMENT STATUS (3751) **
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status:  Element type(4) => Data Transfer Elements
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status:   Starting Element Address: 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status:   Number of Elements      : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status:   Allocation length       : 128
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status:   Device ID: No, voltag: No
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_page: Element type: Data Transfer (drive) Element, min: 1 num: 2
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_page: max_count: 1, max_bytes: 128
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_page: avail: 2, count: 1, space: 7 *cur_count: 0
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_page_hdr: Element Status Page Header: 04 00 00 10 00 00 00 10
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_page: Slot: 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_descriptor: Slot location: 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_descriptor: DVCID: 0, VOLTAG: 0, Index: 12
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_descriptor: Returning 16 bytes
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: num_available_elements: Determing 1 element of type 4 starting at 1, returning 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr: Building READ ELEMENT STATUS Header struct
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:  Starting slot: 1, number of configured slots: 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:  Element Status Data HEADER: 00 01 00 01 00 00 00 18
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:  Decoded:
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:   First element Address    : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:   Number elements reported : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: fill_element_status_data_hdr:   Total byte count         : 24
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: smc_read_element_status: Returning 32 bytes
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status: Element Status Data
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   First element reported       : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Number of elements available : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Byte count of report         : 24
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status: Element Status Page
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Element Type code            : 4
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Primary Vol Tag              : No
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Alt Vol Tag                  : No
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Element descriptor length    : 16
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status:   Byte count of descriptor data: 16
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: decode_element_status: Element Descriptor(s) : Num of Elements 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:  Debug.... i = 0, len = 16
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Element Address             : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Status                      : 0x09
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Medium type                 : 1
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Source Address              : 1024
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:  Identification Descriptor
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Code Set                     : 0x00
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Identifier type              : 0x00
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: dump_element_desc:   Identifier length            : 0
Jun 20 07:54:52 tgslcvtl01 vtllibrary[18417]: completeSCSICommand: OP s/n: (3751), sz: 32, sam_status: 0
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: CDB (3752) 4d 00 2e 00 00 00 00 01 44 00
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: resp_log_sense: LOG SENSE (3752) **
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: resp_log_sense: LOG SENSE: TapeAlert page
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: resp_log_sense:  Returning TapeAlert flags: 0x0
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: setTapeAlert: Setting TapeAlert flags 0x00000000 00000000
Jun 20 07:54:52 tgslcvtl01 vtltape[18306]: completeSCSICommand: OP s/n: (3752), sz: 324, sam_status: 0

[Mark Harvey]

Hi Peter,

Thanks for the bug report.

I can't say I've seen anybody test ArcServe before..

What is it with the 'position' OP code. Such a simple structure that has caused more bugs/problems than any other op code.. Oh well.

Looks like ArcServ doesn't like the return code from the 'read position' and re-tries the position again.

Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_rewind: Rewinding (3735) **
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_read_position: Read Position (3736) **
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_space: SPACE (3737) ** forward 4000 filemarks
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: mkSenseBuf: SENSE [Key/ASC/ASCQ] [08 00 05]

Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: ssc_read_position: Read Position (3738) **
Jun 20 07:53:51 tgslcvtl01 vtltape[18306]: resp_read_position: Positioned at block 2

I'll look at this over the next couple of days and hopefully have something for you to test.

Cheers
Mark

[Mark Harvey]

Sorry, This took me longer than it should have.

Please try the latest code from github. It includes a fix which corrects this error.

Or patch the existing code using the following

From da77ce992d5b91c4611cbab69e64ee61754e4fe8 Mon Sep 17 00:00:00 2001
From: Sebastian Herbszt <[e-mail]>
Date: Tue, 24 May 2011 09:17:07 +1000
Subject: ssc: return correct status code in ssc_space()

The status code can be modified in resp_space(). Return the correct status code
instead of SAM_STAT_GOOD.

Signed-off-by: Sebastian Herbszt <[e-mail]>
Signed-off-by: Mark Harvey <[e-mail]>
---
 usr/ssc.c |    4 +++-
 1 files changed, 3 insertions(+), 1 deletions(-)

diff --git a/usr/ssc.c b/usr/ssc.c
index 03b0b40..3861741 100644
--- a/usr/ssc.c
+++ b/usr/ssc.c
@@ -999,6 +999,8 @@ uint8_t ssc_space(struct scsi_cmd *cmd)

        sam_stat = &cmd->dbuf_p->sam_stat;

+       *sam_stat = SAM_STAT_GOOD;
+
        count = get_unaligned_be24(&cmd->scb[2]);
        code = cmd->scb[1] & 0x07;

@@ -1045,7 +1047,7 @@ uint8_t ssc_space(struct scsi_cmd *cmd)
        if (icount != 0 || code == 3)
                resp_space(icount, code, sam_stat);

-       return SAM_STAT_GOOD;
+       return *sam_stat;
 }

 uint8_t ssc_load_unload(struct scsi_cmd *cmd)
--
1.7.4.1

[petergrace]

That fixed it!

I backed up 50MB which compressed down to 7MB (just backed up a user profile on the windows server), ArcServe reported average throughput of 280.5 MB/min, which I assume in my less-than-optimal setup is pretty good (mhvtl in a vm, arcserve in a vm, both using backing storage on the same iscsi filer, sharing bandwidth)

Let me know if there's anything "exotic" you might want me to test with ArcServe.

Thanks for the fix!
Pete

[nia]

Hi Mark,

This new code is not showing up in github !

Do you still need to merge it ?

nia

[Mark Harvey]

This patch should (is) the 2nd patch / commit following the 0.18-16_release tag. dated 2011-05-24 (give/take a little for timezone variance)

Cheers
Mark

[nia]

I get it now. This was already fixed. Pete must have been using an older MHVTL code.

Makes sense now.

Thanks Mark.