VMware Cloud Community
mune3b
Enthusiast
Enthusiast

iSCSI Connectivity issues

Greetings,

     This is a lab environment. ESXi 6.7 version is running on Dell R710 SFF Server. We created a storage on another Dell R710 LFF with a capacity of 8 TB one volume and 5 TB one volume as virtual disks. Using 5 TB virtual disk and FreeNAS we created an iSCSI Target on top of it. Now we are trying to setup the iSCSI storage and datastore as one Dell R710 SFF is acting as initiator and other Dell R710 LFF acting as a target.

Initiator (10.39.130.35) Dell R710 SFF specifications:

vCPUs 12 with 96 GB RAM

VMKernal2 with MTU 9000 and vDS with MTU of 9000


Target (10.39.130.222 iqn.2005-10.org.freenas.ctl:all-esxi) Dell R710 LFF specifications:

vCPUs 8 and 128 GB RAM

FreeNAS with em1 and MTU of 9000

Issue: The iSCSI Target is getting timeout and Disk is getting ONLINE and OFFLINE intermittently

Below are the logs of esxi vmkernal.log

[root@esxi1:~] cat /var/log/vmkernel.log

2019-05-07T17:48:32.912Z cpu4:2247842)Vol3: 1255: Could not open device '5cc6f8b0-8e513860-6903-0026b93f7b73' for volume open: Failure

2019-05-07T17:48:32.912Z cpu4:2247842)LVM: 5919: Could not open device naa.6589cfc000000f7547481ec53d72549e:1, vol [5cc6f8b0-8e513860-6903-0026b93f7b73, 5cc6f8b0-8e513860-6903-0026b93f7b73, 1]: LVM device unreachable

2019-05-07T17:48:32.912Z cpu4:2247842)Vol3: 1255: Could not open device '5cc6f8b0-8e513860-6903-0026b93f7b73' for volume open: Failure

2019-05-07T17:48:32.912Z cpu4:2247842)LVM: 5919: Could not open device naa.6589cfc000000f7547481ec53d72549e:1, vol [5cc6f8b0-8e513860-6903-0026b93f7b73, 5cc6f8b0-8e513860-6903-0026b93f7b73, 1]: LVM device unreachable

2019-05-07T17:48:32.912Z cpu4:2247842)FSS: 6092: No FS driver claimed device '5cc6f8b0-8e513860-6903-0026b93f7b73': No filesystem on the device

2019-05-07T17:48:32.918Z cpu0:2098497)PLOG: PLOGOpenDevice:4346: Disk handle open failure for device naa.6782bcb05bcabf0021f7e31c06bb079d:2, status:Busy

2019-05-07T17:48:32.919Z cpu0:2098497)PLOG: PLOGInitAndAnnounceMD:7958: Successfully announced VSAN MD (naa.6782bcb05bcabf0021f7e31c06bb079d:2) with UUID: 5259f2c5-80bd-17b5-20c5-77b4fd68b317. kt 1, en 0, enC 0.

2019-05-07T17:48:32.922Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:32.922Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:32.922Z cpu4:2097199)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16b2 from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:32.933Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:32.933Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:32.933Z cpu4:2097199)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16b4 from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:32.942Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:32.942Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:32.942Z cpu4:2097199)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16b6 from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:32.954Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:32.954Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:32.954Z cpu4:2097199)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16b8 from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:32.965Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:32.965Z cpu9:2247840)WARNING: NFS: 1227: Invalid volume UUID mpx.vmhba1:C0:T0:L0

2019-05-07T17:48:32.965Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:32.965Z cpu4:2097199)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16ba from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:32.976Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:32.977Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:32.977Z cpu4:2097199)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16bc from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:32.995Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:32.995Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:32.995Z cpu4:2097199)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16be from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:33.005Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:33.005Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:33.005Z cpu4:2097199)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16c5 from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:33.017Z cpu4:2097199)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:33.017Z cpu9:2097204)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:33.017Z cpu9:2097204)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16c7 from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:33.026Z cpu9:2097204)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:33.026Z cpu9:2097204)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:33.026Z cpu9:2097204)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16c9 from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:33.038Z cpu9:2097204)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:33.038Z cpu9:2097204)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:33.038Z cpu9:2097204)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16cb from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:33.047Z cpu9:2097204)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:33.047Z cpu9:2097204)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x9e (0x459b98d365c0, 0) to dev "mpx.vmhba1:C0:T0:L0" on path "vmhba1:C0:T0:L0" Failed: H:0x7 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:48:33.047Z cpu9:2097204)ScsiDeviceIO: 3082: Cmd(0x459b98d365c0) 0x9e, CmdSN 0x16cd from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x7 D:0x0 P:0x0 Invalid sense data: 0x73 0x65 0x20.

2019-05-07T17:48:33.055Z cpu9:2097204)NMP: nmp_ThrottleLogForDevice:3727: last error status from device mpx.vmhba1:C0:T0:L0 repeated 2 times

2019-05-07T17:48:33.059Z cpu4:2247840)FSS: 6092: No FS driver claimed device 'mpx.vmhba1:C0:T0:L0': No filesystem on the device

2019-05-07T17:48:34.438Z cpu1:2097196)ScsiDeviceIO: 3068: Cmd(0x459b98d97dc0) 0x1a, CmdSN 0x1716 from world 0 to dev "t10.SanDisk00Ultra_USB_3.00000004C530000261203102470" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.

2019-05-07T17:48:34.543Z cpu4:2100460 opID=46e20a1f)VC: 4616: Device rescan time 10157 msec (total number of devices 6)

2019-05-07T17:48:34.543Z cpu4:2100460 opID=46e20a1f)VC: 4619: Filesystem probe time 1628 msec (devices probed 5 of 6)

2019-05-07T17:48:34.543Z cpu4:2100460 opID=46e20a1f)VC: 4621: Refresh open volume time 4 msec

2019-05-07T17:49:04.106Z cpu13:2097835)NMP: nmp_ResetDeviceLogThrottling:3569: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x2 0x3a 0x1 from dev "mpx.vmhba1:C0:T0:L0" occurred 1 times(of 1 commands)

2019-05-07T17:49:19.107Z cpu2:2098823)SunRPC: 1099: Destroying world 0x224cfe

2019-05-07T17:49:34.107Z cpu7:2097507)ScsiVmas: 804: Inquiry for VPD page 00 to device naa.6589cfc000000f7547481ec53d72549e failed with error No connection

2019-05-07T17:49:34.963Z cpu6:2097201)ScsiDeviceIO: 3068: Cmd(0x459b8aafa700) 0x1a, CmdSN 0x1722 from world 0 to dev "mpx.vmhba1:C0:T0:L0" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.

2019-05-07T17:50:22.108Z cpu1:2098823)SunRPC: 1099: Destroying world 0x224dfd

2019-05-07T17:51:17.038Z cpu17:2097726)iscsi_vmk: iscsivmk_ConnTxNotifyFailure:1197: vmhba65:CH:0 T:1 CN:0: Connection tx notifying failure: Network Send Error. State=Online

2019-05-07T17:51:17.038Z cpu17:2097726)iscsi_vmk: iscsivmk_ConnTxNotifyFailure:1198: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:51:17.038Z cpu17:2097726)iscsi_vmk: iscsivmk_ConnTxNotifyFailure:1199: Conn [CID: 0 L: 10.39.130.35:10848 R: 10.39.130.222:3260]

2019-05-07T17:51:17.038Z cpu16:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:699: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "OFFLINE" (Event:6)

2019-05-07T17:51:17.038Z cpu16:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:700: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:51:17.038Z cpu16:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:701: Conn [CID: 0 L: 10.39.130.35:10848 R: 10.39.130.222:3260]

