FC problems mit ESX 4.1 on BL25p G2

[Stephan Grallert]

Dear friends!

Just installed two fresh servers with ESX4.1 and ran into massive FC problems. When the second ESX is booting up, the first one looses the LUN from the storage, presuambly due to massive SCSI reservation conflicts, even the port goes down:

Aug 17 13:20:02 esx3 vmkernel: 0:00:25:07.526 cpu2:4214)<3> rport-2:0-0: blocked FC remote port time out: saving binding
Aug 17 13:20:02 esx3 vmkernel: 0:00:25:07.864 cpu2:4098)NMP: nmp_CompleteCommandForPath: Command 0x12 (0x4102bf9e6040) to NMP device "naa.60a980005672482f694a594d77464e31" failed on physical path "vmhba0:C0:T0:L0" H:0x1 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0.
Aug 17 13:20:02 esx3 vmkernel: 0:00:25:07.864 cpu2:4098)WARNING: NMP: nmp_DeviceRetryCommand: Device "naa.60a980005672482f694a594d77464e31": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.
Aug 17 13:20:02 esx3 vmkernel: 0:00:25:07.864 cpu3:4217)WARNING: NMP: nmpDeviceAttemptFailover: Retry world failover device "naa.60a980005672482f694a594d77464e31" - issuing command 0x4102bf9e6040
Aug 17 13:20:02 esx3 vmkernel: 0:00:25:07.864 cpu3:4217)WARNING: NMP: nmpDeviceAttemptFailover: Retry world failover device "naa.60a980005672482f694a594d77464e31" - failed to issue command due to Not found (APD), try again...
Aug 17 13:20:02 esx3 vmkernel: 0:00:25:07.864 cpu3:4217)WARNING: NMP: nmpDeviceAttemptFailover: Logical device "naa.60a980005672482f694a594d77464e31": awaiting fast path state update...
Aug 17 13:20:02 esx3 vmkernel: 0:00:25:07.929 cpu2:4106)NMP: nmp_CompleteCommandForPath: Command 0x12 (0x4102bf9b4940) to NMP device "mpx.vmhba2:C0:T0:L0" failed on physical path "vmhba2:C0:T0:L0" H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:20:02 esx3 vmkernel: 0:00:25:07.929 cpu2:4106)ScsiDeviceIO: 1672: Command 0x12 to device "mpx.vmhba2:C0:T0:L0" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:20:37 esx3 vmkernel: 0:00:25:42.346 cpu1:4198)ScsiDeviceIO: 1672: Command 0x12 to device "naa.60a980005672482f694a594d77464e31" failed H:0x5 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0.
Aug 17 13:20:37 esx3 vmkernel: 0:00:25:42.346 cpu1:4198)WARNING: NMP: nmp_DeviceStartLoop: NMP Device "naa.60a980005672482f694a594d77464e31" is blocked. Not starting I/O from device.
Aug 17 13:20:37 esx3 vmkernel: 0:00:25:42.346 cpu2:4178)WARNING: VMW_VAAIP_NETAPP: netapp_claim_device: Inquiry to device naa.60a980005672482f694a594d77464e31 failed
Aug 17 13:20:37 esx3 vmkernel: 0:00:25:42.864 cpu2:4217)WARNING: NMP: nmpDeviceAttemptFailover: Retry world restore device "naa.60a980005672482f694a594d77464e31" - no more commands to retry
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)WARNING: NMP: nmp_IssueCommandToDevice: I/O could not be issued to device "naa.60a980005672482f694a594d77464e31" due to Not found
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)ScsiDeviceIO: 1672: Command 0x25 to device "naa.60a980005672482f694a594d77464e31" failed H:0x1 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)WARNING: ScsiCore: 1399: Invalid sense buffer: error=0x0, valid=0x0, segment=0x0, key=0x5
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)WARNING: NMP: nmp_IssueCommandToDevice: I/O could not be issued to device "naa.60a980005672482f694a594d77464e31" due to Not found
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)ScsiDeviceIO: 1672: Command 0x1a to device "naa.60a980005672482f694a594d77464e31" failed H:0x1 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)WARNING: ScsiDeviceIO: 4555: QErr set to 0x0 for device naa.60a980005672482f694a594d77464e31. This may cause unexpected behavior.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)WARNING: ScsiDeviceIO: 4558: The device was originally configured to the supported QErr setting of 0x0, but this has been changed and could not be reset.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)WARNING: ScsiDeviceIO: 5172: READ CAPACITY on device "naa.60a980005672482f694a594d77464e31" from Plugin "NMP" failed. I/O error
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)WARNING: NMP: nmp_IssueCommandToDevice: I/O could not be issued to device "naa.60a980005672482f694a594d77464e31" due to Not found
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)ScsiDeviceIO: 1672: Command 0x25 to device "naa.60a980005672482f694a594d77464e31" failed H:0x1 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)WARNING: ScsiCore: 1399: Invalid sense buffer: error=0x0, valid=0x0, segment=0x0, key=0x5
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)WARNING: NMP: nmp_IssueCommandToDevice: I/O could not be issued to device "naa.60a980005672482f694a594d77464e31" due to Not found
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)ScsiDeviceIO: 1672: Command 0x1a to device "naa.60a980005672482f694a594d77464e31" failed H:0x1 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.239 cpu3:4108)WARNING: ScsiDeviceIO: 5172: READ CAPACITY on device "naa.60a980005672482f694a594d77464e31" from Plugin "NMP" failed. I/O error
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)WARNING: NMP: nmp_IssueCommandToDevice: I/O could not be issued to device "naa.60a980005672482f694a594d77464e31" due to Not found
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)ScsiDeviceIO: 1672: Command 0x25 to device "naa.60a980005672482f694a594d77464e31" failed H:0x1 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)WARNING: ScsiCore: 1399: Invalid sense buffer: error=0x0, valid=0x1, segment=0x0, key=0x5
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)WARNING: NMP: nmp_IssueCommandToDevice: I/O could not be issued to device "naa.60a980005672482f694a594d77464e31" due to Not found
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)ScsiDeviceIO: 1672: Command 0x1a to device "naa.60a980005672482f694a594d77464e31" failed H:0x1 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)WARNING: ScsiDeviceIO: 5172: READ CAPACITY on device "naa.60a980005672482f694a594d77464e31" from Plugin "NMP" failed. I/O error
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)Vol3: 1604: Could not open device 'naa.60a980005672482f694a594d77464e31:1' for probing: I/O error
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)WARNING: NMP: nmp_IssueCommandToDevice: I/O could not be issued to device "naa.60a980005672482f694a594d77464e31" due to Not found
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)ScsiDeviceIO: 1672: Command 0x25 to device "naa.60a980005672482f694a594d77464e31" failed H:0x1 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)WARNING: ScsiCore: 1399: Invalid sense buffer: error=0x0, valid=0x1, segment=0x0, key=0x5
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)WARNING: NMP: nmp_IssueCommandToDevice: I/O could not be issued to device "naa.60a980005672482f694a594d77464e31" due to Not found
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)ScsiDeviceIO: 1672: Command 0x1a to device "naa.60a980005672482f694a594d77464e31" failed H:0x1 D:0x0 P:0x0 Possible sense data: 0x5 0x20 0x0.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)WARNING: ScsiDeviceIO: 5172: READ CAPACITY on device "naa.60a980005672482f694a594d77464e31" from Plugin "NMP" failed. I/O error
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)Vol3: 644: Could not open device 'naa.60a980005672482f694a594d77464e31:1' for volume open: I/O error
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)FSS: 3924: No FS driver claimed device 'naa.60a980005672482f694a594d77464e31:1': Not supported
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)Vol3: 1604: Could not open device '4c630b9d-a0d19896-2358-0019bb372d2e' for probing: No such target on adapter
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)Vol3: 644: Could not open device '4c630b9d-a0d19896-2358-0019bb372d2e' for volume open: No such target on adapter
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.240 cpu3:4108)FSS: 3924: No FS driver claimed device '4c630b9d-a0d19896-2358-0019bb372d2e': Not supported
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.411 cpu3:4108)NMP: nmp_CompleteCommandForPath: Command 0x12 (0x4102bf9f2840) to NMP device "mpx.vmhba2:C0:T0:L0" failed on physical path "vmhba2:C0:T0:L0" H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:22:19 esx3 vmkernel: 0:00:27:24.411 cpu3:4108)ScsiDeviceIO: 1672: Command 0x12 to device "mpx.vmhba2:C0:T0:L0" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:24:07 esx3 vmkernel: 0:00:29:12.186 cpu3:4099)<4>qla2xxx 0000:02:03.0: Loop down - aborting ISP.
Aug 17 13:24:07 esx3 vmkernel: 0:00:29:12.186 cpu1:4220)<6>qla2xxx 0000:02:03.0: Performing ISP error recovery - ha= 0x41000e002538.
Aug 17 13:24:12 esx3 vmkernel: 0:00:29:17.111 cpu1:4220)<6>qla2xxx 0000:02:03.0: LOOP UP detected (2 Gbps).
Aug 17 13:24:12 esx3 vmkernel: 0:00:29:17.606 cpu3:4122)WARNING: ScsiCore: 1353: Power-on Reset occurred on vmhba0:C0:T0:L0
Aug 17 13:24:12 esx3 vmkernel: 0:00:29:17.607 cpu3:4122)vmw_psp_fixed: psp_fixedSelectPathToActivateInt: Changing active path from NONE to vmhba0:C0:T0:L0 for device "naa.60a980005672482f694a594d77464e31".
Aug 17 13:24:12 esx3 vmkernel: 0:00:29:17.670 cpu3:4108)NMP: nmp_CompleteCommandForPath: Command 0x12 (0x4102bf9b6240) to NMP device "mpx.vmhba2:C0:T0:L0" failed on physical path "vmhba2:C0:T0:L0" H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:24:12 esx3 vmkernel: 0:00:29:17.670 cpu3:4108)ScsiDeviceIO: 1672: Command 0x12 to device "mpx.vmhba2:C0:T0:L0" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:24:57 esx3 vmkernel: 0:00:30:02.346 cpu3:4174)VMW_VAAIP_NETAPP: netapp_claim_device: Device naa.60a980005672482f694a594d77464e31 (NETAPP :LUN ) not supported
Aug 17 13:27:13 esx3 vmkernel: 0:00:32:18.441 cpu2:4106)NMP: nmp_CompleteCommandForPath: Command 0x12 (0x4102bf9f0840) to NMP device "mpx.vmhba2:C0:T0:L0" failed on physical path "vmhba2:C0:T0:L0" H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:27:13 esx3 vmkernel: 0:00:32:18.441 cpu2:4106)ScsiDeviceIO: 1672: Command 0x12 to device "mpx.vmhba2:C0:T0:L0" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:27:28 esx3 vmkernel: 0:00:32:33.859 cpu2:4106)NMP: nmp_CompleteCommandForPath: Command 0x12 (0x4102bf9e6d40) to NMP device "mpx.vmhba2:C0:T0:L0" failed on physical path "vmhba2:C0:T0:L0" H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:27:28 esx3 vmkernel: 0:00:32:33.859 cpu2:4106)ScsiDeviceIO: 1672: Command 0x12 to device "mpx.vmhba2:C0:T0:L0" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:28:04 esx3 vmkernel: 0:00:33:09.772 cpu2:4108)ScsiScan: 1059: Path 'vmhba0:C0:T0:L0': Vendor: 'NETAPP ' Model: 'LUN ' Rev: '7320'
Aug 17 13:28:04 esx3 vmkernel: 0:00:33:09.772 cpu2:4108)ScsiScan: 1062: Path 'vmhba0:C0:T0:L0': Type: 0x0, ANSI rev: 4, TPGS: 0 (none)
Aug 17 13:28:04 esx3 vmkernel: 0:00:33:09.837 cpu2:4107)NMP: nmp_CompleteCommandForPath: Command 0x12 (0x4102bf9e0540) to NMP device "mpx.vmhba2:C0:T0:L0" failed on physical path "vmhba2:C0:T0:L0" H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:28:04 esx3 vmkernel: 0:00:33:09.837 cpu2:4107)ScsiDeviceIO: 1672: Command 0x12 to device "mpx.vmhba2:C0:T0:L0" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:28:33 esx3 vmkernel: 0:00:33:38.581 cpu3:4201)<3> rport-2:0-0: blocked FC remote port time out: saving binding
Aug 17 13:28:33 esx3 vmkernel: 0:00:33:38.644 cpu2:4108)NMP: nmp_CompleteCommandForPath: Command 0x12 (0x4102bf9dee40) to NMP device "mpx.vmhba2:C0:T0:L0" failed on physical path "vmhba2:C0:T0:L0" H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.
Aug 17 13:28:33 esx3 vmkernel: 0:00:33:38.644 cpu2:4108)ScsiDeviceIO: 1672: Command 0x12 to device "mpx.vmhba2:C0:T0:L0" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.

Storage is NetApp FAS960c with Data Ontap 7.2.6.1, the host is Proliant BL25 G2

According to VMWare HCL, this host is only supported until ESX 3.5. However I have two other systems running fine on that hosts with ESX 4.0. It must be something in the storage driver, but I could not find anything in the release notes of 4.1

Anybody had similar problems?

Thanx and greetings,
Stephan

[Jan Soska]

Hello,
we had similar issue causing EVA controllers reboots! after upgrading from ESX3.5 to ESX4 on our bl685c's
I am not saying it was exact the same issue but here is what helped us (Brocade SAN & Eva6000 ):
1) setup prefered path/owning controller for each LUN presented to ESX on your storage (if possible, do no know NetApp)
2) check multipath settings on your ESX and set Roud Robin.
3) upgrade SAN fabric to latest available (very helpfull in our case 6.1.0c -> 6.2.2b, solved all port errors)

maybe this helps...
Jan