ESX4.1 and iSCSI Enterprise Target - Writes failing

[raining]

I am using ESX4.1 with Fiber Channel Backend storage. I also have a Virtual Appliance exporting an iSCSI Enterprise Target (IET) to the server. I initiated a copy of a vmdk file from the Fiber Channel datastore to the datastore created on the IET LUN and get only 5 IOPS. When I look at the vmkernel, I see plenty of Abort messages as shown below:

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.227 cpu2:4197)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027f3ccc40) to NMP device "t10.94544500000000003544744465F6C644D203030303D20313" failed on physical path "vmhba33:C0:T0:L0" H:0x5 D:0x0 P:0x0 Possible sense data: 0x2 0x3a 0x1.

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.227 cpu2:4197)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe: NMP device "t10.94544500000000003544744465F6C644D203030303D20313" state in doubt; requested fast path state update...

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.227 cpu2:4197)ScsiDeviceIO: 1672: Command 0x2a to device "t10.94544500000000003544744465F6C644D203030303D20313" failed H:0x5 D:0x0 P:0x0 Possible sense data: 0x2 0x3a 0x1.

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.227 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35ca has been completed on the target but the task response has not arrived

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.299 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35b7 has been completed on the target but the task response has not arrived

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.300 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35b8 has been completed on the target but the task response has not arrived

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.301 cpu3:4113)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027f3b8240) to NMP device "t10.94544500000000003544744465F6C644D203030303D20313" failed on physical path "vmhba33:C0:T0:L0" H:0x8 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0.

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.301 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35b9 has been completed on the target but the task response has not arrived

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.301 cpu3:4113)ScsiDeviceIO: 1672: Command 0x2a to device "t10.94544500000000003544744465F6C644D203030303D20313" failed H:0x8 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0.

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.301 cpu3:4113)FS3: 6978: Starting HB reclaim for [http://HB state abcdef02 offset 3940352 gen 13 stamp 184587298377 uuid 4c6157ec-acd14760-4bac-0016358085fe jrnl <FB 600> drv 8.46|http://HB state abcdef02 offset 3940352 gen 13 stamp 184587298377 uuid 4c6157ec-acd14760-4bac-0016358085fe jrnl <FB 600> drv 8.46]

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.301 cpu3:4153)FS3DM: 2223: status IO was aborted by VMFS via a virt-reset on the device zeroing 1 extents (1048576 each)

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.301 cpu3:4153)J3: 2183: Aborting txn callerID: 0xc1d00006 due to failure pre-committing: IO was aborted by VMFS via a virt-reset on the device

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.301 cpu0:5524)FS3: 7346: Waiting for timed-out heartbeat [http://HB state abcdef02 offset 3940352 gen 13 stamp 184587298377 uuid 4c6157ec-acd14760-4bac-0016358085fe jrnl <FB 600> drv 8.46|http://HB state abcdef02 offset 3940352 gen 13 stamp 184587298377 uuid 4c6157ec-acd14760-4bac-0016358085fe jrnl <FB 600> drv 8.46]

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_ConnSetupScsiResp: vmhba33:CH:0 T:0 CN:0: SCSI Response PDU: Referenced task not found: itt 0x35b8

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_ConnSetupScsiResp: Sess

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_ConnSetupScsiResp: Conn

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu0:5445)iscsi_vmk: iscsivmk_ConnRxNotifyFailure: vmhba33:CH:0 T:0 CN:0: Connection rx notifying failure: SCSI Task Not Found. State=Online

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu0:5445)iscsi_vmk: iscsivmk_ConnRxNotifyFailure: Sess

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu0:5445)iscsi_vmk: iscsivmk_ConnRxNotifyFailure: Conn

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_StopConnection: vmhba33:CH:0 T:0 CN:0: iSCSI connection is being marked "OFFLINE" (Event:6)

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_StopConnection: Sess

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_StopConnection: Conn

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu1:4113)NMP: nmp_CompleteCommandForPath: Command 0x28 (0x41027f3b8240) to NMP device "t10.94544500000000003544744465F6C644D203030303D20313" failed on physical path "vmhba33:C0:T0:L0" H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0.

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.416 cpu1:4113)ScsiDeviceIO: 1672: Command 0x28 to device "t10.94544500000000003544744465F6C644D203030303D20313" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0.

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.467 cpu1:5365)NMP: nmp_CompleteCommandForPath: Command 0x28 (0x41027f3b8240) to NMP device "t10.94544500000000003544744465F6C644D203030303D20313" failed on physical path "vmhba33:C0:T0:L0" H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0.