2019-05-07T17:51:17.041Z cpu18:2097547)WARNING: iscsi_vmk: iscsivmk_TaskMgmtIssue:633: vmhba65:CH:0 T:1 L:70 : Task mgmt "Abort Task" with itt=0xa47 (refITT=0xa3e) timed out.

2019-05-07T17:51:17.041Z cpu18:2097547)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x89 (0x459a40c1d280, 2097185) to dev "naa.6589cfc0000002975052862c22403cca" on path "vmhba65:C0:T1:L70" Failed: H:0x5 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:51:17.041Z cpu18:2097547)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe:237: NMP device "naa.6589cfc0000002975052862c22403cca" state in doubt; requested fast path state update...

2019-05-07T17:51:17.041Z cpu16:2097705)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x28 (0x45a37d996b40, 2098280) to dev "naa.6589cfc0000002975052862c22403cca" on path "vmhba65:C0:T1:L70" Failed: H:0x2 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:51:17.041Z cpu18:2097547)ScsiDeviceIO: 3082: Cmd(0x459a40c1d280) 0x89, CmdSN 0x6d from world 2097185 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x5 D:0x0 P:0x0 Invalid sense data: 0x0 0x35 0x20.

2019-05-07T17:51:17.041Z cpu16:2097705)ScsiDeviceIO: 3047: Cmd(0x45a37d996b40) 0x28, CmdSN 0x6c from world 2098280 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x78 0x32 0x20.

2019-05-07T17:51:17.042Z cpu16:2097211)ScsiDeviceIO: 3047: Cmd(0x459b98c86580) 0x28, CmdSN 0x6e from world 2100138 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x9 0x1a 0x45.

2019-05-07T17:51:17.106Z cpu16:2097705)NMP: nmp_ThrottleLogForDevice:3710: last error status from device naa.6589cfc0000002975052862c22403cca repeated 10 times

2019-05-07T17:51:17.110Z cpu8:2097505)LVM: 5748: Received APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 17)

2019-05-07T17:51:17.110Z cpu8:2097505)LVM: 5356: Handling APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 17, cur apd state UNKNOWN, cur dev state 1)

2019-05-07T17:51:17.110Z cpu8:2097505)HBX: 6287: APD EventType: APD_START (3) for vol 'SAN-PRODUCTION'

2019-05-07T17:51:17.110Z cpu8:2097505)ScsiDevice: 5978: Device state of naa.6589cfc0000002975052862c22403cca set to APD_START; token num:1

2019-05-07T17:51:17.110Z cpu8:2097505)StorageApdHandler: 1203: APD start for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:51:17.110Z cpu0:2097490)StorageApdHandler: 419: APD start event for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:51:17.110Z cpu0:2097490)StorageApdHandlerEv: 110: Device or filesystem with identifier [naa.6589cfc0000002975052862c22403cca] has entered the All Paths Down state.

2019-05-07T17:51:17.112Z cpu2:2098234)WARNING: NMP: nmp_IssueCommandToDevice:5082: I/O could not be issued to device "naa.6589cfc0000002975052862c22403cca" due to Not found

2019-05-07T17:51:17.112Z cpu2:2098234)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2019-05-07T17:51:17.112Z cpu2:2098234)WARNING: NMP: nmp_DeviceStartLoop:729: NMP Device "naa.6589cfc0000002975052862c22403cca" is blocked. Not starting I/O from device.

2019-05-07T17:51:18.040Z cpu12:2097547)ScsiDeviceIO: 3082: Cmd(0x459b98ce9f40) 0x89, CmdSN 0x6f from world 2097185 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x5 D:0x0 P:0x0 Invalid sense data: 0x18 0x4 0x43.

2019-05-07T17:51:18.040Z cpu12:2097547)WARNING: NMP: nmp_DeviceStartLoop:729: NMP Device "naa.6589cfc0000002975052862c22403cca" is blocked. Not starting I/O from device.

2019-05-07T17:51:18.040Z cpu9:2097204)ScsiDeviceIO: 3032: Cmd(0x45a37d996b40) 0x28, CmdSN 0x6c from world 2098280 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x8 D:0x0 P:0x0

2019-05-07T17:51:18.041Z cpu9:2097204)ScsiDeviceIO: 3032: Cmd(0x459b98c86580) 0x28, CmdSN 0x6e from world 2100138 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x8 D:0x0 P:0x0

2019-05-07T17:51:18.041Z cpu12:2098281)HBX: 3033: 'SAN-PRODUCTION': HB at offset 3407872 - Waiting for timed out HB:

2019-05-07T17:51:18.041Z cpu12:2098281)  [HB state abcdef02 offset 3407872 gen 37 stampUS 24703934162 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 4> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:51:18.110Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:603: Retry world restore device "naa.6589cfc0000002975052862c22403cca" - no more commands to retry

2019-05-07T17:51:19.331Z cpu11:2248652)HBX: 3033: 'SAN-PRODUCTION': HB at offset 3407872 - Waiting for timed out HB:

2019-05-07T17:51:19.331Z cpu11:2248652)  [HB state abcdef02 offset 3407872 gen 37 stampUS 24703934162 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 4> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:51:20.146Z cpu22:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2170: socket 0x430bd54cc9f0 network resource pool netsched.pools.persist.iscsi associated

2019-05-07T17:51:20.146Z cpu22:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2198: socket 0x430bd54cc9f0 network tracker id 45045162 tracker.iSCSI.10.39.130.222 associated

2019-05-07T17:51:20.398Z cpu22:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:880: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "ONLINE"

2019-05-07T17:51:20.398Z cpu22:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:881: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:51:20.398Z cpu22:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:882: Conn [CID: 0 L: 10.39.130.35:56605 R: 10.39.130.222:3260]

2019-05-07T17:51:20.541Z cpu2:2100195)WARNING: NMP: nmp_IssueCommandToDevice:5082: I/O could not be issued to device "naa.6589cfc0000002975052862c22403cca" due to Not found

2019-05-07T17:51:20.541Z cpu2:2100195)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2019-05-07T17:51:20.542Z cpu2:2100195)WARNING: NMP: nmp_DeviceStartLoop:729: NMP Device "naa.6589cfc0000002975052862c22403cca" is blocked. Not starting I/O from device.

2019-05-07T17:51:21.114Z cpu5:2097505)ScsiDevice: 6000: Setting Device naa.6589cfc0000002975052862c22403cca state back to 0x2

2019-05-07T17:51:21.114Z cpu5:2097505)LVM: 5748: Received APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 18)

2019-05-07T17:51:21.114Z cpu5:2097505)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 18, cur apd state APD_START, cur dev state 1)

2019-05-07T17:51:21.114Z cpu5:2097505)ScsiDevice: 6021: Device naa.6589cfc0000002975052862c22403cca is Out of APD; token num:1

2019-05-07T17:51:21.114Z cpu0:2097255)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (locked, gen 18, cur apd state APD_START, cur dev state 1)

2019-05-07T17:51:21.114Z cpu1:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459a40d93740

2019-05-07T17:51:24.463Z cpu16:2097211)NMP: nmpCompleteRetryForPath:327: Retry world recovered device "naa.6589cfc0000002975052862c22403cca"

2019-05-07T17:51:25.110Z cpu0:2098823)SunRPC: 3303: Synchronous RPC abort for client 0x4305cc2271c0 IP 10.39.115.222.0.111 proc 3 xid 0x439cd42c attempt 3 of 3

2019-05-07T17:51:25.110Z cpu0:2098823)SunRPC: 1099: Destroying world 0x224fd9

2019-05-07T17:51:29.332Z cpu1:2248652)HBX: 3033: 'SAN-PRODUCTION': HB at offset 3407872 - Waiting for timed out HB:

