Aug 18 07:43:07 vmkernel: 0:20:06:06.630 cpu10:36187)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027ef18e40) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x5 D:0x0 P:0x0 Possible sense data: Aug 18 07:43:07 0x0 0x0 0x0. Aug 18 07:43:07 vmkernel: 0:20:06:06.630 cpu10:36187)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe: NMP device "naa.60030d90f9307b02d19dbffbcfb69805" state in doubt; requested fast path state update... Aug 18 07:43:07 vmkernel: 0:20:06:06.630 cpu10:36187)ScsiDeviceIO: 1672: Command 0x2a to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x5 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:10 Vpxa: [2011-08-18 07:43:10.817 17894B90 warning 'App'] [VpxaHalStats] Unexpected return result. Expect 1 sample, receive 2 Aug 18 07:43:10 Vpxa: [2011-08-18 07:43:10.819 17894B90 verbose 'App'] Set internal stats for VM: 2 (vpxa VM id), 21 (vpxd VM id). Is FT primary? 0 Aug 18 07:43:10 Vpxa: [2011-08-18 07:43:10.820 17894B90 verbose 'App'] Set internal stats for VM: 3 (vpxa VM id), 12 (vpxd VM id). Is FT primary? 0 Aug 18 07:43:12 vmkernel: 0:20:06:11.703 cpu0:36187)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027ef18e40) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x5 D:0x0 P:0x0 Possible sense data: Aug 18 07:43:12 0x0 0x0 0x0. Aug 18 07:43:12 vmkernel: 0:20:06:11.703 cpu0:36187)WARNING: NMP: nmp_DeviceRequestFastDeviceProbe: NMP device "naa.60030d90f9307b02d19dbffbcfb69805" state in doubt; requested fast path state update... Aug 18 07:43:12 vmkernel: 0:20:06:11.703 cpu0:36187)ScsiDeviceIO: 1672: Command 0x2a to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x5 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:12 Vpxa: [2011-08-18 07:43:12.807 FFB61B10 verbose 'VpxaHalCnxHostagent'] Received callback in WaitForUpdatesDone Aug 18 07:43:12 Vpxa: [2011-08-18 07:43:12.807 FFB61B10 verbose 'VpxaHalCnxHostagent'] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 2841 to 2842 (at 2841) Aug 18 07:43:12 Vpxa: [2011-08-18 07:43:12.807 FFB61B10 verbose 'App'] [VpxaHalVmHostagent] 16: GuestInfo changed 'guest.disk' Aug 18 07:43:12 Vpxa: [2011-08-18 07:43:12.807 FFB61B10 verbose 'App'] [VpxaHalServices] VmGuestDiskChange Event for vm(3) 16 Aug 18 07:43:12 Vpxa: [2011-08-18 07:43:12.807 FFB61B10 verbose 'App'] [VpxaInvtVmChangeListener] Guest DiskInfo Changed Aug 18 07:43:12 Vpxa: [2011-08-18 07:43:12.807 FFB61B10 verbose 'App'] [VpxaInvtHost] Increment master gen. no to (1558): VmRuntime:GuestDiskChanged Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.645 17894B90 verbose 'SoapAdapter.HTTPService'] User agent is 'VMware-client/4.1.0' Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.645 1768DB90 verbose 'SoapAdapter.HTTPService'] User agent is 'VMware-client/4.1.0' Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.645 17894B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Client: NeedsContentLength: false UnderstandsChunking: true CanKeepAlive: true (PresetContentLength -1) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.645 1768DB90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Client: NeedsContentLength: false UnderstandsChunking: true CanKeepAlive: true (PresetContentLength -1) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.646 1768DB90 info 'Libs'] UUID: Unable to open /dev/mem: No such file or directory Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.646 1768DB90 verbose 'PropertyProvider'] RecordOp ASSIGN: info.reason, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.646 1768DB90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Complete (processed 522 bytes) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.646 17894B90 verbose 'PropertyProvider'] RecordOp ASSIGN: info.startTime, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.646 17894B90 verbose 'PropertyProvider' opID=HB-host-9@1558-9] RecordOp ASSIGN: info.state, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.646 17894B90 verbose 'PropertyProvider' opID=HB-host-9@1558-9] RecordOp ASSIGN: info.cancelable, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.646 17894B90 info 'App' opID=HB-host-9@1558-9] [VpxLRO] -- BEGIN session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 -- -- vpxapi.VpxaService.retrieveChanges -- 52eea1d6-578c-6 Aug 18 07:43:16 6d2-aa37-938dc4e05b9c Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.646 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [1+] VpxaMoService::GetChanges Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.646 17894B90 verbose 'App' opID=HB-host-9@1558-9] [VpxaMoService] GetChanges: 1557 -> 1558 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.648 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [2+] VpxaStatsMetadata::PrepareStatsChanges Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.648 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [2-] VpxaStatsMetadata::PrepareStatsChanges (took 0 ms) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.648 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [2+] VpxdDatastore::PrepareChanges Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.648 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [2-] VpxdDatastore::PrepareChanges (took 0 ms) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.648 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [2+] VpxaMoService::PrepareHostChanges Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.648 17957B90 verbose 'SoapAdapter.HTTPService'] User agent is 'VMware-client/4.1.0' Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.648 17957B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Client: NeedsContentLength: false UnderstandsChunking: true CanKeepAlive: true (PresetContentLength -1) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.648 17957B90 info 'Libs'] UUID: Unable to open /dev/mem: No such file or directory Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.648 17957B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Complete (processed 516 bytes) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.649 17A1AB90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Complete (processed 1445 bytes) Aug 18 07:43:16 Hostd: [2011-08-18 07:43:16.649 30382B90 verbose 'ha-license-manager' opID=HB-host-9@1558-9] Load: Loading existing file: /etc/vmware/license.cfg Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.651 FFB61B10 verbose 'SoapAdapter.HTTPService'] User agent is 'VMware-client/4.1.0' Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.651 FFB61B10 verbose 'SoapAdapter.HTTPService'] HTTP Response: Client: NeedsContentLength: false UnderstandsChunking: true CanKeepAlive: true (PresetContentLength -1) Aug 18 07:43:16 Hostd: [2011-08-18 07:43:16.660 30382B90 verbose 'App' opID=HB-host-9@1558-9] ha-license-manager:Validate -> Valid license detected for "VMware ESX Server 4.0" (lastError=0, desc.IsValid:Yes) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.668 17894B90 verbose 'App' opID=HB-host-9@1558-9] [VpxaMoService] host changes include changed properties [] Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.668 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [2-] VpxaMoService::PrepareHostChanges (took 20 ms) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.668 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [2+] VpxaMoService::PrepareVmChanges Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.668 17894B90 verbose 'PropertyProvider' opID=HB-host-9@1558-9] RecordOp ASSIGN: info.progress, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.668 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [3+] HandleVMChanges for vmid:3 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.668 17894B90 verbose 'App' opID=HB-host-9@1558-9] [VpxURL] Resolved localPath /vmfs/volumes/4d810d89-c7499fb0-c827-b499bab6665e/tb-test1/tb-test1.vmx to URL sanfs://vmfs_uuid:4d810d89-c7499fb0-c827-b499bab66 Aug 18 07:43:16 65e/tb-test1/tb-test1.vmx Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.668 17853B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Complete (processed 824 bytes) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.668 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [3-] HandleVMChanges for vmid:3 (took 0 ms) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'PropertyProvider' opID=HB-host-9@1558-9] RecordOp ASSIGN: info.progress, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'PropertyProvider' opID=HB-host-9@1558-9] RecordOp ASSIGN: info.progress, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'PropertyProvider' opID=HB-host-9@1558-9] RecordOp ASSIGN: info.progress, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'PropertyProvider' opID=HB-host-9@1558-9] RecordOp ASSIGN: info.progress, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [2-] VpxaMoService::PrepareVmChanges (took 0 ms) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'VpxaHalResourcePool' opID=HB-host-9@1558-9] NeedFullSync() = false Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'VpxaHalResourcePool' opID=HB-host-9@1558-9] VpxaHalResourcePoolStandalone::GetVpxaMoRef(vim.ResourcePool:ha-root-pool) = vim.ResourcePool:/Resources Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'VpxProfiler' opID=HB-host-9@1558-9] [1-] VpxaMoService::GetChanges (took 22 ms) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'PropertyProvider' opID=HB-host-9@1558-9] RecordOp ASSIGN: info.state, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'PropertyProvider' opID=HB-host-9@1558-9] RecordOp ASSIGN: info.cancelable, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'PropertyProvider' opID=HB-host-9@1558-9] RecordOp ASSIGN: info.result, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 info 'App' opID=HB-host-9@1558-9] [VpxLRO] -- FINISH session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 -- -- vpxapi.VpxaService.retrieveChanges -- 52eea1d6-578c- Aug 18 07:43:16 66d2-aa37-938dc4e05b9c Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.669 17894B90 verbose 'PropertyProvider'] RecordOp ASSIGN: info.completeTime, session[52eea1d6-578c-66d2-aa37-938dc4e05b9c]52a16b7e-400a-07c2-68d0-8a23d369ab22 Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.671 178D5B90 verbose 'SoapAdapter.HTTPService'] User agent is 'VMware-client/4.1.0' Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.671 178D5B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Client: NeedsContentLength: false UnderstandsChunking: true CanKeepAlive: true (PresetContentLength -1) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.671 17894B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Complete (processed 6413 bytes) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.675 17A1AB90 verbose 'SoapAdapter.HTTPService'] User agent is 'VMware-client/4.1.0' Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.675 17A1AB90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Client: NeedsContentLength: false UnderstandsChunking: true CanKeepAlive: true (PresetContentLength -1) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.675 178D5B90 verbose 'SoapAdapter.HTTPService'] User agent is 'VMware-client/4.1.0' Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.675 178D5B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Client: NeedsContentLength: false UnderstandsChunking: true CanKeepAlive: true (PresetContentLength -1) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.676 17812B90 info 'App' opID=HB-host-9@1558-66] [VpxLRO] -- BEGIN task-internal-2278 -- -- vmodl.query.PropertyCollector.Filter.destroy -- 52eea1d6-578c-66d2-aa37-938dc4e05b9c Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.676 17812B90 verbose 'SoapAdapter.HTTPService' opID=HB-host-9@1558-66] HTTP Response: Complete (processed 408 bytes) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.676 17812B90 info 'App' opID=HB-host-9@1558-66] [VpxLRO] -- FINISH task-internal-2278 -- -- vmodl.query.PropertyCollector.Filter.destroy -- 52eea1d6-578c-66d2-aa37-938dc4e05b9c Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.678 17812B90 verbose 'SoapAdapter.HTTPService'] User agent is 'VMware-client/4.1.0' Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.678 17812B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Client: NeedsContentLength: false UnderstandsChunking: true CanKeepAlive: true (PresetContentLength -1) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.678 17812B90 verbose 'SoapAdapter.HTTPService'] User agent is 'VMware-client/4.1.0' Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.678 17812B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Client: NeedsContentLength: false UnderstandsChunking: true CanKeepAlive: true (PresetContentLength -1) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.678 17812B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Complete (processed 530 bytes) Aug 18 07:43:16 Vpxa: [2011-08-18 07:43:16.678 17812B90 verbose 'SoapAdapter.HTTPService'] HTTP Response: Complete (processed 406 bytes) Aug 18 07:43:17 vmkernel: 0:20:06:16.775 cpu4:36187)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027ef18e40) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x5 D:0x0 P:0x0 Possible sense data: Aug 18 07:43:17 0x0 0x0 0x0. Aug 18 07:43:17 vmkernel: 0:20:06:16.775 cpu4:36187)ScsiDeviceIO: 1672: Command 0x2a to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x5 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:17 vobd: Aug 18 07:43:17.948: 72377365672us: [esx.problem.vmfs.heartbeat.timedout] 4e491434-f1d58ba0-faf8-b499bab6665e vm1-test. Aug 18 07:43:17 Hostd: [2011-08-18 07:43:17.948 30382B90 info 'ha-eventmgr'] Event 261 : Lost access to volume 4e491434-f1d58ba0-faf8-b499bab6665e (vm1-test) due to connectivity issues. Recovery attempt is in progress and outcome will be reported sho Aug 18 07:43:17 rtly. Aug 18 07:43:17 Vpxa: [2011-08-18 07:43:17.950 177D1B90 verbose 'VpxaHalCnxHostagent'] Received callback in WaitForUpdatesDone Aug 18 07:43:17 Vpxa: [2011-08-18 07:43:17.950 177D1B90 verbose 'VpxaHalCnxHostagent'] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 2842 to 2843 (at 2842) Aug 18 07:43:17 Vpxa: [2011-08-18 07:43:17.950 177D1B90 verbose 'App'] Got an EventEx (id: esx.problem.vmfs.heartbeat.timedout) Aug 18 07:43:17 Vpxa: [2011-08-18 07:43:17.950 177D1B90 verbose 'App'] [VpxaHalServices] EventsRecorded Event Fired Aug 18 07:43:25 iscsid: connection 1:0 (iqn.2000-08.com.datacore:tb-daco1-target1 if=default addr=172.19.1.1:3260 (TPGT:1 ISID:0x1) (T0 C0)) Nop-out timeout after 10 sec in state (3). Aug 18 07:43:25 vmkernel: 0:20:06:24.291 cpu20:4844)WARNING: iscsi_vmk: iscsivmk_StopConnection: vmhba37:CH:0 T:0 CN:0: iSCSI connection is being marked "OFFLINE" (Event:4) Aug 18 07:43:25 vmkernel: 0:20:06:24.291 cpu20:4844)WARNING: iscsi_vmk: iscsivmk_StopConnection: Sess [ISID: 00023d000001 TARGET: iqn.2000-08.com.datacore:tb-daco1-target1 TPGT: 1 TSIH: 0] Aug 18 07:43:25 vmkernel: 0:20:06:24.291 cpu20:4844)WARNING: iscsi_vmk: iscsivmk_StopConnection: Conn [CID: 0 L: 172.19.1.11:53283 R: 172.19.1.1:3260] Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu20:4844)WARNING: iscsi_vmk: iscsivmk_TaskMgmtIssue: vmhba37:CH:0 T:0 L:1 : Task mgmt "Abort Task" with itt=0x0 (refITT=0x277258) timed out. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027e628440) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x8 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)ScsiDeviceIO: 1672: Command 0x2a to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x8 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027f170d40) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x8 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)ScsiDeviceIO: 1672: Command 0x2a to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x8 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027f9ea140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x8 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)ScsiDeviceIO: 1672: Command 0x2a to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x8 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027e8aa140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x8 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)ScsiDeviceIO: 1672: Command 0x2a to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x8 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)NMP: nmp_CompleteCommandForPath: Command 0x2a (0x41027eaa8140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x8 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)ScsiDeviceIO: 1672: Command 0x2a to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x8 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)FS3: 7044: Starting HB reclaim for [HB state abcdef02 offset 3883008 gen 21 stamp 72376847832 uuid 4e4ba7f9-f714e707-3e00-b499bab6665e jrnl drv 8.46] Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu1:250447)ScsiPath: 2974: CmdSN 0x0 to path vmhba37:C0:T0:L1 timed out: expiry time occurs 6660ms in the past Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu1:250447)WARNING: ScsiPath: 3178: Failed to issue command on path vmhba37:C0:T0:L1: Timeout Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)NMP: nmp_CompleteCommandForPath: Command 0x16 (0x41027eaa8140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x2 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu1:250447)VMW_SATP_ALUA: satp_alua_issueCommandOnPath: Failed to issue sync command on path "vmhba37:C0:T0:L1" (UP) due to status Timeout. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)NMP: nmp_PathDetermineFailure: SCSI cmd RESERVE failed on path vmhba37:C0:T0:L1, reservation state on device naa.60030d90f9307b02d19dbffbcfb69805 is unknown. Aug 18 07:43:25 vmkernel: 0:20:06:24.292 cpu4:4133)ScsiDeviceIO: 1672: Command 0x16 to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.342 cpu4:4100)NMP: nmp_CompleteCommandForPath: Command 0x16 (0x41027eaa8140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x2 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.342 cpu4:4100)NMP: nmp_PathDetermineFailure: SCSI cmd RESERVE failed on path vmhba37:C0:T0:L1, reservation state on device naa.60030d90f9307b02d19dbffbcfb69805 is unknown. Aug 18 07:43:25 vmkernel: 0:20:06:24.342 cpu4:4100)ScsiDeviceIO: 1672: Command 0x16 to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.394 cpu4:4100)NMP: nmp_CompleteCommandForPath: Command 0x16 (0x41027eaa8140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x2 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.394 cpu4:4100)NMP: nmp_PathDetermineFailure: SCSI cmd RESERVE failed on path vmhba37:C0:T0:L1, reservation state on device naa.60030d90f9307b02d19dbffbcfb69805 is unknown. Aug 18 07:43:25 vmkernel: 0:20:06:24.394 cpu4:4100)ScsiDeviceIO: 1672: Command 0x16 to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.446 cpu4:4100)NMP: nmp_CompleteCommandForPath: Command 0x16 (0x41027eaa8140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x2 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.446 cpu4:4100)NMP: nmp_PathDetermineFailure: SCSI cmd RESERVE failed on path vmhba37:C0:T0:L1, reservation state on device naa.60030d90f9307b02d19dbffbcfb69805 is unknown. Aug 18 07:43:25 vmkernel: 0:20:06:24.446 cpu4:4100)ScsiDeviceIO: 1672: Command 0x16 to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.497 cpu4:4100)NMP: nmp_CompleteCommandForPath: Command 0x16 (0x41027eaa8140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x2 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.497 cpu4:4100)NMP: nmp_PathDetermineFailure: SCSI cmd RESERVE failed on path vmhba37:C0:T0:L1, reservation state on device naa.60030d90f9307b02d19dbffbcfb69805 is unknown. Aug 18 07:43:25 vmkernel: 0:20:06:24.497 cpu4:4100)ScsiDeviceIO: 1672: Command 0x16 to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.548 cpu4:250137)NMP: nmp_CompleteCommandForPath: Command 0x16 (0x41027eaa8140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x2 D:0x0 P:0x0 Possible sense data: Aug 18 07:43:25 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.548 cpu4:250137)NMP: nmp_PathDetermineFailure: SCSI cmd RESERVE failed on path vmhba37:C0:T0:L1, reservation state on device naa.60030d90f9307b02d19dbffbcfb69805 is unknown. Aug 18 07:43:25 vmkernel: 0:20:06:24.548 cpu4:250137)ScsiDeviceIO: 1672: Command 0x16 to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.599 cpu4:4100)NMP: nmp_CompleteCommandForPath: Command 0x16 (0x41027eaa8140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x2 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.599 cpu4:4100)NMP: nmp_PathDetermineFailure: SCSI cmd RESERVE failed on path vmhba37:C0:T0:L1, reservation state on device naa.60030d90f9307b02d19dbffbcfb69805 is unknown. Aug 18 07:43:25 vmkernel: 0:20:06:24.599 cpu4:4100)ScsiDeviceIO: 1672: Command 0x16 to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.651 cpu4:4100)NMP: nmp_CompleteCommandForPath: Command 0x16 (0x41027eaa8140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x2 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.651 cpu4:4100)NMP: nmp_PathDetermineFailure: SCSI cmd RESERVE failed on path vmhba37:C0:T0:L1, reservation state on device naa.60030d90f9307b02d19dbffbcfb69805 is unknown. Aug 18 07:43:25 vmkernel: 0:20:06:24.651 cpu4:4100)ScsiDeviceIO: 1672: Command 0x16 to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.702 cpu4:4100)NMP: nmp_CompleteCommandForPath: Command 0x16 (0x41027eaa8140) to NMP device "naa.60030d90f9307b02d19dbffbcfb69805" failed on physical path "vmhba37:C0:T0:L1" H:0x2 D:0x0 P:0x0 Possible sense data: 0 Aug 18 07:43:25 x0 0x0 0x0. Aug 18 07:43:25 vmkernel: 0:20:06:24.702 cpu4:4100)NMP: nmp_PathDetermineFailure: SCSI cmd RESERVE failed on path vmhba37:C0:T0:L1, reservation state on device naa.60030d90f9307b02d19dbffbcfb69805 is unknown. Aug 18 07:43:25 vmkernel: 0:20:06:24.702 cpu4:4100)ScsiDeviceIO: 1672: Command 0x16 to device "naa.60030d90f9307b02d19dbffbcfb69805" failed H:0x2 D:0x0 P:0x0 Possible sense data: 0x0 0x0 0x0. Aug 18 07:43:25 vobd: Aug 18 07:43:25.804: 72384703989us: [vob.scsi.scsipath.pathstate.dead] scsiPath vmhba37:C0:T0:L1 changed state from on. Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.804 FFCBEE80 verbose 'StorageSystem'] StoragePathUpdate: Invalidate Path Cache immediately Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.804 FFCBEE80 verbose 'StorageSystem'] SendStorageInfoEvent() called Aug 18 07:43:25 vobd: Aug 18 07:43:25.804: 72385222296us: [esx.problem.storage.connectivity.lost] Lost connectivity to storage device naa.60030d90f9307b02d19dbffbcfb69805. Path vmhba37:C0:T0:L1 is down. Affected datastores: "vm1-test".. Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.805 30F0FB90 info 'ha-eventmgr'] Event 262 : Lost connectivity to storage device naa.60030d90f9307b02d19dbffbcfb69805. Path vmhba37:C0:T0:L1 is down. Affected datastores: "vm1-test". Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.805 307B1B90 verbose 'Hostsvc::DatastoreSystem'] VmfsVobUpdate: got Vob message [N11HostdCommon6VobMsgE:0x304bab88] timestamp=72385222817 Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.805 307B1B90 info 'Hostsvc::DatastoreSystem'] VmfsVobUpdate: Accessibility changed for datastore vm1-test Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.805 307B1B90 verbose 'FSVolumeProvider'] RefreshOneVmfsVolume on /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.805 307B1B90 verbose 'Hostsvc::Datastore'] NotifyIfAccessibleChanged:: -- notify that datastore 4e491434-f1d58ba0-faf8-b499bab6665e at path /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e now has accessib Aug 18 07:43:25 ility of false Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.805 30F5AB90 verbose 'vm:/vmfs/volumes/4e439658-5a45789a-c462-b499bab6665e/tb-db/tb-db.vmx'] Got DSSYS change: [N11HostdCommon18DatastoreSystemMsgE:0x30a598d8]UPDATE-NOW-DISCONNECTED, 4e491434-f1d58ba0-faf8 Aug 18 07:43:25 -b499bab6665e, /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e; Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.805 30F5AB90 verbose 'vm:/vmfs/volumes/4d810d89-c7499fb0-c827-b499bab6665e/tb-test1/tb-test1.vmx'] Got DSSYS change: [N11HostdCommon18DatastoreSystemMsgE:0x30a598d8]UPDATE-NOW-DISCONNECTED, 4e491434-f1d58ba Aug 18 07:43:25 0-faf8-b499bab6665e, /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e; Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.805 30F5AB90 info 'vm:/vmfs/volumes/4d810d89-c7499fb0-c827-b499bab6665e/tb-test1/tb-test1.vmx'] VM Datastore updates for device file backing, refresh config Aug 18 07:43:25 vmkernel: 0:20:06:24.711 cpu0:16981)FS3: 7412: Waiting for timed-out heartbeat [HB state abcdef02 offset 3883008 gen 21 stamp 72376847832 uuid 4e4ba7f9-f714e707-3e00-b499bab6665e jrnl drv 8.46] Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.829 30382B90 info 'App'] CreateISCSIHBA Aug 18 07:43:25 vmkernel: 0:20:06:24.754 cpu4:4100)WARNING: NMP: nmp_IssueCommandToDevice: I/O could not be issued to device "naa.60030d90f9307b02d19dbffbcfb69805" due to Not found Aug 18 07:43:25 vmkernel: 0:20:06:24.754 cpu4:4100)WARNING: NMP: nmp_DeviceRetryCommand: Device "naa.60030d90f9307b02d19dbffbcfb69805": awaiting fast path state update for failover with I/O blocked. No prior reservation exists on the device. Aug 18 07:43:25 vmkernel: 0:20:06:24.754 cpu4:4100)WARNING: NMP: nmp_DeviceStartLoop: NMP Device "naa.60030d90f9307b02d19dbffbcfb69805" is blocked. Not starting I/O from device. Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.886 30382B90 info 'App'] CreateISCSIHBA Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.940 30382B90 info 'App'] CreateISCSIHBA Aug 18 07:43:25 Hostd: [2011-08-18 07:43:25.992 30382B90 info 'App'] CreateISCSIHBA Aug 18 07:43:26 Hostd: [2011-08-18 07:43:26.043 30382B90 info 'App'] CreateISCSIHBA Aug 18 07:43:26 vmkernel: 0:20:06:25.163 cpu1:4719)NMP: nmp_CompleteCommandForPath: Command 0x12 (0x41027e786a40) to NMP device "mpx.vmhba0:C0:T0:L0" failed on physical path "vmhba0:C0:T0:L0" H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0. Aug 18 07:43:26 vmkernel: 0:20:06:25.163 cpu1:4719)ScsiDeviceIO: 1672: Command 0x12 to device "mpx.vmhba0:C0:T0:L0" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0. Aug 18 07:43:26 Hostd: [2011-08-18 07:43:26.265 30382B90 error 'App'] Unable to build Durable Name dependent properties: Unable to query VPD pages from device, all paths are dead, no I/O possible. Aug 18 07:43:26 Hostd: [2011-08-18 07:43:26.315 30382B90 verbose 'App'] Looking up object with name = "firewallSystem" failed. Aug 18 07:43:26 Hostd: [2011-08-18 07:43:26.373 30382B90 verbose 'NetConfigProvider'] FetchFn: List of pnics opted out Aug 18 07:43:26 vmkernel: 0:20:06:25.704 cpu14:4511)WARNING: NMP: nmpDeviceAttemptFailover: Retry world failover device "naa.60030d90f9307b02d19dbffbcfb69805" - issuing command 0x41027eaa8140 Aug 18 07:43:26 vmkernel: 0:20:06:25.704 cpu14:4511)WARNING: NMP: nmpDeviceAttemptFailover: Retry world failover device "naa.60030d90f9307b02d19dbffbcfb69805" - failed to issue command due to Not found (APD), try again... Aug 18 07:43:26 vmkernel: 0:20:06:25.704 cpu14:4511)WARNING: NMP: nmpDeviceAttemptFailover: Logical device "naa.60030d90f9307b02d19dbffbcfb69805": awaiting fast path state update... Aug 18 07:43:26 Hostd: [2011-08-18 07:43:26.946 30382B90 verbose 'NetConfigProvider'] FetchFn: List of pnics opted out Aug 18 07:43:27 Hostd: [2011-08-18 07:43:27.466 30382B90 warning 'PropertyCollector'] ComputeGUReq took 1661176 microSec Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.481 178D5B90 verbose 'VpxaHalCnxHostagent'] Received callback in WaitForUpdatesDone Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.482 178D5B90 verbose 'VpxaHalCnxHostagent'] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 2843 to 2844 (at 2843) Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.483 178D5B90 verbose 'App'] [VpxaHalServices] HostChanged Event Fired, properties changed [config.fileSystemVolume, config.multipathState, config.storageDevice] Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.484 178D5B90 verbose 'App'] [VpxaInvtHost] Increment master gen. no to (1559): HostConfig:VpxaInvtHostListener::HostChanged(config.fileSystemVolume) Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.484 178D5B90 verbose 'App'] [VpxaInvtHost] Increment master gen. no to (1560): HostConfig:VpxaInvtHostListener::HostChanged(config.multipathState) Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.484 178D5B90 verbose 'App'] [VpxaInvtHost] Increment master gen. no to (1561): HostConfig:VpxaInvtHostListener::HostChanged(config.storageDevice) Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.487 1768DB90 verbose 'VpxaHalCnxHostagent'] Received callback in WaitForUpdatesDone Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.487 1768DB90 verbose 'VpxaHalCnxHostagent'] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 2844 to 2845 (at 2844) Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.487 1768DB90 verbose 'App'] [VpxaDatastore] url: sanfs://vmfs_uuid:4e491434-f1d58ba0-faf8-b499bab6665e/ Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.487 1768DB90 verbose 'App'] [VpxaInvtHost] Increment master gen. no (1562): DetailPropertyChanged Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.487 1768DB90 verbose 'App'] Got an EventEx (id: esx.problem.storage.connectivity.lost) Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.488 1768DB90 verbose 'App'] [VpxaHalServices] Component health event fired to the listeners. Aug 18 07:43:27 Vpxa: [2011-08-18 07:43:27.488 1768DB90 verbose 'App'] [VpxaHalServices] EventsRecorded Event Fired Aug 18 07:43:28 vmkernel: 0:20:06:27.202 cpu20:4844)iscsi_vmk: iscsivmk_ConnNetRegister: socket 0x4100a603f7b0 network resource pool netsched.pools.persist.iscsi associated Aug 18 07:43:28 iscsid: connection 1:0 (iqn.2000-08.com.datacore:tb-daco1-target1 if=default addr=172.19.1.1:3260 (TPGT:1 ISID:0x1) (T0 C0)) has recovered (2 attempts) Aug 18 07:43:28 vmkernel: 0:20:06:27.453 cpu14:4844)WARNING: iscsi_vmk: iscsivmk_StartConnection: vmhba37:CH:0 T:0 CN:0: iSCSI connection is being marked "ONLINE" Aug 18 07:43:28 vmkernel: 0:20:06:27.453 cpu14:4844)WARNING: iscsi_vmk: iscsivmk_StartConnection: Sess [ISID: 00023d000001 TARGET: iqn.2000-08.com.datacore:tb-daco1-target1 TPGT: 1 TSIH: 0] Aug 18 07:43:28 vmkernel: 0:20:06:27.453 cpu14:4844)WARNING: iscsi_vmk: iscsivmk_StartConnection: Conn [CID: 0 L: 172.19.1.11:55239 R: 172.19.1.1:3260] Aug 18 07:43:28 vmkernel: 0:20:06:27.706 cpu1:255550)vmw_psp_mru: psp_mruSelectPathToActivateInt: Changing active path from NONE to vmhba37:C0:T0:L1 for device "naa.60030d90f9307b02d19dbffbcfb69805". Aug 18 07:43:28 vobd: Aug 18 07:43:28.806: 72387706191us: [vob.scsi.scsipath.pathstate.on] scsiPath vmhba37:C0:T0:L1 changed state from dead. Aug 18 07:43:28 vmkernel: 0:20:06:27.706 cpu8:14536)NMP: nmpCompleteRetryForPath: Retry world recovered device "naa.60030d90f9307b02d19dbffbcfb69805" Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.806 FFFB5B90 verbose 'StorageSystem'] StoragePathUpdate: Invalidate Path Cache immediately Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.807 FFFB5B90 verbose 'StorageSystem'] SendStorageInfoEvent() called Aug 18 07:43:28 vobd: Aug 18 07:43:28.807: 72388224588us: [esx.clear.storage.connectivity.restored] Connectivity to storage device naa.60030d90f9307b02d19dbffbcfb69805 (Datastores: "vm1-test") restored. Path vmhba37:C0:T0:L1 is active again.. Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.807 30540B90 info 'ha-eventmgr'] Event 263 : Connectivity to storage device naa.60030d90f9307b02d19dbffbcfb69805 (Datastores: "vm1-test") restored. Path vmhba37:C0:T0:L1 is active again. Aug 18 07:43:28 vmkernel: 0:20:06:27.707 cpu4:4133)FS3: 398: Reclaimed heartbeat for volume 4e491434-f1d58ba0-faf8-b499bab6665e (vm1-test): [Timeout] [HB state abcdef02 offset 3883008 gen 21 stamp 72387706509 uuid 4e4ba7f9-f714e707-3e00-b499bab6665e Aug 18 07:43:28 jrnl drv 8.46] Aug 18 07:43:28 vobd: Aug 18 07:43:28.807: 72388225147us: [esx.problem.vmfs.heartbeat.recovered] 4e491434-f1d58ba0-faf8-b499bab6665e vm1-test. Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.807 FFCBEE80 verbose 'Hostsvc::DatastoreSystem'] VmfsVobUpdate: got Vob message [N11HostdCommon6VobMsgE:0x304e7748] timestamp=72388225114 Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.807 FFCBEE80 info 'Hostsvc::DatastoreSystem'] VmfsVobUpdate: Accessibility changed for datastore vm1-test Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.807 FFCBEE80 verbose 'FSVolumeProvider'] RefreshOneVmfsVolume on /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.808 30540B90 info 'ha-eventmgr'] Event 264 : Successfully restored access to volume 4e491434-f1d58ba0-faf8-b499bab6665e (vm1-test) following connectivity issues. Aug 18 07:43:28 vmkernel: 0:20:06:27.707 cpu3:4133)FS3: 8562: Long VMFS3 rsv time on 'vm1-test' (held for 3415 msecs). # R: 1, # W: 1 bytesXfer: 2 sectors Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.831 30BDAB90 info 'App'] CreateISCSIHBA Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.833 FFCBEE80 verbose 'Hostsvc::Datastore'] NotifyIfAccessibleChanged:: -- notify that datastore 4e491434-f1d58ba0-faf8-b499bab6665e at path /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e now has accessib Aug 18 07:43:28 ility of true Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.867 30F5AB90 verbose 'vm:/vmfs/volumes/4d810d89-c7499fb0-c827-b499bab6665e/tb-test1/tb-test1.vmx'] Time to gather config: 3060 (msecs) Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.873 30F5AB90 verbose 'vm:/vmfs/volumes/4e439658-5a45789a-c462-b499bab6665e/tb-ts1/tb-ts1.vmx'] Got DSSYS change: [N11HostdCommon18DatastoreSystemMsgE:0x30a598d8]UPDATE-NOW-DISCONNECTED, 4e491434-f1d58ba0-fa Aug 18 07:43:28 f8-b499bab6665e, /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e; Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.874 30F5AB90 verbose 'vm:/vmfs/volumes/4e439658-5a45789a-c462-b499bab6665e/tb-dc1/tb-dc1.vmx'] Got DSSYS change: [N11HostdCommon18DatastoreSystemMsgE:0x30a598d8]UPDATE-NOW-DISCONNECTED, 4e491434-f1d58ba0-fa Aug 18 07:43:28 f8-b499bab6665e, /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e; Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.874 30F5AB90 verbose 'vm:/vmfs/volumes/4e439658-5a45789a-c462-b499bab6665e/tb-fs/tb-fs.vmx'] Got DSSYS change: [N11HostdCommon18DatastoreSystemMsgE:0x30a598d8]UPDATE-NOW-DISCONNECTED, 4e491434-f1d58ba0-faf8 Aug 18 07:43:28 -b499bab6665e, /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e; Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.887 30BDAB90 info 'App'] CreateISCSIHBA Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.941 30BDAB90 info 'App'] CreateISCSIHBA Aug 18 07:43:28 Hostd: [2011-08-18 07:43:28.994 30BDAB90 info 'App'] CreateISCSIHBA Aug 18 07:43:29 Hostd: [2011-08-18 07:43:29.045 30BDAB90 info 'App'] CreateISCSIHBA Aug 18 07:43:29 vmkernel: 0:20:06:28.179 cpu11:4719)NMP: nmp_CompleteCommandForPath: Command 0x12 (0x41027e8a2840) to NMP device "mpx.vmhba0:C0:T0:L0" failed on physical path "vmhba0:C0:T0:L0" H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0. Aug 18 07:43:29 vmkernel: 0:20:06:28.179 cpu11:4719)ScsiDeviceIO: 1672: Command 0x12 to device "mpx.vmhba0:C0:T0:L0" failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0. Aug 18 07:43:29 Vpxa: [2011-08-18 07:43:29.286 17A1AB90 verbose 'VpxProfiler'] [1+] CheckEnvBrowserChanges Aug 18 07:43:29 Hostd: [2011-08-18 07:43:29.302 30581B90 verbose 'DvsTracker'] FetchSwitches: added 0 items Aug 18 07:43:29 Hostd: [2011-08-18 07:43:29.302 30581B90 verbose 'DvsTracker'] FetchDVPortgroups: added 0 items Aug 18 07:43:29 Vpxa: [2011-08-18 07:43:29.346 17A1AB90 verbose 'VpxProfiler'] [1-] CheckEnvBrowserChanges (took 59 ms) Aug 18 07:43:29 Hostd: [2011-08-18 07:43:29.366 30BDAB90 verbose 'App'] Looking up object with name = "firewallSystem" failed. Aug 18 07:43:29 Hostd: [2011-08-18 07:43:29.425 30BDAB90 verbose 'NetConfigProvider'] FetchFn: List of pnics opted out Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.007 30BDAB90 verbose 'NetConfigProvider'] FetchFn: List of pnics opted out Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.526 30F5AB90 verbose 'vm:/vmfs/volumes/4e439658-5a45789a-c462-b499bab6665e/tb-db/tb-db.vmx'] Got DSSYS change: [N11HostdCommon18DatastoreSystemMsgE:0x30636098]UPDATE-NOW-AVAILABLE, 4e491434-f1d58ba0-faf8-b4 Aug 18 07:43:30 99bab6665e, /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e; Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.526 30F5AB90 verbose 'vm:/vmfs/volumes/4d810d89-c7499fb0-c827-b499bab6665e/tb-test1/tb-test1.vmx'] Got DSSYS change: [N11HostdCommon18DatastoreSystemMsgE:0x30636098]UPDATE-NOW-AVAILABLE, 4e491434-f1d58ba0-f Aug 18 07:43:30 af8-b499bab6665e, /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e; Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.526 30F5AB90 info 'vm:/vmfs/volumes/4d810d89-c7499fb0-c827-b499bab6665e/tb-test1/tb-test1.vmx'] VM Datastore updates for device file backing, refresh config Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.529 30BDAB90 warning 'PropertyCollector'] ComputeGUReq took 1722498 microSec Aug 18 07:43:30 Vpxa: [2011-08-18 07:43:30.546 178D5B90 verbose 'VpxaHalCnxHostagent'] Received callback in WaitForUpdatesDone Aug 18 07:43:30 Vpxa: [2011-08-18 07:43:30.546 178D5B90 verbose 'VpxaHalCnxHostagent'] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 2845 to 2846 (at 2845) Aug 18 07:43:30 Vpxa: [2011-08-18 07:43:30.548 178D5B90 verbose 'App'] [VpxaHalServices] HostChanged Event Fired, properties changed [config.fileSystemVolume, config.multipathState, config.storageDevice] Aug 18 07:43:30 Vpxa: [2011-08-18 07:43:30.548 178D5B90 verbose 'App'] [VpxaInvtHost] Increment master gen. no to (1563): HostConfig:VpxaInvtHostListener::HostChanged(config.fileSystemVolume) Aug 18 07:43:30 Vpxa: [2011-08-18 07:43:30.548 178D5B90 verbose 'App'] [VpxaInvtHost] Increment master gen. no to (1564): HostConfig:VpxaInvtHostListener::HostChanged(config.multipathState) Aug 18 07:43:30 Vpxa: [2011-08-18 07:43:30.548 178D5B90 verbose 'App'] [VpxaInvtHost] Increment master gen. no to (1565): HostConfig:VpxaInvtHostListener::HostChanged(config.storageDevice) Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.590 30BDAB90 verbose 'App'] Looking up object with name = "firewallSystem" failed. Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.647 30BDAB90 verbose 'NetConfigProvider'] FetchFn: List of pnics opted out Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.668 30F5AB90 verbose 'vm:/vmfs/volumes/4d810d89-c7499fb0-c827-b499bab6665e/tb-test1/tb-test1.vmx'] Time to gather config: 140 (msecs) Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.675 30F5AB90 verbose 'vm:/vmfs/volumes/4e439658-5a45789a-c462-b499bab6665e/tb-ts1/tb-ts1.vmx'] Got DSSYS change: [N11HostdCommon18DatastoreSystemMsgE:0x30636098]UPDATE-NOW-AVAILABLE, 4e491434-f1d58ba0-faf8- Aug 18 07:43:30 b499bab6665e, /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e; Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.675 30F5AB90 verbose 'vm:/vmfs/volumes/4e439658-5a45789a-c462-b499bab6665e/tb-dc1/tb-dc1.vmx'] Got DSSYS change: [N11HostdCommon18DatastoreSystemMsgE:0x30636098]UPDATE-NOW-AVAILABLE, 4e491434-f1d58ba0-faf8- Aug 18 07:43:30 b499bab6665e, /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e; Aug 18 07:43:30 Hostd: [2011-08-18 07:43:30.675 30F5AB90 verbose 'vm:/vmfs/volumes/4e439658-5a45789a-c462-b499bab6665e/tb-fs/tb-fs.vmx'] Got DSSYS change: [N11HostdCommon18DatastoreSystemMsgE:0x30636098]UPDATE-NOW-AVAILABLE, 4e491434-f1d58ba0-faf8-b4 Aug 18 07:43:30 99bab6665e, /vmfs/volumes/4e491434-f1d58ba0-faf8-b499bab6665e;