arcserver 11.5 sp3 build 4402

[hospitalcase]

E3719
E3712
E3705

Dell power vault 114T, certance ultrium 2 backup unit.
Tape device disabled in device manager.
Adaptec Scsi 393020a.

Recently installed a new Dell power vault unit.
Initial backups went fine, however no matter what tapes (Sony / TDK) are tried it fails on E3719 and E3712.
It will format some tapes but not others, and if I put these tapes into our other ultrium 2 system they work with no problems.
I'm thinking it may be a hardware issue but if any one's got other suggestions I'd be grateful.

thks

 

[davidmichel]

include the full text of the errors and the corresponding part of tape.log.

 

[hospitalcase]

[10/02/2007-15:49:45 ,1,45,0,0,-1,2,18,0,0] Overwrite media TUESDAY 3, ID 5DE4, sequence #1
[10/02/2007-15:49:57 ,1,0,0,4,-1,2,18,0,0] Tape Engine finished formatting media.(New Name: [TUESDAY3], S/N: [], Seq: [1], RID: [611d]; Old Name: [TUESDAY 3], S/N: [], Seq: [1], RID: [5de4])
[10/02/2007-15:49:57 ,1,0,0,4,-1,2,18,0,0] Format Successful!
[10/02/2007-15:49:57 ,1,45,0,0,-1,2,18,0,0] Use media TUESDAY3, ID 611D, sequence #1
[10/02/2007-15:49:57 ,1,45,0,0,-1,2,18,0,0] Backup Method: Full (Clear Archive Bit).
[10/02/2007-15:49:57 ,1,45,0,0,-1,2,18,0,0] Connected with client agent at ). (User = olhsc\administrator)
[10/02/2007-15:49:57 ,1,45,1,0,-1,2,18,0,0] BrightStor ARCserve Backup Client Agent for Windows is r11.5, build 3884...
[10/02/2007-15:49:58 ,1,0,0,0,-1,2,3,0,0] Begin cleaning database.
[10/02/2007-15:49:58 ,1,0,0,0,-1,2,3,0,0] End cleaning database. (CLEANED=0)
[10/02/2007-15:49:58 ,1,45,1,0,-1,2,18,0,0] Source Directory: C:
[10/02/2007-15:49:58 ,1,45,1,0,-1,2,18,0,0] Backup Session 1 on Media TUESDAY3
[10/02/2007-15:50:02 ,1,45,1,0,-1,2,18,0,0] Approximately 18,342 file(s) 1,632.02 MB will be processed.
[10/02/2007-15:50:02 ,1,45,1,0,-1,2,18,0,0] Failed to open file <C:\Exchsrvr\FirstStorageGroup\tmp.edb>. RC=32, The process cannot access the file because it is being used by another process.
[10/02/2007-15:50:05 ,1,45,1,0,-1,2,1,0,0] E3719 Unable to write to media. (MEDIA=TUESDAY3 [S/N: ], EC=COMMAND ABORTED)
[10/02/2007-15:50:07 ,1,45,1,0,-1,2,18,0,0] 57 file(s) 49.53 MB sent by agent @ 416.15 MB/min
[10/02/2007-15:50:07 ,1,45,0,0,-1,2,1,0,0] E3712 Unable to close session. (EC=COMMAND ABORTED)
[10/02/2007-15:50:11 ,1,45,0,0,-1,2,3,0,0] dbaexchis Version 11.5 Build 3884 8-9-2005 Microsoft Exchange Server 2K/up
[10/02/2007-15:50:14 ,1,45,0,0,-1,2,18,0,0] Connected with Exchange database agent at .
[10/02/2007-15:50:15 ,1,45,2,0,-1,2,18,0,0] Source Directory: dbaexchis\First Storage Group
[10/02/2007-15:50:15 ,1,45,2,0,-1,2,18,0,0] Backup Session 2 on Media TUESDAY3
[10/02/2007-15:50:30 ,1,45,2,0,-1,2,1,0,0] E3719 Unable to write to media. (MEDIA=TUESDAY3 [S/N: ], EC=COMMAND ABORTED)


tape log