2019-05-07T17:51:29.332Z cpu1:2248652)  [HB state abcdef02 offset 3407872 gen 37 stampUS 24703934162 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 4> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:51:33.390Z cpu13:2098820)WARNING: LSOM: LSOMVsiGetVirstoInstanceStats:800: Throttled: Attempt to get Virsto stats on unsupported disk52256481-aa44-4783-d2f0-625461b41dfe

2019-05-07T17:51:39.335Z cpu1:2248652)HBX: 3033: 'SAN-PRODUCTION': HB at offset 3407872 - Waiting for timed out HB:

2019-05-07T17:51:39.335Z cpu1:2248652)  [HB state abcdef02 offset 3407872 gen 37 stampUS 24703934162 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 4> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:51:46.272Z cpu20:2097729)iscsi_vmk: iscsivmk_ConnTxNotifyFailure:1197: vmhba65:CH:0 T:1 CN:0: Connection tx notifying failure: Network Send Error. State=Online

2019-05-07T17:51:46.272Z cpu20:2097729)iscsi_vmk: iscsivmk_ConnTxNotifyFailure:1198: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:51:46.272Z cpu20:2097729)iscsi_vmk: iscsivmk_ConnTxNotifyFailure:1199: Conn [CID: 0 L: 10.39.130.35:56605 R: 10.39.130.222:3260]

2019-05-07T17:51:46.272Z cpu18:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:699: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "OFFLINE" (Event:6)

2019-05-07T17:51:46.272Z cpu18:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:700: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:51:46.272Z cpu18:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:701: Conn [CID: 0 L: 10.39.130.35:56605 R: 10.39.130.222:3260]

2019-05-07T17:51:46.281Z cpu18:2097707)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe:237: NMP device "naa.6589cfc0000002975052862c22403cca" state in doubt; requested fast path state update...

2019-05-07T17:51:46.281Z cpu18:2097707)ScsiDeviceIO: 3047: Cmd(0x459a40cde840) 0x28, CmdSN 0x73 from world 0 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x43.

2019-05-07T17:51:46.281Z cpu18:2097707)ScsiDeviceIO: 3047: Cmd(0x459b98d932c0) 0x12, CmdSN 0x1782 from world 0 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x43.

2019-05-07T17:51:46.394Z cpu18:2097707)NMP: nmp_ThrottleLogForDevice:3710: last error status from device naa.6589cfc0000002975052862c22403cca repeated 20 times

2019-05-07T17:51:46.645Z cpu18:2097707)NMP: nmp_ThrottleLogForDevice:3710: last error status from device naa.6589cfc0000002975052862c22403cca repeated 40 times

2019-05-07T17:51:47.111Z cpu0:2097505)LVM: 5748: Received APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 19)

2019-05-07T17:51:47.111Z cpu0:2097505)LVM: 5356: Handling APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 19, cur apd state APD_START, cur dev state 1)

2019-05-07T17:51:47.111Z cpu0:2097505)WARNING: LVM: 5375: Pre-existing unhandled APD event for device <naa.6589cfc0000002975052862c22403cca:3>: type APD_EXIT (gen 18)

2019-05-07T17:51:47.111Z cpu0:2097505)StorageApdHandler: 1315: APD exit for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:51:47.111Z cpu0:2097505)HBX: 6287: APD EventType: APD_START (3) for vol 'SAN-PRODUCTION'

2019-05-07T17:51:47.111Z cpu0:2097505)ScsiDevice: 5978: Device state of naa.6589cfc0000002975052862c22403cca set to APD_START; token num:2

2019-05-07T17:51:47.111Z cpu0:2097505)StorageApdHandler: 1218: APD bounce-start for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca], no event transition

2019-05-07T17:51:47.118Z cpu18:2098469)WARNING: NMP: nmp_IssueCommandToDevice:5082: I/O could not be issued to device "naa.6589cfc0000002975052862c22403cca" due to Not found

2019-05-07T17:51:47.118Z cpu18:2098469)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2019-05-07T17:51:47.118Z cpu18:2098469)WARNING: NMP: nmp_DeviceStartLoop:729: NMP Device "naa.6589cfc0000002975052862c22403cca" is blocked. Not starting I/O from device.

2019-05-07T17:51:48.111Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459a40cde840

2019-05-07T17:51:48.111Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:715: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - failed to issue command due to Not found (APD), try again...

2019-05-07T17:51:48.111Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:765: Logical device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update...

2019-05-07T17:51:49.044Z cpu22:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2170: socket 0x430bd5546e80 network resource pool netsched.pools.persist.iscsi associated

2019-05-07T17:51:49.044Z cpu22:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2198: socket 0x430bd5546e80 network tracker id 45045162 tracker.iSCSI.10.39.130.222 associated

2019-05-07T17:51:49.111Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459a40cde840

2019-05-07T17:51:49.111Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:715: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - failed to issue command due to Not found (APD), try again...

2019-05-07T17:51:49.111Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:765: Logical device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update...

2019-05-07T17:51:49.298Z cpu22:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:880: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "ONLINE"

2019-05-07T17:51:49.298Z cpu22:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:881: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:51:49.298Z cpu22:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:882: Conn [CID: 0 L: 10.39.130.35:37059 R: 10.39.130.222:3260]

2019-05-07T17:51:49.339Z cpu3:2248652)HBX: 3033: 'SAN-PRODUCTION': HB at offset 3407872 - Waiting for timed out HB:

2019-05-07T17:51:49.339Z cpu3:2248652)  [HB state abcdef02 offset 3407872 gen 37 stampUS 24703934162 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 4> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:51:50.113Z cpu10:2097505)ScsiDevice: 6000: Setting Device naa.6589cfc0000002975052862c22403cca state back to 0x2

2019-05-07T17:51:50.113Z cpu10:2097505)LVM: 5748: Received APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 20)

2019-05-07T17:51:50.113Z cpu10:2097505)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 20, cur apd state APD_START, cur dev state 1)

2019-05-07T17:51:50.113Z cpu10:2097505)ScsiDevice: 6021: Device naa.6589cfc0000002975052862c22403cca is Out of APD; token num:1

2019-05-07T17:51:50.114Z cpu16:2098023)NMP: nmpCompleteRetryForPath:327: Retry world recovered device "naa.6589cfc0000002975052862c22403cca"

2019-05-07T17:51:53.614Z cpu4:2097255)LVM: 5425: Async handling of event APD_EXIT for device <naa.6589cfc0000002975052862c22403cca:3> took too long - bailing (my gen 18, cur gen 20, cur state APD_START)

2019-05-07T17:51:53.614Z cpu4:2097255)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (locked, gen 20, cur apd state APD_START, cur dev state 1)

2019-05-07T17:51:59.043Z cpu0:2097255)HBX: 6287: APD EventType: APD_EXIT (4) for vol 'SAN-PRODUCTION'

2019-05-07T17:51:59.043Z cpu0:2097255)LVM: 5487: Device <naa.6589cfc000000f7547481ec53d72549e:1> APD handler with closeOnAPDExit - attempting close.

2019-05-07T17:51:59.045Z cpu8:2098161)HBX: 312: 'SAN-PRODUCTION': HB at offset 3407872 - Reclaimed heartbeat [Timeout]:

2019-05-07T17:51:59.045Z cpu8:2098161)  [HB state abcdef02 offset 3407872 gen 37 stampUS 24744936741 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 4> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:51:59.045Z cpu8:2098161)StorageApdHandler: 1315: APD exit for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:51:59.045Z cpu8:2098161)HBX: 5509: Completed APD/PDL event processing on vol 'SAN-PRODUCTION'.