Aug 12 18:01:06 dg1 vmkernel: 2:03:16:27.467 cpu1:5365)ScsiDeviceIO: 1672: Command 0x28 to device "t10.94544500000000003544744465F6C644D203030303D20313" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0.

Eventually, the iSCSI connection was marked on ONLINE, but writes kept failing, until eventually the connection was marked as OFFLINE once again as seen below:

Aug 12 18:01:09 dg1 vmkernel: 2:03:16:30.679 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_StartConnection: vmhba33:CH:0 T:0 CN:0: iSCSI connection is being marked "ONLINE"

Aug 12 18:01:09 dg1 vmkernel: 2:03:16:30.679 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_StartConnection: Sess

Aug 12 18:01:09 dg1 vmkernel: 2:03:16:30.679 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_StartConnection: Conn

Aug 12 18:01:09 dg1 vmkernel: 2:03:16:30.700 cpu2:4098)NMP: nmp_CompleteCommandForPath: Command 0x28 (0x41027f3b8240) to NMP device "t10.94544500000000003544744465F6C644D203030303D20313" failed on physical path "vmhba33:C0:T0:L0" H:0x0 D:0x2 P:0x0 Valid sense data: 0x6 0x29 0x0.

Aug 12 18:01:09 dg1 vmkernel: 2:03:16:30.700 cpu2:4098)ScsiDeviceIO: 1672: Command 0x28 to device "t10.94544500000000003544744465F6C644D203030303D20313" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x6 0x29 0x0.

Aug 12 18:01:09 dg1 vmkernel: 2:03:16:30.700 cpu2:4098)WARNING: ScsiCore: 1353: Power-on Reset occurred on t10.94544500000000003544744465F6C644D203030303D20313

Aug 12 18:01:10 dg1 vmkernel: 2:03:16:30.732 cpu2:4113)FS3: 397: Reclaimed heartbeat for volume 4c641b58-4dd59608-64c5-0016358085fe (sp-dvol): [http://HB state abcdef02 offset 3940352 gen 13 stamp 184590713314 uuid 4c6157ec-acd14760-4bac-0016358085fe jrnl <FB 600> drv 8.46|http://HB state abcdef02 offset 3940352 gen 13 stamp 184590713314 uuid 4c6157ec-acd14760-4bac-0016358085fe jrnl <FB 600> drv 8.46]

Aug 12 18:01:10 dg1 vmkernel: 2:03:16:30.732 cpu2:4113)FS3: 8496: Long VMFS3 rsv time on 'sp-dvol' (held for 3431 msecs). # R: 1, # W: 1 bytesXfer: 2 sectors

Aug 12 18:01:17 dg1 vmkernel: 2:03:16:37.982 cpu2:4197)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027f3ca140) to NMP device "t10.94544500000000003544744465F6C644D203030303D20313" failed on physical path "vmhba33:C0:T0:L0" H:0x5 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.

Aug 12 18:01:17 dg1 vmkernel: 2:03:16:37.982 cpu2:4197)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe: NMP device "t10.94544500000000003544744465F6C644D203030303D20313" state in doubt; requested fast path state update...

Aug 12 18:01:17 dg1 vmkernel: 2:03:16:37.982 cpu2:4197)ScsiDeviceIO: 1672: Command 0x2a to device "t10.94544500000000003544744465F6C644D203030303D20313" failed H:0x5 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.

Aug 12 18:01:17 dg1 vmkernel: 2:03:16:37.982 cpu0:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x3600 has been completed on the target but the task response has not arrived

Aug 12 18:01:20 dg1 vmkernel: 2:03:16:41.285 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35ff has been completed on the target but the task response has not arrived

Aug 12 18:01:22 dg1 vmkernel: 2:03:16:43.055 cpu3:4197)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027f3ca140) to NMP device "t10.94544500000000003544744465F6C644D203030303D20313" failed on physical path "vmhba33:C0:T0:L0" H:0x5 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.

Aug 12 18:01:22 dg1 vmkernel: 2:03:16:43.055 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x3602 has been completed on the target but the task response has not arrived

Aug 12 18:01:22 dg1 vmkernel: 2:03:16:43.055 cpu3:4197)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe: NMP device "t10.94544500000000003544744465F6C644D203030303D20313" state in doubt; requested fast path state update...