2007/10/02 15:47:53 [0538] USE DEFAULT PATH = C:\Program Files\CA\BrightStor ARCserve Backup\LOG FOR LOGGING
2007/10/02 15:47:53 [0538]
2007/10/02 15:47:53 [0538] ============ TAPE ENGINE SUMMARY LOG ====================
2007/10/02 15:47:53 [0538] Product Info: [CA Inc.] [BrightStor ARCserve Backup] Ver[11.5]
2007/10/02 15:47:53 [0538] Tapeeng Info: Date[Mar 1 2007] Time[22:53:46]
2007/10/02 15:47:53 [0538] Debug Info : Level[1] Read/Write/TestUnitReady Logging[OFF]
2007/10/02 15:47:53 [0538] =========================================================
2007/10/02 15:47:53 [0538] Client Set DebugLevel: 1
2007/10/02 15:47:53 [0538] Getting serial number for Device[3]
2007/10/02 15:47:53 [0538] FindTapeDriveCategory: inquirydata->VendorID: CERTANCEULTRIUM 2 1914
2007/10/02 15:47:53 [0538] 10/02 15:47:53 ABSL:4060 SCSICommandRetry: NT Error that can be retried. CMD:[12], Error 1117
2007/10/02 15:47:53 [0538] Bad Device handle printing SCSI Port Error...
2007/10/02 15:47:55 [0538] =>ABSL:4060 CMD<INQUIRY> NT Error that can be retried. Retry Count:0
2007/10/02 15:47:55 [0538] =>ABSL:4060 Error MS=1117 [The request could not be performed because of an I/O device error.
]
2007/10/02 15:47:55 [0538] =>ABSL[4060] CMD<INQUIRY> Retry Count:1
2007/10/02 15:47:55 [0538] 10/02 15:47:55 ABSL:4060 SCSICommandRetry: NT Error that can be retried. CMD:[12], Error 1117
2007/10/02 15:47:55 [0538] Bad Device handle printing SCSI Port Error...
2007/10/02 15:47:55 [0538] =>ABSL:4060 CMD<INQUIRY> NT Error that can be retried. Retry Count:1
2007/10/02 15:47:55 [0538] =>ABSL:4060 Error MS=1117 [The request could not be performed because of an I/O device error.
]
2007/10/02 15:47:55 [0538] =>ABSL[4060] CMD<INQUIRY> Retry Count:2
2007/10/02 15:47:55 [0538] 10/02 15:47:55 ABSL:4060 SCSICommandRetry: NT Error that can be retried. CMD:[12], Error 1117
2007/10/02 15:47:55 [0538] Bad Device handle printing SCSI Port Error...
2007/10/02 15:47:55 [0538] =>ABSL:4060 CMD<INQUIRY> NT Error that can be retried. Retry Count:2
2007/10/02 15:47:55 [0538] =>ABSL:4060 Error MS=1117 [The request could not be performed because of an I/O device error.
]
2007/10/02 15:47:55 [0538] =>ABSL[4060] CMD<INQUIRY> Retry Count:3
2007/10/02 15:47:55 [0538] 10/02 15:47:55 ABSL:4060 SCSICommandRetry: NT Error that can be retried. CMD:[12], Error 1117
2007/10/02 15:47:55 [0538] Bad Device handle printing SCSI Port Error...
2007/10/02 15:47:55 [0538] =>ABSL:4060 CMD<INQUIRY> NT Error that can be retried. Retry Count:3
2007/10/02 15:47:55 [0538] =>ABSL:4060 Error MS=1117 [The request could not be performed because of an I/O device error.
]
2007/10/02 15:47:55 [0538] =>ABSL:4060 Error. MS=1117 [The request could not be performed because of an I/O device error.
]
2007/10/02 15:47:55 [0538] Bad Device handle printing SCSI Port Error...
2007/10/02 15:47:55 [0538] Found [0]USB Devices, Total [4] Devices.
2007/10/02 15:47:55 [0538] Loading Changer.dll: Date[Mar 1 2007] Time[19:02:01]
2007/10/02 15:47:55 [0538] TapeDrive[3] ABSL:4060 <ULTRIUM 2 1914> S/N[JK0420B]
2007/10/02 15:47:55 [0538] ABSL = 0 0 0 0, adapterTransferSize = 131072
2007/10/02 15:47:55 [0538] ABSL = 1 0 0 0, adapterTransferSize = 131072
2007/10/02 15:47:55 [0538] ABSL = 2 0 0 0, adapterTransferSize = 131072
2007/10/02 15:47:55 [0538] ABSL = 4 0 6 0, adapterTransferSize = 266240
2007/10/02 15:47:55 [0690] =>ABSL:4060 Command:[INQUIRY ] <Drive>
2007/10/02 15:47:55 [0690] ABSL:4060 Sense Key status: Illegal Request [05]
2007/10/02 15:47:55 [0690] ABSL:4060 Additional sense: Invalid Field In CDB [24, 00]
2007/10/02 15:50:03 [0f9c] UnExpected SCSI Error ==> JobID[45], Device[3], ABSL[4 0 6 0], SN[JK0420B], CMD[ah], [Data Phase Error], ASC[4b], ASCQ[00]
2007/10/02 15:50:03 [0f9c] =>ABSL:4060 Command:[WRITE ] <Drive>
2007/10/02 15:50:03 [0f9c] ABSL:4060 Sense Key status: Command Aborted [0b]
2007/10/02 15:50:03 [0f9c] ABSL:4060 Additional sense: Data Phase Error [4b, 00]
2007/10/02 15:50:27 [0fd8] UnExpected SCSI Error ==> JobID[45], Device[3], ABSL[4 0 6 0], SN[JK0420B], CMD[ah], [Data Phase Error], ASC[4b], ASCQ[00]
2007/10/02 15:50:27 [0fd8] =>ABSL:4060 Command:[WRITE ] <Drive>
2007/10/02 15:50:27 [0fd8] ABSL:4060 Sense Key status: Command Aborted [0b]
2007/10/02 15:50:27 [0fd8] ABSL:4060 Additional sense: Data Phase Error [4b, 00]
2007/10/02 15:50:30 [0694] DRV:3 [CERTANCEULTRIUM 2 1914] recovered [0] error for [writing.].
2007/10/02 16:00:31 [0690] =>ABSL:4060 Command:[TEST UNIT READY ] <Drive>
2007/10/02 16:00:31 [0690] ABSL:4060 Sense Key status: Unit Attention [06]
2007/10/02 16:00:31 [0690] ABSL:4060 Additional sense: Diagnostic Failure On Component ASCQ: NN (80H-FFH) [3f, 10]
2007/10/02 16:00:31 [0690] DRV:3 Got SCSI Unit Attention, Go test drive again with Unit Attention
2007/10/02 16:00:37 [0690] =>ABSL:4060 Command:[TEST UNIT READY ] <Drive>
2007/10/02 16:00:37 [0690] ABSL:4060 Sense Key status: Unit Attention [06]
2007/10/02 16:00:37 [0690] ABSL:4060 Additional sense: Diagnostic Failure On Component ASCQ: NN (80H-FFH) [3f, 11]
2007/10/02 16:00:37 [0690] DRV:3 Got SCSI Unit Attention, Go test drive again with Unit Attention
2007/10/02 16:01:19 [0690] DRV:3 Got SCSI Unit Attention, Go test drive again with Unit Attention
2007/10/02 16:04:59 [0694] =>ABSL:4060 Command:[WRITE FILEMARK ] <Drive>
2007/10/02 16:04:59 [0694] ABSL:4060 Sense Key status: Media Error [03]
2007/10/02 16:04:59 [0694] ABSL:4060 Additional sense: Write Append Error [50, 00]
2007/10/02 16:04:59 [0694] DRV:3 Retry1 DMWriteTapeHeader count[1]
2007/10/02 16:07:08 [0694] =>ABSL:4060 Command:[WRITE FILEMARK ] <Drive>
2007/10/02 16:07:08 [0694] ABSL:4060 Sense Key status: Media Error [03]
2007/10/02 16:07:08 [0694] ABSL:4060 Additional sense: Write Append Error [50, 00]
2007/10/02 16:07:08 [0694] DRV:3 Retry1 DMWriteTapeHeader count[2]
2007/10/02 16:08:37 [0694] =>ABSL:4060 Command:[WRITE FILEMARK ] <Drive>
2007/10/02 16:08:37 [0694] ABSL:4060 Sense Key status: Media Error [03]
2007/10/02 16:08:37 [0694] ABSL:4060 Additional sense: Write Append Error [50, 00]
2007/10/02 16:08:37 [0694] DRV:3 Retry1 DMWriteTapeHeader count[3]
2007/10/02 16:10:06 [0694] =>ABSL:4060 Command:[WRITE FILEMARK ] <Drive>
2007/10/02 16:10:06 [0694] ABSL:4060 Sense Key status: Media Error [03]
2007/10/02 16:10:06 [0694] ABSL:4060 Additional sense: Write Append Error [50, 00]
2007/10/02 16:10:06 [0694] DRV:3 Retry1 DMWriteTapeHeader count[4]
2007/10/02 16:11:34 [0694] =>ABSL:4060 Command:[WRITE FILEMARK ] <Drive>
2007/10/02 16:11:34 [0694] ABSL:4060 Sense Key status: Media Error [03]
2007/10/02 16:11:34 [0694] ABSL:4060 Additional sense: Write Append Error [50, 00]
2007/10/02 16:11:34 [0694] DRV:3 Retry1 DMWriteTapeHeader count[5]
2007/10/02 16:13:03 [0694] =>ABSL:4060 Command:[WRITE FILEMARK ] <Drive>
2007/10/02 16:13:03 [0694] ABSL:4060 Sense Key status: Media Error [03]
2007/10/02 16:13:03 [0694] ABSL:4060 Additional sense: Write Append Error [50, 00]
2007/10/02 16:13:03 [0694] DRV:3 Retry1 DMWriteTapeHeader count[6]
2007/10/02 16:14:31 [0694] =>ABSL:4060 Command:[WRITE FILEMARK ] <Drive>
2007/10/02 16:14:31 [0694] ABSL:4060 Sense Key status: Media Error [03]
2007/10/02 16:14:31 [0694] ABSL:4060 Additional sense: Write Append Error [50, 00]
2007/10/02 16:14:31 [0694] DRV:3 Retry1 DMWriteTapeHeader count[7]
2007/10/02 16:16:00 [0694] =>ABSL:4060 Command:[WRITE FILEMARK ] <Drive>
2007/10/02 16:16:00 [0694] ABSL:4060 Sense Key status: Media Error [03]
2007/10/02 16:16:00 [0694] ABSL:4060 Additional sense: Write Append Error [50, 00]
2007/10/02 16:16:00 [0694] DRV:3 Retry1 DMWriteTapeHeader count[8]
2007/10/02 16:17:28 [0694] =>ABSL:4060 Command:[WRITE FILEMARK ] <Drive>
2007/10/02 16:17:28 [0694] ABSL:4060 Sense Key status: Media Error [03]
2007/10/02 16:17:28 [0694] ABSL:4060 Additional sense: Write Append Error [50, 00]
2007/10/02 16:17:28 [0694] DRV:3 Retry1 DMWriteTapeHeader count[9]
2007/10/02 16:18:57 [0694] =>ABSL:4060 Command:[WRITE FILEMARK ] <Drive>
2007/10/02 16:18:57 [0694] ABSL:4060 Sense Key status: Media Error [03]
2007/10/02 16:18:57 [0694] ABSL:4060 Additional sense: Write Append Error [50, 00]
2007/10/02 16:18:57 [0694] DRV:3 Retry1 DMWriteTapeHeader count[10]
2007/10/02 16:18:57 [0694] DRV:3 DMTapeWriteTapeHeader Failed: 165
2007/10/02 16:18:57 [0694] DMFormatTape failed. error = 0xa5 -- jID[46], mID[0], jTKN[1190371173], jNUM@2@, dcb[3]
2007/10/02 16:18:57 [0f50] DRV:3 [CERTANCEULTRIUM 2 1914] recovered [0] error for [writing.].

 

[davidmichel]

E3712 Unable to close session. (EC=COMMAND ABORTED)

2007/10/02 15:50:03 [0f9c] ABSL:4060 Sense Key status: Command Aborted [0b]
2007/10/02 15:50:03 [0f9c] ABSL:4060 Additional sense: Data Phase Error [4b, 00]

data phase error - command from Tape Engine sent to drive - data in, response from drive sent back to TE - data out.

the SCSI bus should have been in a data in phase as a result of the Write command but it was in a data out phase and hence the command was aborted.

but even before that there are all those NT SCSI port errors.
disable the tape device from within the OS Device Manager
check SCSI bus termination
update the SCSI controller driver
remove other devices from this SCSI bus