2019-05-07T17:51:59.045Z cpu0:2097490)StorageApdHandler: 507: APD exit event for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:51:59.045Z cpu0:2097490)StorageApdHandlerEv: 117: Device or filesystem with identifier [naa.6589cfc0000002975052862c22403cca] has exited the All Paths Down state.

2019-05-07T17:52:04.114Z cpu4:2097835)NMP: nmp_ResetDeviceLogThrottling:3569: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x24 0x0 from dev "mpx.vmhba1:C0:T0:L0" occurred 1 times(of 1 commands)

2019-05-07T17:52:26.114Z cpu2:2098823)SunRPC: 1099: Destroying world 0x2250fb

2019-05-07T17:52:34.112Z cpu8:2097835)NMP: nmp_ResetDeviceLogThrottling:3575: last error status from device naa.6589cfc0000002975052862c22403cca repeated 73 times

2019-05-07T17:52:58.437Z cpu14:2097918)ScsiDeviceIO: 3068: Cmd(0x45a24068ac40) 0x1a, CmdSN 0x17b8 from world 0 to dev "naa.6782bcb05bcabf0021f7e31c06bb079d" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.

2019-05-07T17:53:19.373Z cpu0:2248652)HBX: 3033: 'SAN-PRODUCTION': HB at offset 3407872 - Waiting for timed out HB:

2019-05-07T17:53:19.373Z cpu0:2248652)  [HB state abcdef02 offset 3407872 gen 37 stampUS 24811934158 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 4> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:53:24.048Z cpu12:2097547)WARNING: iscsi_vmk: iscsivmk_TaskMgmtIssue:633: vmhba65:CH:0 T:1 L:70 : Task mgmt "Abort Task" with itt=0xb3c (refITT=0xb3b) timed out.

2019-05-07T17:53:24.048Z cpu17:2097726)iscsi_vmk: iscsivmk_ConnTxNotifyFailure:1197: vmhba65:CH:0 T:1 CN:0: Connection tx notifying failure: Network Send Error. State=Online

2019-05-07T17:53:24.048Z cpu17:2097726)iscsi_vmk: iscsivmk_ConnTxNotifyFailure:1198: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:53:24.048Z cpu17:2097726)iscsi_vmk: iscsivmk_ConnTxNotifyFailure:1199: Conn [CID: 0 L: 10.39.130.35:37059 R: 10.39.130.222:3260]

2019-05-07T17:53:24.048Z cpu23:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:699: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "OFFLINE" (Event:6)

2019-05-07T17:53:24.048Z cpu23:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:700: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:53:24.048Z cpu23:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:701: Conn [CID: 0 L: 10.39.130.35:37059 R: 10.39.130.222:3260]

2019-05-07T17:53:24.052Z cpu12:2097547)WARNING: iscsi_vmk: iscsivmk_TaskMgmtIssue:633: vmhba65:CH:0 T:1 L:70 : Task mgmt "Abort Task" with itt=0xb3d (refITT=0xb3b) timed out.

2019-05-07T17:53:24.052Z cpu12:2097547)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x89 (0x459a40c8cf40, 2097185) to dev "naa.6589cfc0000002975052862c22403cca" on path "vmhba65:C0:T1:L70" Failed: H:0x5 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:53:24.052Z cpu12:2097547)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe:237: NMP device "naa.6589cfc0000002975052862c22403cca" state in doubt; requested fast path state update...

2019-05-07T17:53:24.052Z cpu23:2097218)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x28 (0x459b98d37c40, 2100138) to dev "naa.6589cfc0000002975052862c22403cca" on path "vmhba65:C0:T1:L70" Failed: H:0x2 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:53:24.052Z cpu12:2097547)ScsiDeviceIO: 3082: Cmd(0x459a40c8cf40) 0x89, CmdSN 0xae from world 2097185 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x5 D:0x0 P:0x0 Invalid sense data: 0x0 0x35 0x20.

2019-05-07T17:53:24.052Z cpu23:2097218)ScsiDeviceIO: 3047: Cmd(0x459b98d37c40) 0x28, CmdSN 0xad from world 2100138 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x78 0x32 0x20.

2019-05-07T17:53:24.052Z cpu8:2097697)ScsiDeviceIO: 3047: Cmd(0x459b98d76d00) 0x28, CmdSN 0xaf from world 0 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x2 0x80 0x41.

2019-05-07T17:53:24.114Z cpu1:2097505)LVM: 5748: Received APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 21)

2019-05-07T17:53:24.114Z cpu1:2097505)LVM: 5356: Handling APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 21, cur apd state UNKNOWN, cur dev state 1)

2019-05-07T17:53:24.114Z cpu1:2097505)HBX: 6287: APD EventType: APD_START (3) for vol 'SAN-PRODUCTION'

2019-05-07T17:53:24.114Z cpu1:2097505)ScsiDevice: 5978: Device state of naa.6589cfc0000002975052862c22403cca set to APD_START; token num:1

2019-05-07T17:53:24.114Z cpu1:2097505)StorageApdHandler: 1203: APD start for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:53:24.114Z cpu0:2097490)StorageApdHandler: 419: APD start event for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:53:24.114Z cpu0:2097490)StorageApdHandlerEv: 110: Device or filesystem with identifier [naa.6589cfc0000002975052862c22403cca] has entered the All Paths Down state.

2019-05-07T17:53:24.120Z cpu8:2097183)WARNING: NMP: nmp_IssueCommandToDevice:5082: I/O could not be issued to device "naa.6589cfc0000002975052862c22403cca" due to Not found

2019-05-07T17:53:24.120Z cpu8:2097183)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2019-05-07T17:53:24.120Z cpu8:2097183)WARNING: NMP: nmp_DeviceStartLoop:729: NMP Device "naa.6589cfc0000002975052862c22403cca" is blocked. Not starting I/O from device.

2019-05-07T17:53:25.114Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459b98d76d00

2019-05-07T17:53:25.114Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:715: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - failed to issue command due to Not found (APD), try again...

2019-05-07T17:53:25.114Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:765: Logical device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update...

2019-05-07T17:53:26.113Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459b98d76d00

2019-05-07T17:53:26.114Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:715: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - failed to issue command due to Not found (APD), try again...

2019-05-07T17:53:26.114Z cpu0:2097836)WARNING: NMP: nmpDeviceAttemptFailover:765: Logical device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update...

2019-05-07T17:53:26.559Z cpu12:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2170: socket 0x430bd5546e80 network resource pool netsched.pools.persist.iscsi associated

2019-05-07T17:53:26.559Z cpu12:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2198: socket 0x430bd5546e80 network tracker id 45045162 tracker.iSCSI.10.39.130.222 associated

2019-05-07T17:53:26.811Z cpu12:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:880: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "ONLINE"

2019-05-07T17:53:26.811Z cpu12:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:881: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:53:26.811Z cpu12:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:882: Conn [CID: 0 L: 10.39.130.35:31611 R: 10.39.130.222:3260]

2019-05-07T17:53:27.117Z cpu3:2097505)ScsiDevice: 6000: Setting Device naa.6589cfc0000002975052862c22403cca state back to 0x2

2019-05-07T17:53:27.117Z cpu3:2097505)LVM: 5748: Received APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 22)

2019-05-07T17:53:27.117Z cpu3:2097505)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 22, cur apd state APD_START, cur dev state 1)

2019-05-07T17:53:27.117Z cpu3:2097505)ScsiDevice: 6021: Device naa.6589cfc0000002975052862c22403cca is Out of APD; token num:1

2019-05-07T17:53:27.117Z cpu0:2097255)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (locked, gen 22, cur apd state APD_START, cur dev state 1)

2019-05-07T17:53:27.117Z cpu15:2098023)NMP: nmpCompleteRetryForPath:327: Retry world recovered device "naa.6589cfc0000002975052862c22403cca"