Aug 12 18:01:22 dg1 vmkernel: 2:03:16:43.055 cpu3:4197)ScsiDeviceIO: 1672: Command 0x2a to device "t10.94544500000000003544744465F6C644D203030303D20313" failed H:0x5 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.127 cpu2:4197)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027f3e8640) to NMP device "t10.94544500000000003544744465F6C644D203030303D20313" failed on physical path "vmhba33:C0:T0:L0" H:0x5 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.127 cpu2:4197)ScsiDeviceIO: 1672: Command 0x2a to device "t10.94544500000000003544744465F6C644D203030303D20313" failed H:0x5 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.127 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x3606 has been completed on the target but the task response has not arrived

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.202 cpu1:4115)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027f3de140) to NMP device "t10.94544500000000003544744465F6C644D203030303D20313" failed on physical path "vmhba33:C0:T0:L0" H:0x8 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.202 cpu1:4115)ScsiDeviceIO: 1672: Command 0x2a to device "t10.94544500000000003544744465F6C644D203030303D20313" failed H:0x8 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.202 cpu1:4115)FS3: 6978: Starting HB reclaim for [http://HB state abcdef02 offset 3940352 gen 13 stamp 184608197617 uuid 4c6157ec-acd14760-4bac-0016358085fe jrnl <FB 600> drv 8.46|http://HB state abcdef02 offset 3940352 gen 13 stamp 184608197617 uuid 4c6157ec-acd14760-4bac-0016358085fe jrnl <FB 600> drv 8.46]

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35f6 has been completed on the target but the task response has not arrived

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35f7 has been completed on the target but the task response has not arrived

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35f8 has been completed on the target but the task response has not arrived

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35f9 has been completed on the target but the task response has not arrived

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35fa has been completed on the target but the task response has not arrived

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35fb has been completed on the target but the task response has not arrived

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35fc has been completed on the target but the task response has not arrived

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu2:5445)WARNING: iscsi_vmk: iscsivmk_TaskMgmtAbortCommands: vmhba33:CH:0 T:0 L:0 : Abort task response indicates task with itt=0x35fd has been completed on the target but the task response has not arrived

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu2:5526)FS3DM: 2223: status IO was aborted by VMFS via a virt-reset on the device zeroing 1 extents (1048576 each)

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu2:5526)J3: 2183: Aborting txn callerID: 0xc1d00006 due to failure pre-committing: IO was aborted by VMFS via a virt-reset on the device

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.203 cpu3:5524)FS3: 7346: Waiting for timed-out heartbeat [http://HB state abcdef02 offset 3940352 gen 13 stamp 184608197617 uuid 4c6157ec-acd14760-4bac-0016358085fe jrnl <FB 600> drv 8.46|http://HB state abcdef02 offset 3940352 gen 13 stamp 184608197617 uuid 4c6157ec-acd14760-4bac-0016358085fe jrnl <FB 600> drv 8.46]

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.241 cpu3:5445)WARNING: iscsi_vmk: iscsivmk_ConnSetupScsiResp: vmhba33:CH:0 T:0 CN:0: SCSI Response PDU: Referenced task not found: itt 0x35f6

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.241 cpu3:5445)WARNING: iscsi_vmk: iscsivmk_ConnSetupScsiResp: Sess

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.241 cpu3:5445)WARNING: iscsi_vmk: iscsivmk_ConnSetupScsiResp: Conn

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.241 cpu3:5445)iscsi_vmk: iscsivmk_ConnRxNotifyFailure: vmhba33:CH:0 T:0 CN:0: Connection rx notifying failure: SCSI Task Not Found. State=Online

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.241 cpu3:5445)iscsi_vmk: iscsivmk_ConnRxNotifyFailure: Sess

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.241 cpu3:5445)iscsi_vmk: iscsivmk_ConnRxNotifyFailure: Conn

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.241 cpu3:5445)WARNING: iscsi_vmk: iscsivmk_StopConnection: vmhba33:CH:0 T:0 CN:0: iSCSI connection is being marked "OFFLINE" (Event:6)

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.241 cpu3:5445)WARNING: iscsi_vmk: iscsivmk_StopConnection: Sess

Aug 12 18:01:27 dg1 vmkernel: 2:03:16:48.241 cpu3:5445)WARNING: iscsi_vmk: iscsivmk_StopConnection: Conn

Can someone provide guidance on how I should try to debug this problem?

Thanks for your help in advance.

[thausmann]

Hello raining,

i have a similar problem with an ESXi 4.0 host and IET. This happens after a while of using the IET storage or when load take place on the iscsi storage.

Take a look at:

I have made changes yesterday but i have now result yet. At this time i have seen no abort erros in the log.

I hope that help you