2019-05-07T17:53:27.347Z cpu8:2098161)HBX: 312: 'SAN-PRODUCTION': HB at offset 3407872 - Reclaimed heartbeat [Timeout]:

2019-05-07T17:53:27.347Z cpu8:2098161)  [HB state abcdef02 offset 3407872 gen 37 stampUS 24833007489 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 4> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:53:28.113Z cpu0:2098823)SunRPC: 1099: Destroying world 0x2252a2

2019-05-07T17:53:33.286Z cpu0:2097255)HBX: 6287: APD EventType: APD_EXIT (4) for vol 'SAN-PRODUCTION'

2019-05-07T17:53:33.286Z cpu0:2097255)StorageApdHandler: 1315: APD exit for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:53:33.286Z cpu0:2097255)HBX: 5509: Completed APD/PDL event processing on vol 'SAN-PRODUCTION'.

2019-05-07T17:53:33.286Z cpu0:2097255)LVM: 5487: Device <naa.6589cfc000000f7547481ec53d72549e:1> APD handler with closeOnAPDExit - attempting close.

2019-05-07T17:53:33.286Z cpu2:2097490)StorageApdHandler: 507: APD exit event for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:53:33.286Z cpu2:2097490)StorageApdHandlerEv: 117: Device or filesystem with identifier [naa.6589cfc0000002975052862c22403cca] has exited the All Paths Down state.

2019-05-07T17:54:04.114Z cpu2:2097835)NMP: nmp_ResetDeviceLogThrottling:3575: last error status from device naa.6589cfc0000002975052862c22403cca repeated 5 times

2019-05-07T17:54:08.519Z cpu15:2097918)ScsiDeviceIO: 3068: Cmd(0x45a240703b40) 0x1a, CmdSN 0x1819 from world 0 to dev "naa.6782bcb05bcabf00ff0000380397ca71" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.

2019-05-07T17:54:30.115Z cpu2:2098823)SunRPC: 1099: Destroying world 0x2253c2

2019-05-07T17:54:34.115Z cpu7:2097507)ScsiVmas: 804: Inquiry for VPD page 00 to device naa.6589cfc000000f7547481ec53d72549e failed with error No connection

2019-05-07T17:55:31.118Z cpu11:2098823)SunRPC: 1099: Destroying world 0x225593

2019-05-07T17:56:32.120Z cpu2:2098823)SunRPC: 1099: Destroying world 0x2256a8

2019-05-07T17:56:33.387Z cpu16:2098820)WARNING: LSOM: LSOMVsiGetVirstoInstanceStats:800: Throttled: Attempt to get Virsto stats on unsupported disk52256481-aa44-4783-d2f0-625461b41dfe

2019-05-07T17:56:41.760Z cpu20:2098023)WARNING: iscsi_vmk: iscsivmk_ConnReceiveAtomic:517: vmhba65:CH:0 T:1 CN:0: Failed to receive data: Connection closed by peer

2019-05-07T17:56:41.760Z cpu20:2098023)WARNING: iscsi_vmk: iscsivmk_ConnReceiveAtomic:525: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:56:41.760Z cpu20:2098023)WARNING: iscsi_vmk: iscsivmk_ConnReceiveAtomic:526: Conn [CID: 0 L: 10.39.130.35:31611 R: 10.39.130.222:3260]

2019-05-07T17:56:41.760Z cpu20:2098023)iscsi_vmk: iscsivmk_ConnRxNotifyFailure:1235: vmhba65:CH:0 T:1 CN:0: Connection rx notifying failure: Failed to Receive. State=Online

2019-05-07T17:56:41.760Z cpu20:2098023)iscsi_vmk: iscsivmk_ConnRxNotifyFailure:1236: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:56:41.760Z cpu20:2098023)iscsi_vmk: iscsivmk_ConnRxNotifyFailure:1237: Conn [CID: 0 L: 10.39.130.35:31611 R: 10.39.130.222:3260]

2019-05-07T17:56:41.760Z cpu16:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:699: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "OFFLINE" (Event:6)

2019-05-07T17:56:41.760Z cpu16:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:700: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:56:41.760Z cpu16:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:701: Conn [CID: 0 L: 10.39.130.35:31611 R: 10.39.130.222:3260]

2019-05-07T17:56:41.766Z cpu0:2097195)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x28 (0x459a40d3e9c0, 2100138) to dev "naa.6589cfc0000002975052862c22403cca" on path "vmhba65:C0:T1:L70" Failed: H:0x2 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:56:41.766Z cpu0:2097195)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe:237: NMP device "naa.6589cfc0000002975052862c22403cca" state in doubt; requested fast path state update...

2019-05-07T17:56:41.766Z cpu0:2097195)ScsiDeviceIO: 3047: Cmd(0x459a40d3e9c0) 0x28, CmdSN 0x6d from world 2100138 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x0 0x20 0x44.

2019-05-07T17:56:41.908Z cpu0:2097195)NMP: nmp_ThrottleLogForDevice:3710: last error status from device naa.6589cfc0000002975052862c22403cca repeated 10 times

2019-05-07T17:56:42.049Z cpu0:2097689)ScsiDeviceIO: 3047: Cmd(0x459a40cbc880) 0x89, CmdSN 0x6e from world 2097185 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x40 0x80 0x41.

2019-05-07T17:56:42.119Z cpu4:2097505)LVM: 5748: Received APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 23)

2019-05-07T17:56:42.119Z cpu4:2097505)LVM: 5356: Handling APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 23, cur apd state UNKNOWN, cur dev state 1)

2019-05-07T17:56:42.119Z cpu4:2097505)HBX: 6287: APD EventType: APD_START (3) for vol 'SAN-PRODUCTION'

2019-05-07T17:56:42.119Z cpu4:2097505)ScsiDevice: 5978: Device state of naa.6589cfc0000002975052862c22403cca set to APD_START; token num:1

2019-05-07T17:56:42.119Z cpu4:2097505)StorageApdHandler: 1203: APD start for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:56:42.119Z cpu1:2097490)StorageApdHandler: 419: APD start event for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:56:42.119Z cpu1:2097490)StorageApdHandlerEv: 110: Device or filesystem with identifier [naa.6589cfc0000002975052862c22403cca] has entered the All Paths Down state.

2019-05-07T17:56:42.121Z cpu0:2101764)WARNING: NMP: nmp_IssueCommandToDevice:5082: I/O could not be issued to device "naa.6589cfc0000002975052862c22403cca" due to Not found

2019-05-07T17:56:42.121Z cpu0:2101764)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2019-05-07T17:56:42.121Z cpu0:2101764)WARNING: NMP: nmp_DeviceStartLoop:729: NMP Device "naa.6589cfc0000002975052862c22403cca" is blocked. Not starting I/O from device.

2019-05-07T17:56:43.119Z cpu5:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459a40cbc880

2019-05-07T17:56:43.119Z cpu5:2097836)WARNING: NMP: nmpDeviceAttemptFailover:715: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - failed to issue command due to Not found (APD), try again...

2019-05-07T17:56:43.119Z cpu5:2097836)WARNING: NMP: nmpDeviceAttemptFailover:765: Logical device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update...

2019-05-07T17:56:44.119Z cpu4:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459a40cbc880

2019-05-07T17:56:44.119Z cpu4:2097836)WARNING: NMP: nmpDeviceAttemptFailover:715: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - failed to issue command due to Not found (APD), try again...

2019-05-07T17:56:44.119Z cpu4:2097836)WARNING: NMP: nmpDeviceAttemptFailover:765: Logical device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update...

2019-05-07T17:56:44.667Z cpu22:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2170: socket 0x430bd554eaa0 network resource pool netsched.pools.persist.iscsi associated

2019-05-07T17:56:44.667Z cpu22:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2198: socket 0x430bd554eaa0 network tracker id 45045162 tracker.iSCSI.10.39.130.222 associated

2019-05-07T17:56:44.921Z cpu22:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:880: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "ONLINE"

2019-05-07T17:56:44.921Z cpu22:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:881: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:56:44.921Z cpu22:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:882: Conn [CID: 0 L: 10.39.130.35:49504 R: 10.39.130.222:3260]

2019-05-07T17:56:45.122Z cpu9:2097505)ScsiDevice: 6000: Setting Device naa.6589cfc0000002975052862c22403cca state back to 0x2

2019-05-07T17:56:45.122Z cpu9:2097505)LVM: 5748: Received APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 24)

2019-05-07T17:56:45.122Z cpu9:2097505)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 24, cur apd state APD_START, cur dev state 1)

2019-05-07T17:56:45.122Z cpu9:2097505)ScsiDevice: 6021: Device naa.6589cfc0000002975052862c22403cca is Out of APD; token num:1

2019-05-07T17:56:45.122Z cpu0:2097255)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (locked, gen 24, cur apd state APD_START, cur dev state 1)

2019-05-07T17:56:45.123Z cpu16:2098023)NMP: nmpCompleteRetryForPath:327: Retry world recovered device "naa.6589cfc0000002975052862c22403cca"

2019-05-07T17:56:51.630Z cpu0:2097255)HBX: 6287: APD EventType: APD_EXIT (4) for vol 'SAN-PRODUCTION'

2019-05-07T17:56:51.630Z cpu0:2097255)StorageApdHandler: 1315: APD exit for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:56:51.630Z cpu0:2097255)HBX: 5509: Completed APD/PDL event processing on vol 'SAN-PRODUCTION'.

2019-05-07T17:56:51.630Z cpu0:2097255)LVM: 5487: Device <naa.6589cfc000000f7547481ec53d72549e:1> APD handler with closeOnAPDExit - attempting close.

2019-05-07T17:56:51.630Z cpu4:2097490)StorageApdHandler: 507: APD exit event for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:56:51.630Z cpu4:2097490)StorageApdHandlerEv: 117: Device or filesystem with identifier [naa.6589cfc0000002975052862c22403cca] has exited the All Paths Down state.

2019-05-07T17:57:09.724Z cpu20:2250615)HBX: 3033: 'SAN-PRODUCTION': HB at offset 3407872 - Waiting for timed out HB:

2019-05-07T17:57:09.724Z cpu20:2250615)  [HB state abcdef02 offset 3407872 gen 41 stampUS 25045933439 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 8388614> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:57:18.052Z cpu14:2097547)WARNING: iscsi_vmk: iscsivmk_TaskMgmtIssue:633: vmhba65:CH:0 T:1 L:70 : Task mgmt "Abort Task" with itt=0xe98 (refITT=0xe97) timed out.

2019-05-07T17:57:19.727Z cpu14:2250615)HBX: 3033: 'SAN-PRODUCTION': HB at offset 3407872 - Waiting for timed out HB:

2019-05-07T17:57:19.727Z cpu14:2250615)  [HB state abcdef02 offset 3407872 gen 41 stampUS 25045933439 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 8388614> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:57:28.054Z cpu14:2097547)WARNING: iscsi_vmk: iscsivmk_TaskMgmtIssue:633: vmhba65:CH:0 T:1 L:70 : Task mgmt "Abort Task" with itt=0xe99 (refITT=0xe97) timed out.

2019-05-07T17:57:29.731Z cpu13:2250615)HBX: 3033: 'SAN-PRODUCTION': HB at offset 3407872 - Waiting for timed out HB:

2019-05-07T17:57:29.731Z cpu13:2250615)  [HB state abcdef02 offset 3407872 gen 41 stampUS 25045933439 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 8388614> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:57:33.348Z cpu12:2098046)WARNING: iscsi_vmk: iscsivmk_StopConnection:699: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "OFFLINE" (Event:4)

2019-05-07T17:57:33.348Z cpu12:2098046)WARNING: iscsi_vmk: iscsivmk_StopConnection:700: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:57:33.348Z cpu12:2098046)WARNING: iscsi_vmk: iscsivmk_StopConnection:701: Conn [CID: 0 L: 10.39.130.35:49504 R: 10.39.130.222:3260]

2019-05-07T17:57:33.352Z cpu12:2097207)NMP: nmp_ThrottleLogForDevice:3710: last error status from device naa.6589cfc0000002975052862c22403cca repeated 20 times

2019-05-07T17:57:33.352Z cpu12:2097207)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe:237: NMP device "naa.6589cfc0000002975052862c22403cca" state in doubt; requested fast path state update...

2019-05-07T17:57:33.352Z cpu12:2097207)ScsiDeviceIO: 3047: Cmd(0x459b98daa240) 0x28, CmdSN 0x7f from world 2100138 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x0 0x1a 0x45.

2019-05-07T17:57:33.352Z cpu14:2097547)WARNING: iscsi_vmk: iscsivmk_TaskMgmtIssue:633: vmhba65:CH:0 T:1 L:70 : Task mgmt "Abort Task" with itt=0xe9b (refITT=0xe97) timed out.

2019-05-07T17:57:33.352Z cpu14:2097547)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x89 (0x459a40deb580, 2097185) to dev "naa.6589cfc0000002975052862c22403cca" on path "vmhba65:C0:T1:L70" Failed: H:0x5 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:57:33.352Z cpu14:2097547)ScsiDeviceIO: 3082: Cmd(0x459a40deb580) 0x89, CmdSN 0x80 from world 2097185 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x5 D:0x0 P:0x0 Invalid sense data: 0x78 0x35 0x20.

2019-05-07T17:57:33.352Z cpu8:2097697)NMP: nmp_ThrottleLogForDevice:3781: Cmd 0x28 (0x459b98d0b3c0, 0) to dev "naa.6589cfc0000002975052862c22403cca" on path "vmhba65:C0:T1:L70" Failed: H:0x2 D:0x0 P:0x0 Invalid sense data: 0x0 0x0 0x0. Act:EVAL

2019-05-07T17:57:33.352Z cpu8:2097697)ScsiDeviceIO: 3047: Cmd(0x459b98d0b3c0) 0x28, CmdSN 0x81 from world 0 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x30 0x20 0x50.

2019-05-07T17:57:33.498Z cpu8:2097697)NMP: nmp_ThrottleLogForDevice:3710: last error status from device naa.6589cfc0000002975052862c22403cca repeated 10 times

2019-05-07T17:57:33.786Z cpu8:2097697)NMP: nmp_ThrottleLogForDevice:3710: last error status from device naa.6589cfc0000002975052862c22403cca repeated 20 times

2019-05-07T17:57:34.121Z cpu2:2097505)LVM: 5748: Received APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 25)

2019-05-07T17:57:34.121Z cpu2:2097505)LVM: 5356: Handling APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 25, cur apd state UNKNOWN, cur dev state 1)

2019-05-07T17:57:34.121Z cpu2:2097505)HBX: 6287: APD EventType: APD_START (3) for vol 'SAN-PRODUCTION'

2019-05-07T17:57:34.121Z cpu2:2097505)ScsiDevice: 5978: Device state of naa.6589cfc0000002975052862c22403cca set to APD_START; token num:1

2019-05-07T17:57:34.121Z cpu2:2097505)StorageApdHandler: 1203: APD start for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:57:34.121Z cpu4:2097490)StorageApdHandler: 419: APD start event for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:57:34.121Z cpu4:2097490)StorageApdHandlerEv: 110: Device or filesystem with identifier [naa.6589cfc0000002975052862c22403cca] has entered the All Paths Down state.

2019-05-07T17:57:34.121Z cpu8:2098823)SunRPC: 1099: Destroying world 0x22586e

2019-05-07T17:57:34.133Z cpu8:2097900)WARNING: NMP: nmp_IssueCommandToDevice:5082: I/O could not be issued to device "naa.6589cfc0000002975052862c22403cca" due to Not found

2019-05-07T17:57:34.133Z cpu8:2097900)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2019-05-07T17:57:34.133Z cpu8:2097900)WARNING: NMP: nmp_DeviceStartLoop:729: NMP Device "naa.6589cfc0000002975052862c22403cca" is blocked. Not starting I/O from device.

2019-05-07T17:57:35.120Z cpu4:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459b98d0b3c0

2019-05-07T17:57:35.120Z cpu4:2097836)WARNING: NMP: nmpDeviceAttemptFailover:715: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - failed to issue command due to Not found (APD), try again...

2019-05-07T17:57:35.120Z cpu4:2097836)WARNING: NMP: nmpDeviceAttemptFailover:765: Logical device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update...

2019-05-07T17:57:36.120Z cpu2:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459b98d0b3c0

2019-05-07T17:57:36.121Z cpu2:2097836)WARNING: NMP: nmpDeviceAttemptFailover:715: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - failed to issue command due to Not found (APD), try again...

2019-05-07T17:57:36.121Z cpu2:2097836)WARNING: NMP: nmpDeviceAttemptFailover:765: Logical device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update...

2019-05-07T17:57:36.121Z cpu13:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2170: socket 0x430bd563c320 network resource pool netsched.pools.persist.iscsi associated

2019-05-07T17:57:36.121Z cpu13:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2198: socket 0x430bd563c320 network tracker id 45045162 tracker.iSCSI.10.39.130.222 associated

2019-05-07T17:57:36.375Z cpu13:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:880: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "ONLINE"

2019-05-07T17:57:36.375Z cpu13:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:881: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:57:36.375Z cpu13:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:882: Conn [CID: 0 L: 10.39.130.35:15542 R: 10.39.130.222:3260]

2019-05-07T17:57:37.124Z cpu5:2097505)ScsiDevice: 6000: Setting Device naa.6589cfc0000002975052862c22403cca state back to 0x2

2019-05-07T17:57:37.124Z cpu5:2097505)LVM: 5748: Received APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 26)

2019-05-07T17:57:37.124Z cpu5:2097505)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 26, cur apd state APD_START, cur dev state 1)

2019-05-07T17:57:37.124Z cpu5:2097505)ScsiDevice: 6021: Device naa.6589cfc0000002975052862c22403cca is Out of APD; token num:1

2019-05-07T17:57:37.124Z cpu0:2097255)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (locked, gen 26, cur apd state APD_START, cur dev state 1)

2019-05-07T17:57:37.125Z cpu12:2098023)NMP: nmpCompleteRetryForPath:327: Retry world recovered device "naa.6589cfc0000002975052862c22403cca"

2019-05-07T17:57:37.343Z cpu1:2098161)HBX: 312: 'SAN-PRODUCTION': HB at offset 3407872 - Reclaimed heartbeat [Timeout]:

2019-05-07T17:57:37.343Z cpu1:2098161)  [HB state abcdef02 offset 3407872 gen 41 stampUS 25083008142 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 8388614> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:57:42.573Z cpu7:2097255)HBX: 6287: APD EventType: APD_EXIT (4) for vol 'SAN-PRODUCTION'

2019-05-07T17:57:42.573Z cpu7:2097255)StorageApdHandler: 1315: APD exit for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:57:42.573Z cpu7:2097255)HBX: 5509: Completed APD/PDL event processing on vol 'SAN-PRODUCTION'.

2019-05-07T17:57:42.573Z cpu7:2097255)LVM: 5487: Device <naa.6589cfc000000f7547481ec53d72549e:1> APD handler with closeOnAPDExit - attempting close.

2019-05-07T17:57:42.573Z cpu4:2097490)StorageApdHandler: 507: APD exit event for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:57:42.573Z cpu4:2097490)StorageApdHandlerEv: 117: Device or filesystem with identifier [naa.6589cfc0000002975052862c22403cca] has exited the All Paths Down state.

2019-05-07T17:57:55.833Z cpu22:2098023)WARNING: iscsi_vmk: iscsivmk_ConnReceiveAtomic:517: vmhba65:CH:0 T:1 CN:0: Failed to receive data: Connection closed by peer

2019-05-07T17:57:55.833Z cpu22:2098023)WARNING: iscsi_vmk: iscsivmk_ConnReceiveAtomic:525: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:57:55.833Z cpu22:2098023)WARNING: iscsi_vmk: iscsivmk_ConnReceiveAtomic:526: Conn [CID: 0 L: 10.39.130.35:15542 R: 10.39.130.222:3260]

2019-05-07T17:57:55.833Z cpu22:2098023)iscsi_vmk: iscsivmk_ConnRxNotifyFailure:1235: vmhba65:CH:0 T:1 CN:0: Connection rx notifying failure: Failed to Receive. State=Online

2019-05-07T17:57:55.833Z cpu22:2098023)iscsi_vmk: iscsivmk_ConnRxNotifyFailure:1236: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:57:55.833Z cpu22:2098023)iscsi_vmk: iscsivmk_ConnRxNotifyFailure:1237: Conn [CID: 0 L: 10.39.130.35:15542 R: 10.39.130.222:3260]

2019-05-07T17:57:55.833Z cpu22:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:699: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "OFFLINE" (Event:6)

2019-05-07T17:57:55.833Z cpu22:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:700: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:57:55.833Z cpu22:2097688)WARNING: iscsi_vmk: iscsivmk_StopConnection:701: Conn [CID: 0 L: 10.39.130.35:15542 R: 10.39.130.222:3260]

2019-05-07T17:57:55.838Z cpu2:2097197)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe:237: NMP device "naa.6589cfc0000002975052862c22403cca" state in doubt; requested fast path state update...

2019-05-07T17:57:55.838Z cpu2:2097197)ScsiDeviceIO: 3047: Cmd(0x459b98dd7d80) 0x28, CmdSN 0x95 from world 2100138 to dev "naa.6589cfc0000002975052862c22403cca" failed H:0x2 D:0x0 P:0x0 Invalid sense data: 0x0 0x1a 0x45.

2019-05-07T17:57:56.065Z cpu2:2097197)NMP: nmp_ThrottleLogForDevice:3710: last error status from device naa.6589cfc0000002975052862c22403cca repeated 40 times

2019-05-07T17:57:56.121Z cpu2:2097197)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe:237: NMP device "naa.6589cfc0000002975052862c22403cca" state in doubt; requested fast path state update...

2019-05-07T17:57:56.121Z cpu5:2097505)LVM: 5748: Received APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 27)

2019-05-07T17:57:56.121Z cpu5:2097505)LVM: 5356: Handling APD EventType: APD_START (3) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 27, cur apd state UNKNOWN, cur dev state 1)

2019-05-07T17:57:56.121Z cpu5:2097505)HBX: 6287: APD EventType: APD_START (3) for vol 'SAN-PRODUCTION'

2019-05-07T17:57:56.121Z cpu5:2097505)ScsiDevice: 5978: Device state of naa.6589cfc0000002975052862c22403cca set to APD_START; token num:1

2019-05-07T17:57:56.121Z cpu5:2097505)StorageApdHandler: 1203: APD start for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:57:56.121Z cpu6:2097490)StorageApdHandler: 419: APD start event for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:57:56.121Z cpu6:2097490)StorageApdHandlerEv: 110: Device or filesystem with identifier [naa.6589cfc0000002975052862c22403cca] has entered the All Paths Down state.

2019-05-07T17:57:56.135Z cpu2:2099067)WARNING: NMP: nmp_IssueCommandToDevice:5082: I/O could not be issued to device "naa.6589cfc0000002975052862c22403cca" due to Not found

2019-05-07T17:57:56.135Z cpu2:2099067)WARNING: NMP: nmp_DeviceRetryCommand:133: Device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device.

2019-05-07T17:57:56.135Z cpu2:2099067)WARNING: NMP: nmp_DeviceStartLoop:729: NMP Device "naa.6589cfc0000002975052862c22403cca" is blocked. Not starting I/O from device.

2019-05-07T17:57:57.122Z cpu5:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459b98dd7d80

2019-05-07T17:57:57.122Z cpu5:2097836)WARNING: NMP: nmpDeviceAttemptFailover:715: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - failed to issue command due to Not found (APD), try again...

2019-05-07T17:57:57.122Z cpu5:2097836)WARNING: NMP: nmpDeviceAttemptFailover:765: Logical device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update...

2019-05-07T17:57:58.123Z cpu5:2097836)WARNING: NMP: nmpDeviceAttemptFailover:640: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - issuing command 0x459b98dd7d80

2019-05-07T17:57:58.123Z cpu5:2097836)WARNING: NMP: nmpDeviceAttemptFailover:715: Retry world failover device "naa.6589cfc0000002975052862c22403cca" - failed to issue command due to Not found (APD), try again...

2019-05-07T17:57:58.123Z cpu5:2097836)WARNING: NMP: nmpDeviceAttemptFailover:765: Logical device "naa.6589cfc0000002975052862c22403cca": awaiting fast path state update...

2019-05-07T17:57:58.851Z cpu12:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2170: socket 0x430bd5399020 network resource pool netsched.pools.persist.iscsi associated

2019-05-07T17:57:58.851Z cpu12:2098046)iscsi_vmk: iscsivmk_ConnNetRegister:2198: socket 0x430bd5399020 network tracker id 45045162 tracker.iSCSI.10.39.130.222 associated

2019-05-07T17:57:59.104Z cpu12:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:880: vmhba65:CH:0 T:1 CN:0: iSCSI connection is being marked "ONLINE"

2019-05-07T17:57:59.104Z cpu12:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:881: Sess [ISID: 00023d000001 TARGET: iqn.2005-10.org.freenas.ctl:all-esxi TPGT: 1 TSIH: 0]

2019-05-07T17:57:59.104Z cpu12:2098046)WARNING: iscsi_vmk: iscsivmk_StartConnection:882: Conn [CID: 0 L: 10.39.130.35:47878 R: 10.39.130.222:3260]

2019-05-07T17:57:59.124Z cpu0:2097505)ScsiDevice: 6000: Setting Device naa.6589cfc0000002975052862c22403cca state back to 0x2

2019-05-07T17:57:59.124Z cpu0:2097505)LVM: 5748: Received APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (gen 28)

2019-05-07T17:57:59.124Z cpu0:2097505)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (unlocked, gen 28, cur apd state APD_START, cur dev state 1)

2019-05-07T17:57:59.124Z cpu0:2097505)ScsiDevice: 6021: Device naa.6589cfc0000002975052862c22403cca is Out of APD; token num:1

2019-05-07T17:57:59.124Z cpu7:2097255)LVM: 5356: Handling APD EventType: APD_EXIT (4) for device <naa.6589cfc0000002975052862c22403cca:3> (locked, gen 28, cur apd state APD_START, cur dev state 1)

2019-05-07T17:58:02.946Z cpu17:2097212)NMP: nmpCompleteRetryForPath:327: Retry world recovered device "naa.6589cfc0000002975052862c22403cca"

2019-05-07T17:58:09.744Z cpu14:2250615)HBX: 3033: 'SAN-PRODUCTION': HB at offset 3407872 - Waiting for timed out HB:

2019-05-07T17:58:09.744Z cpu14:2250615)  [HB state abcdef02 offset 3407872 gen 41 stampUS 25108932940 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 8388614> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:58:11.157Z cpu7:2097255)HBX: 6287: APD EventType: APD_EXIT (4) for vol 'SAN-PRODUCTION'

2019-05-07T17:58:11.157Z cpu7:2097255)LVM: 5487: Device <naa.6589cfc000000f7547481ec53d72549e:1> APD handler with closeOnAPDExit - attempting close.

2019-05-07T17:58:11.157Z cpu8:2098234)ScsiDeviceIO: 4536: Command 0x89 (CmdSN 0xa3, World 2097185) to device naa.6589cfc0000002975052862c22403cca timed out: expiry time occurs 2105ms in the past

2019-05-07T17:58:11.157Z cpu8:2098234)WARNING: ScsiVmas: 3021: Failed to issue command on device "naa.6589cfc0000002975052862c22403cca": Timeout

2019-05-07T17:58:11.476Z cpu1:2098161)HBX: 312: 'SAN-PRODUCTION': HB at offset 3407872 - Reclaimed heartbeat [Timeout]:

2019-05-07T17:58:11.476Z cpu1:2098161)  [HB state abcdef02 offset 3407872 gen 41 stampUS 25117052859 uuid 5cd16571-5dd95f1e-0244-782bcb396c1f jrnl <FB 8388614> drv 24.82 lockImpl 4 ip 172.16.0.35]

2019-05-07T17:58:11.476Z cpu1:2098161)StorageApdHandler: 1315: APD exit for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:58:11.477Z cpu1:2098161)HBX: 5509: Completed APD/PDL event processing on vol 'SAN-PRODUCTION'.

2019-05-07T17:58:11.477Z cpu6:2097490)StorageApdHandler: 507: APD exit event for 0x4304183eeea0 [naa.6589cfc0000002975052862c22403cca]

2019-05-07T17:58:11.477Z cpu6:2097490)StorageApdHandlerEv: 117: Device or filesystem with identifier [naa.6589cfc0000002975052862c22403cca] has exited the All Paths Down state.

2019-05-07T17:58:34.122Z cpu10:2097835)NMP: nmp_ResetDeviceLogThrottling:3575: last error status from device naa.6589cfc0000002975052862c22403cca repeated 4 times

2019-05-07T17:58:36.123Z cpu8:2098823)SunRPC: 1099: Destroying world 0x225a09

[root@esxi1:~]

iqn.2005-10.org.freenas.ctl:all-esxi

Reply
0 Kudos
5 Replies
hussainbte
Expert
Expert

can you drop the MTU to 1500.. just for troubleshooting purposes and check

If you found my answers useful please consider marking them as Correct OR Helpful Regards, Hussain https://virtualcubes.wordpress.com/
Reply
0 Kudos
mune3b
Enthusiast
Enthusiast

Yeah I did earlier. Changed MTU at FreeNAS and VMKernal Adapter but no postive results.

Reply
0 Kudos
hussainbte
Expert
Expert

confirm your iSCSI port binding configurations.. if you can please share.

Configure Port Binding for iSCSI or iSER

If you found my answers useful please consider marking them as Correct OR Helpful Regards, Hussain https://virtualcubes.wordpress.com/
Reply
0 Kudos
Wolken
Enthusiast
Enthusiast

It seems that there is an issue with storage. At least codes 0x89 and 0x28 pointing to it: SCSI Operation Codes ** Numeric Sorted Listing

Please make sure that the storage components are healthy.

Reply
0 Kudos
geauxgetter
Contributor
Contributor

I am having the exact same issue running 6.7u2, I can’t find any resolutio. All links are running clean. Did you resolve the issue?

Reply
0 Kudos