RCA 33: Having issues with VMFS Mount

Hostname: pplzesxic10.xyz.abc.net 

ESXi Version: ESXi 6.7 P01

 

Time of Issue: around 7:30AM PHT

Time in GMT: 11:30 PM GMT 4th Oct

 

vmhba

driver

driver version

VID

DID

SVID

SDID

model

vmhba0

lsi_mr3

7.710.07.00-1OEM.670.0.0.8169922

1000

005d

1028

1f47

Broadcom PERC H730P Mini

vmhba1

vmw_ahci

1.2.8-1vmw.670.3.73.14320388

8086

8d62

1028

627

Intel Corporation Wellsburg AHCI Controller

vmhba2

vmw_ahci

1.2.8-1vmw.670.3.73.14320388

8086

8d02

1028

627

Intel Corporation Wellsburg AHCI Controller

vmhba3

qlnativefc

3.1.31.0-1OEM.670.0.0.8169922

1077

2532

1077

015c

QLogic Corp ISP2532-based 8Gb Fibre Channel to PCI Express HBA

vmhba4

qlnativefc

3.1.31.0-1OEM.670.0.0.8169922

1077

2532

1077

015c

QLogic Corp ISP2532-based 8Gb Fibre Channel to PCI Express HBA

vmhba5

lsi_mr3

7.710.07.00-1OEM.670.0.0.8169922

1000

005d

1028

1f42

Broadcom PERC H730P Adapter

 

 

Shell Logs:

 

  • From the Shell Logs we can see that the First Mount Operation was initiated around 21:04 GMT.

 

2020-10-03T21:04:58Z shell[3520709]: [root]: esxcfg-volume -r “PMAX2_ABCRESSO1”
2020-10-03T21:07:01Z shell[3520709]: [root]: esxcfg-volume -r “PMAX2_ABCRESSO3”
2020-10-03T21:07:20Z shell[3520709]: [root]: esxcfg-volume -r “PMAX2_ABCRESSO2”
2020-10-03T21:08:23Z shell[3520709]: [root]: esxcfg-volume -r “PMAX2_M_ABCRESSO1”
2020-10-03T21:08:48Z shell[3520709]: [root]: esxcfg-volume -r “PMAX2_ABCRESSO_X”

 

  • Later Second Mount Operation was initiated around 

 

2020-10-03T23:14:03Z shell[3537666]: [root]: esxcfg-volume -M “PMAX2_ABCRESSO1”
2020-10-03T23:17:26Z shell[3537666]: [root]: esxcfg-volume -M “PMAX2_ABCRESSO2”
2020-10-03T23:17:50Z shell[3537666]: [root]: esxcfg-volume -M “PMAX2_ABCRESSO3”
2020-10-03T23:20:25Z shell[3537666]: [root]: esxcfg-volume -M “PMAX2_ABCRESSO3”
2020-10-03T23:22:25Z shell[3537666]: [root]: esxcfg-volume -M “PMAX2_ABCRESSO3”
2020-10-03T23:23:04Z shell[3537666]: [root]: esxcfg-volume -M “PMAX2_ABCRESSO_X”
2020-10-03T23:23:48Z shell[3537666]: [root]: esxcfg-volume -M “PMAX2_M_ABCRESSO1”

 

  • The Last Attempt can be seen made on 4th around 3:02 AM.

 

2020-10-04T03:02:54Z shell[2123919]: [root]: esxcfg-volume -M PMAX2_ACSDB
2020-10-04T05:53:14Z shell[2140208]: [root]: esxcfg-volume -M “PMAX2_ABCRESSO1”
2020-10-04T05:56:01Z shell[2140469]: [root]: esxcfg-volume -M “PMAX2_ABCRESSO2”
2020-10-04T06:00:42Z shell[2141643]: [root]: esxcfg-volume -M “PMAX2_ABCRESSO3”
2020-10-04T06:03:51Z shell[2141643]: [root]: esxcfg-volume -M “PMAX2_ABCRESSO_X”
2020-10-04T06:07:32Z shell[2141643]: [root]: esxcfg-volume -M “PMAX2_M_ABCRESSO1”

 

 

VOBD Logs:

 

  • Checked the VOBD Logs and we can see the events for the Volume being Mounted in rw Mode.

 

2020-10-03T23:14:13.143Z: [vmfsCorrelator] 895904822619us: [vob.vmfs.volume.mounted] File system ‘[PMAX2_ABCRESSO1, 5e35e84e-7f0bdeae-997c-b49691170364]’ (LV snap-1807086a-5ccc1f93-2be15dfb-c689-a0369fceaf40) mounted in ‘rw’ mode.
2020-10-03T23:14:13.144Z: [vmfsCorrelator] 895912237134us: [esx.audit.vmfs.volume.mounted] File system [PMAX2_ABCRESSO1, 5e35e84e-7f0bdeae-997c-b49691170364] on volume snap-1807086a-5ccc1f93-2be15dfb-c689-a0369fceaf40 has been mounted in ‘rw’ mode. The datastore is now accessible on this host.

2020-10-03T23:17:36.766Z: [vmfsCorrelator] 896108443104us: [vob.vmfs.volume.mounted] File system ‘[PMAX2_ABCRESSO2, 5e35e893-76c7a8cc-40ef-b496911705a4]’ (LV snap-2f7387e5-5ccc2043-14413d56-8c58-a0369fceaf40) mounted in ‘rw’ mode.
2020-10-03T23:17:36.766Z: [vmfsCorrelator] 896115859320us: [esx.audit.vmfs.volume.mounted] File system [PMAX2_ABCRESSO2, 5e35e893-76c7a8cc-40ef-b496911705a4] on volume snap-2f7387e5-5ccc2043-14413d56-8c58-a0369fceaf40 has been mounted in ‘rw’ mode. The datastore is now accessible on this host.

2020-10-03T23:20:01.412Z: [vmfsCorrelator] 896253088055us: [vob.vmfs.volume.mounted] File system ” (LV snap-794c7be3-5ccc20bd-69e4c9cb-7660-a0369fceaf40) mounted in ‘rw’ mode.
2020-10-03T23:20:01.412Z: [vmfsCorrelator] 896260505665us: [esx.audit.vmfs.volume.mounted] File system  on volume snap-794c7be3-5ccc20bd-69e4c9cb-7660-a0369fceaf40 has been mounted in ‘rw’ mode. The datastore is now accessible on this host.

 

2020-10-03T23:23:14.575Z: [vmfsCorrelator] 896446248851us: [vob.vmfs.volume.mounted] File system ‘[PMAX2_ABCRESSO_X, 5f2bf331-be548372-dd0c-a0369fceaf40]’ (LV 5f2bf331-758cc522-1a52-a0369fceaf40) mounted in ‘rw’ mode.
2020-10-03T23:23:14.575Z: [vmfsCorrelator] 896453668153us: [esx.audit.vmfs.volume.mounted] File system [PMAX2_ABCRESSO_X, 5f2bf331-be548372-dd0c-a0369fceaf40] on volume 5f2bf331-758cc522-1a52-a0369fceaf40 has been mounted in ‘rw’ mode. The datastore is now accessible on this host.
2020-10-03T23:25:57.802Z: [vmfsCorrelator] 896609474432us: [vob.vmfs.volume.mounted] File system ” (LV snap-1a8cbddb-5d309e9a-83f0ecd1-7edd-0894ef0fbfb4) mounted in ‘rw’ mode.
2020-10-03T23:25:57.802Z: [vmfsCorrelator] 896616895172us: [esx.audit.vmfs.volume.mounted] File system  on volume snap-1a8cbddb-5d309e9a-83f0ecd1-7edd-0894ef0fbfb4 has been mounted in ‘rw’ mode. The datastore is now accessible on this host.

 

2020-10-04T01:38:18.227Z: An event (esx.audit.net.firewall.config.changed) could not be sent immediately to hostd; queueing for retry.
2020-10-04T01:38:18.227Z: An event (esx.audit.net.firewall.config.changed) could not be sent immediately to hostd; queueing for retry.
2020-10-04T01:38:18.227Z: An event (esx.audit.net.firewall.config.changed) could not be sent immediately to hostd; queueing for retry.

 

VMKernel Logs:

 

  • Doesn’t have the logs for the time of issue 21:00 and 23:00 on 3rd when initially two command sets were ran to Mount the Datastore.

 

  • Looking into the logs for 4th we can see below:

 

  • Initially we can see that the logs are filed with the below SCSI Errors: The sense code D:0x2 indicates that there is a check condition received for the device.

 

2020-10-04T05:16:32.701Z cpu78:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030304346” occurred 1 times(of 1 commands)
2020-10-04T05:16:32.701Z cpu78:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303732” occurred 1 times(of 1 commands)
2020-10-04T05:16:32.701Z cpu78:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303632” occurred 1 times(of 1 commands)
2020-10-04T05:16:32.701Z cpu78:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303734” occurred 1 times(of 1 commands)
2020-10-04T05:16:32.701Z cpu78:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303735” occurred 1 times(of 1 commands)
2020-10-04T05:16:32.701Z cpu78:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303245” occurred 1 times(of 1 commands)
2020-10-04T05:16:32.701Z cpu78:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303246” occurred 1 times(of 1 commands)

2020-10-04T05:17:48.650Z cpu71:2098321)ScsiDeviceIO: 3435: Cmd(0x45a3416b2700) 0x1a, CmdSN 0xf2e43 from world 0 to dev “naa.66666660212f220022317f3e14aeb3d0” failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.
2020-10-04T05:27:32.707Z cpu11:2098275)DVFilter: 5963: Checking disconnected filters for timeouts
2020-10-04T05:28:21.685Z cpu56:2098321)ScsiDeviceIO: 3435: Cmd(0x45a5a12bcc80) 0x1a, CmdSN 0xff151 from world 0 to dev “naa.66666660212f220022317f3e14aeb3d0” failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.
2020-10-04T05:37:32.712Z cpu26:2098275)DVFilter: 5963: Checking disconnected filters for timeouts
2020-10-04T05:37:49.305Z cpu28:2098320)ScsiDeviceIO: 3435: Cmd(0x459d86f3e5c0) 0x1a, CmdSN 0x106e09 from world 0 to dev “naa.66666660212f220022317f3e14aeb3d0” failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.
2020-10-04T05:45:54.920Z cpu25:2098320)ScsiDeviceIO: 3435: Cmd(0x459db0839480) 0x85, CmdSN 0x113c from world 2106407 to dev “naa.66666660212f220022317f3e14aeb3d0” failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.

 

2020-10-04T05:46:32.716Z cpu47:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303836” occurred 1 times(of 1 commands)
2020-10-04T05:46:32.717Z cpu47:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303330” occurred 1 times(of 1 commands)
2020-10-04T05:46:32.717Z cpu47:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303344” occurred 1 times(of 1 commands)
2020-10-04T05:46:32.717Z cpu47:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303245” occurred 1 times(of 1 commands)
2020-10-04T05:46:32.717Z cpu47:2098204)NMP: nmp_ResetDeviceLogThrottling:3580: Error status H:0x0 D:0x2 P:0x0 Sense Data: 0x5 0x20 0x0 from dev “naa.66660970000297900151533030303246” occurred 1 times(of 1 commands)

 

  • In the Last Occurrence I can see the volumes being Mounted.

 

2020-10-04T05:53:21.435Z cpu14:2140226)WARNING: NFS: 1227: Invalid volume UUID snap-1807086a-5ccc1f93-2be15dfb-c689-a0369fceaf40 ::: ABCRESSO1

 

2020-10-04T05:53:21.491Z cpu14:2140226)LVM: 16756: File system ‘[PMAX2_ABCRESSO1, 5e35e84e-7f0bdeae-997c-b49691170364]’ (LV snap-1807086a-5ccc1f93-2be15dfb-c689-a0369fceaf40) mounted in ‘rw’ mode.
2020-10-04T05:56:08.233Z cpu25:2140593)WARNING: NFS: 1227: Invalid volume UUID snap-2f7387e5-5ccc2043-14413d56-8c58-a0369fceaf40::: ABCRESSO2

 

2020-10-04T05:56:08.273Z cpu25:2140593)LVM: 16756: File system ‘[PMAX2_ABCRESSO2, 5e35e893-76c7a8cc-40ef-b496911705a4]’ (LV snap-2f7387e5-5ccc2043-14413d56-8c58-a0369fceaf40) mounted in ‘rw’ mode.

2020-10-04T06:00:49.292Z cpu49:2141662)WARNING: NFS: 1227: Invalid volume UUID snap-794c7be3-5ccc20bd-69e4c9cb-7660-a0369fceaf40:::PMAX2_ABCRESSO3
2020-10-04T06:00:49.348Z cpu49:2141662)LVM: 16756: File system ‘[PMAX2_ABCRESSO3, 5e35e892-095edfa6-293c-e4434b69290e]’ (LV snap-794c7be3-5ccc20bd-69e4c9cb-7660-a0369fceaf40) mounted in ‘rw’ mode.

2020-10-04T06:03:58.235Z cpu50:2142208)LVM: 16756: File system ‘[PMAX2_ABCRESSO_X, 5f2bf331-be548372-dd0c-a0369fceaf40]’ (LV 5f2bf331-758cc522-1a52-a0369fceaf40) mounted in ‘rw’ mode.
2020-10-04T06:07:38.860Z cpu25:2142548)WARNING: NFS: 1227: Invalid volume UUID snap-1a8cbddb-5d309e9a-83f0ecd1-7edd-0894ef0fbfb4:::PMAX2_M_ABCRESSO1
2020-10-04T06:07:38.909Z cpu25:2142548)LVM: 16756: File system ‘[PMAX2_M_ABCRESSO1, 5e35e893-e99c5eab-9c9f-b49691170848]’ (LV snap-1a8cbddb-5d309e9a-83f0ecd1-7edd-0894ef0fbfb4) mounted in ‘rw’ mode.

 

  • Here we can see the VM started.

 

2020-10-04T06:11:39.460Z cpu76:2143015)World: vm 2143016: 7076: Starting world vmm0:ABCRESSO1 of type 8
2020-10-04T06:11:39.460Z cpu76:2143015)Sched: vm 2143016: 6206: Adding world ‘vmm0:ABCRESSO1’, group ‘host/user’, cpu: shares=-3 min=0 minLimit=-1 max=-1, mem: shares=-3 min=0 minLimit=-1 max=-1

 

 

Hostd Logs:

 

  • From the Hostd Logs we can see the Mount Events coming to the Service.

 

2020-10-03T21:05:04.638Z info hostd[2518315] [Originator@6876 sub=Hostsvc.DatastoreSystem] Received volume event [N11HostdCommon13VolumeMessageE:0x000000ad5261ee10] timestamp=888156387966 eventType=VMK_REL_EVT_VOLUME_MOUNTED volumeUUID=5f78e780-10099162-b276-b49691170784 volumeLabel=snap-128a9ca2-PMAX2_ABCRESSO1 deviceName=snap-3c2845b8-5ccc1f93-2be15dfb-c689-a0369fceaf40

2020-10-03T21:05:04.673Z info hostd[2518314] [Originator@6876 sub=Vslmsvc.DatastoreStateListener] ReceiveDatastoreChange: Processing msg: [N11HostdCommon18DatastoreSystemMsgE:0x000000ad5138e490]DatastoreSystemMsg::DsChange{Type=ADD, Msg=DatastoreAddedMsg{DatastoreMsg{Type=1, MoId=5f78e780-10099162-b276-b49691170784, Path=/vmfs/volumes/5f78e780-10099162-b276-b49691170784}, Name=snap-128a9ca2-PMAX2_ABCRESSO1, WorkloadParams=WorkloadParams{outstandingIO(K1)=2, ioSize(K2)=20, readPercent(K3)=0.05, randomPercent(K4)=0.4}}};

 

2020-10-03T21:05:14.994Z warning hostd[2518130] [Originator@6876 sub=Libs] VmFileSystem: Skipping volume snap-2853955a-59a80ec3-0e4d5faf-1f29-0894ef0fbfb4: Unable to complete Sysinfo operation.  Please see the VMkernel log file for more details.: Sysinfo error: Read onlySee VMkernel log for details.

 

2020-10-03T21:07:08.331Z info hostd[2518315] [Originator@6876 sub=Hostsvc.DatastoreSystem] Received volume event [N11HostdCommon13VolumeMessageE:0x000000ad4fad3d40] timestamp=888280079787 eventType=VMK_REL_EVT_VOLUME_MOUNTED volumeUUID=5f78e7fc-6bc386f3-4bb1-b49691170784 volumeLabel=snap-296f3734-PMAX2_ABCRESSO3 deviceName=snap-61c17ad5-5ccc20bd-69e4c9cb-7660-a0369fceaf40

 

2020-10-03T21:07:08.332Z info hostd[2518315] [Originator@6876 sub=Libs] OBJLIB-LIB:  Failed to get VCFS root path for ‘/vmfs/volumes/5e3006e9-07093e90-5260-a0369fceac46’: No such file or directory (131076).
2020-10-03T21:07:08.332Z info hostd[2518315] [Originator@6876 sub=Libs] FILE: FileVMKGetMaxFileSize: Could not get max file size for path: /vmfs/volumes/5e3006e9-07093e90-5260-a0369fceac46, error: Inappropriate ioctl for device
2020-10-03T21:07:08.332Z info hostd[2518315] [Originator@6876 sub=Libs] FILE: FileVMKGetMaxOrSupportsFileSize: File_GetVMFSAttributes Failed
2020-10-03T21:07:08.332Z info hostd[2518315] [Originator@6876 sub=Libs] OBJLIB-LIB: ObjLib_GetMaxSizeInfo: failed. Obj backend type: file, Path: /vmfs/volumes/5e3006e9-07093e90-5260-a0369fceac46, Error: Unknown object error
2020-10-03T21:07:08.332Z error hostd[2518315] [Originator@6876 sub=Hostsvc.Datastore] Cannot retrieve max file size from objLib for /vmfs/volumes/5e3006e9-07093e90-5260-a0369fceac46, error 25, revert to default
2020-10-03T21:07:08.332Z info hostd[2518315] [Originator@6876 sub=Libs] OBJLIB-LIB:  Failed to get VCFS root path for ‘/vmfs/volumes/5e261256-911f2706-05cd-b49691170e64’: No such file or directory (131076).
2020-10-03T21:07:08.333Z info hostd[2518315] [Originator@6876 sub=Libs] FILE: FileVMKGetMaxFileSize: Could not get max file size for path: /vmfs/volumes/5e261256-911f2706-05cd-b49691170e64, error: Inappropriate ioctl for device
2020-10-03T21:07:08.333Z info hostd[2518315] [Originator@6876 sub=Libs] FILE: FileVMKGetMaxOrSupportsFileSize: File_GetVMFSAttributes Failed

2020-10-03T21:07:08.335Z info hostd[2518315] [Originator@6876 sub=Libs] OBJLIB-LIB: ObjLib_GetMaxSizeInfo: failed. Obj backend type: file, Path: /vmfs/volumes/5e261a82-286efe34-51ef-b49691170e64, Error: Unknown object error
2020-10-03T21:07:08.335Z error hostd[2518315] [Originator@6876 sub=Hostsvc.Datastore] Cannot retrieve max file size from objLib for /vmfs/volumes/5e261a82-286efe34-51ef-b49691170e64, error 25, revert to default
2020-10-03T21:07:08.392Z info hostd[2518299] [Originator@6876 sub=Vslmsvc.DatastoreStateListener] ReceiveDatastoreChange: Processing msg: [N11HostdCommon18DatastoreSystemMsgE:0x000000ad4fa97ff0]DatastoreSystemMsg::DsChange{Type=ADD, Msg=DatastoreAddedMsg{DatastoreMsg{Type=1, MoId=5f78e7fc-6bc386f3-4bb1-b49691170784, Path=/vmfs/volumes/5f78e7fc-6bc386f3-4bb1-b49691170784}, Name=snap-296f3734-PMAX2_ABCRESSO3, WorkloadParams=WorkloadParams{outstandingIO(K1)=2, ioSize(K2)=20, readPercent(K3)=0.05, randomPercent(K4)=0.4}}};
2020-10-03T21:07:18.713Z warning hostd[2518316] [Originator@6876 sub=Libs] VmFileSystem: Skipping volume snap-2853955a-59a80ec3-0e4d5faf-1f29-0894ef0fbfb4: Unable to complete Sysinfo operation.  Please see the VMkernel log file for more details.: Sysinfo error: Read onlySee VMkernel log for details.

 

 

2020-10-03T21:07:26.566Z info hostd[2518207] [Originator@6876 sub=Hostsvc.DatastoreSystem] Received volume event [N11HostdCommon13VolumeMessageE:0x000000ad52738fa0] timestamp=888298313952 eventType=VMK_REL_EVT_VOLUME_MOUNTED volumeUUID=5f78e80e-c2d2f033-f2e5-b49691170784 volumeLabel=snap-1c8d78ab-PMAX2_ABCRESSO2 deviceName=snap-3a6bf598-5ccc2043-14413d56-8c58-a0369fceaf40
2020-10-03T21:07:26.566Z info hostd[2518207] [Originator@6876 sub=Libs] OBJLIB-LIB:  Failed to get VCFS root path for ‘/vmfs/volumes/5e3006e9-07093e90-5260-a0369fceac46’: No such file or directory (131076).
2020-10-03T21:07:26.566Z info hostd[2518207] [Originator@6876 sub=Libs] FILE: FileVMKGetMaxFileSize: Could not get max file size for path: /vmfs/volumes/5e3006e9-07093e90-5260-a0369fceac46, error: Inappropriate ioctl for device
2020-10-03T21:07:26.566Z info hostd[2518207] [Originator@6876 sub=Libs] FILE: FileVMKGetMaxOrSupportsFileSize: File_GetVMFSAttributes Failed
2020-10-03T21:07:26.609Z info hostd[2518309] [Originator@6876 sub=Vslmsvc.DatastoreStateListener] ReceiveDatastoreChange: Processing msg: [N11HostdCommon18DatastoreSystemMsgE:0x000000ad512f3010]DatastoreSystemMsg::DsChange{Type=ADD, Msg=DatastoreAddedMsg{DatastoreMsg{Type=1, MoId=5f78e80e-c2d2f033-f2e5-b49691170784, Path=/vmfs/volumes/5f78e80e-c2d2f033-f2e5-b49691170784}, Name=snap-1c8d78ab-PMAX2_ABCRESSO2, WorkloadParams=WorkloadParams{outstandingIO(K1)=2, ioSize(K2)=20, readPercent(K3)=0.05, randomPercent(K4)=0.4}}};
2020-10-03T21:07:29.112Z info hostd[2522988] [Originator@6876 sub=Vimsvc opID=40e3b090] [Auth]: User nagios
2020-10-03T21:07:36.795Z warning hostd[2518130] [Originator@6876 sub=Libs] VmFileSystem: Skipping volume snap-2853955a-59a80ec3-0e4d5faf-1f29-0894ef0fbfb4: Unable to complete Sysinfo operation.  Please see the VMkernel log file for more details.: Sysinfo error: Read onlySee VMkernel log for details.

 

 

  • Here we can see the Events of the Startup operation for the VM for the First Time. It failed with the Error Unable to Find the Files.

 

2020-10-03T21:12:01.536Z info hostd[2518317] [Originator@6876 sub=Solo.HaVMFolder opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] Register called: []/vmfs/volumes/5f78e780-10099162-b276-b49691170784/ABCRESSO1/ABCRESSO1.vmx
2020-10-03T21:12:01.540Z info hostd[2518317] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5f78e780-10099162-b276-b49691170784/ABCRESSO1/ABCRESSO1.vmx opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SetVmxVersion: switching environment browser to vmx version ‘vmx-11’
2020-10-03T21:12:01.543Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e892-095edfa6-293c-e4434b69290e/ABCRESSO1/ABCRESSO1.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e893-76c7a8cc-40ef-b496911705a4/ABCRESSO1/ABCRESSO1_5.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e892-095edfa6-293c-e4434b69290e/ABCRESSO1/ABCRESSO1_1.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_1.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_2.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e892-095edfa6-293c-e4434b69290e/ABCRESSO1/ABCRESSO1_2.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_3.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_4.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_5.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_6.vmdk’
2020-10-03T21:12:01.544Z info hostd[2518317] [Originator@6876 sub=Libs opID=kdhgg2tr-7566715-auto-4i6ik-h5:70631037-a1-01-2b-b3d0 user=vpxuser:VSPHERE.LOCAL\dcouser] SNAPSHOT: SnapshotConfigExtFinder: Unable to find file: ‘/vmfs/volumes/5f2bf331-be548372-dd0c-a0369fceaf40/ABCRESSO1/ABCRESSO1.vmdk’

 

 

  • Later for the Third Try we can see the Volumes Being Mounted:

 

2020-10-04T05:53:21.492Z info hostd[2120088] [Originator@6876 sub=Hostsvc.DatastoreSystem] Received volume event [N11HostdCommon13VolumeMessageE:0x000000a6bd69b4e0] timestamp=15348771633 eventType=VMK_REL_EVT_VOLUME_MOUNTED volumeUUID=5e35e84e-7f0bdeae-997c-b49691170364 volumeLabel=PMAX2_ABCRESSO1 deviceName=snap-1807086a-5ccc1f93-2be15dfb-c689-a0369fceaf40
2020-10-04T05:53:21.493Z info hostd[2119813] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 605 : File system [PMAX2_ABCRESSO1, 5e35e84e-7f0bdeae-997c-b49691170364] on volume snap-1807086a-5ccc1f93-2be15dfb-c689-a0369fceaf40 has been mounted in rw mode on this host.

 

2020-10-04T05:56:08.274Z info hostd[2106778] [Originator@6876 sub=Hostsvc.DatastoreSystem] Received volume event [N11HostdCommon13VolumeMessageE:0x000000a6bd6ce5e0] timestamp=15515551884 eventType=VMK_REL_EVT_VOLUME_MOUNTED volumeUUID=5e35e893-76c7a8cc-40ef-b496911705a4 volumeLabel=PMAX2_ABCRESSO2 deviceName=snap-2f7387e5-5ccc2043-14413d56-8c58-a0369fceaf40
2020-10-04T05:56:08.275Z info hostd[2106129] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 612 : File system [PMAX2_ABCRESSO2, 5e35e893-76c7a8cc-40ef-b496911705a4] on volume snap-2f7387e5-5ccc2043-14413d56-8c58-a0369fceaf40 has been mounted in rw mode on this host.

2020-10-04T06:00:49.348Z info hostd[2106011] [Originator@6876 sub=Hostsvc.DatastoreSystem] Received volume event [N11HostdCommon13VolumeMessageE:0x000000a6beddf490] timestamp=15796624345 eventType=VMK_REL_EVT_VOLUME_MOUNTED volumeUUID=5e35e892-095edfa6-293c-e4434b69290e volumeLabel=PMAX2_ABCRESSO3 deviceName=snap-794c7be3-5ccc20bd-69e4c9cb-7660-a0369fceaf40
2020-10-04T06:00:49.349Z info hostd[2119818] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 636 : File system [PMAX2_ABCRESSO3, 5e35e892-095edfa6-293c-e4434b69290e] on volume snap-794c7be3-5ccc20bd-69e4c9cb-7660-a0369fceaf40 has been mounted in rw mode on this host.

2020-10-04T06:03:58.236Z info hostd[2119818] [Originator@6876 sub=Hostsvc.DatastoreSystem] Received volume event [N11HostdCommon13VolumeMessageE:0x000000a6bef3b490] timestamp=15985510035 eventType=VMK_REL_EVT_VOLUME_MOUNTED volumeUUID=5f2bf331-be548372-dd0c-a0369fceaf40 volumeLabel=PMAX2_ABCRESSO_X deviceName=5f2bf331-758cc522-1a52-a0369fceaf40
2020-10-04T06:03:58.237Z info hostd[2119823] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 649 : File system [PMAX2_ABCRESSO_X, 5f2bf331-be548372-dd0c-a0369fceaf40] on volume 5f2bf331-758cc522-1a52-a0369fceaf40 has been mounted in rw mode on this host.

2020-10-04T06:07:38.910Z info hostd[2106778] [Originator@6876 sub=Hostsvc.DatastoreSystem] Received volume event [N11HostdCommon13VolumeMessageE:0x000000a6be708330] timestamp=16206182600 eventType=VMK_REL_EVT_VOLUME_MOUNTED volumeUUID=5e35e893-e99c5eab-9c9f-b49691170848 volumeLabel=PMAX2_M_ABCRESSO1 deviceName=snap-1a8cbddb-5d309e9a-83f0ecd1-7edd-0894ef0fbfb4
2020-10-04T06:07:38.911Z info hostd[2120085] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 662 : File system [PMAX2_M_ABCRESSO1, 5e35e893-e99c5eab-9c9f-b49691170848] on volume snap-1a8cbddb-5d309e9a-83f0ecd1-7edd-0894ef0fbfb4 has been mounted in rw mode on this host.

 

  • Tried to Register the VM:

 

2020-10-04T06:09:21.731Z info hostd[2106828] [Originator@6876 sub=Vimsvc.TaskManager opID=kdhgg2tr-7744315-auto-4lzjw-h5:70651880-3-01-69-2b0d user=vpxuser:VSPHERE.LOCAL\newyr888] Task Created : haTask-ha-folder-vm-vim.Folder.registerVm-7973
2020-10-04T06:09:21.732Z info hostd[2119824] [Originator@6876 sub=Solo.HaVMFolder opID=kdhgg2tr-7744315-auto-4lzjw-h5:70651880-3-01-69-2b0d user=vpxuser:VSPHERE.LOCAL\newyr888] Register called: []/vmfs/volumes/5e35e84e-7f0bdeae-997c-b49691170364/ABCRESSO1/ABCRESSO1.vmx
2020-10-04T06:09:21.737Z info hostd[2119824] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5e35e84e-7f0bdeae-997c-b49691170364/ABCRESSO1/ABCRESSO1.vmx opID=kdhgg2tr-7744315-auto-4lzjw-h5:70651880-3-01-69-2b0d user=vpxuser:VSPHERE.LOCAL\newyr888] SetVmxVersion: switching environment browser to vmx version ‘vmx-11’

  • It failed with the Invalid Configuration error.

 

2020-10-04T06:09:21.883Z warning hostd[2119824] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5e35e84e-7f0bdeae-997c-b49691170364/ABCRESSO1/ABCRESSO1.vmx opID=kdhgg2tr-7744315-auto-4lzjw-h5:70651880-3-01-69-2b0d user=vpxuser:VSPHERE.LOCAL\newyr888] CannotRetrieveCorefiles: VM is in an invalid state
2020-10-04T06:09:21.921Z warning hostd[2119824] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5e35e84e-7f0bdeae-997c-b49691170364/ABCRESSO1/ABCRESSO1.vmx opID=kdhgg2tr-7744315-auto-4lzjw-h5:70651880-3-01-69-2b0d user=vpxuser:VSPHERE.LOCAL\newyr888] File – failed to get objectId, ‘/vmfs/volumes/5e35e84e-7f0bdeae-997c-b49691170364/ABCRESSO1/ABCRESSO1.vmx’: Operation not supported (11)

2020-10-04T06:09:21.988Z info hostd[2119824] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5e35e84e-7f0bdeae-997c-b49691170364/ABCRESSO1/ABCRESSO1.vmx opID=kdhgg2tr-7744315-auto-4lzjw-h5:70651880-3-01-69-2b0d user=vpxuser:VSPHERE.LOCAL\newyr888] State Transition (VM_STATE_INITIALIZING -> VM_STATE_OFF)

 

 

2020-10-04T06:09:21.992Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e84e-7f0bdeae-997c-b49691170364/ABCRESSO1/ABCRESSO1_6.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.993Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e84e-7f0bdeae-997c-b49691170364/ABCRESSO1/ABCRESSO1_1.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.993Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e892-095edfa6-293c-e4434b69290e/ABCRESSO1/ABCRESSO1.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.994Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e84e-7f0bdeae-997c-b49691170364/ABCRESSO1/ABCRESSO1_3.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.994Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e84e-7f0bdeae-997c-b49691170364/ABCRESSO1/ABCRESSO1_4.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.995Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e893-76c7a8cc-40ef-b496911705a4/ABCRESSO1/ABCRESSO1_5.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.995Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e892-095edfa6-293c-e4434b69290e/ABCRESSO1/ABCRESSO1_1.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.995Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.996Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_1.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.996Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_2.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.997Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e892-095edfa6-293c-e4434b69290e/ABCRESSO1/ABCRESSO1_2.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.997Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_3.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.998Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_4.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.998Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_5.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.999Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5e35e893-e99c5eab-9c9f-b49691170848/ABCRESSO1_1/ABCRESSO1_6.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.
2020-10-04T06:09:21.999Z warning hostd[2106129] [Originator@6876 sub=Vslmsvc] Disk /vmfs/volumes/5f2bf331-be548372-dd0c-a0369fceaf40/ABCRESSO1/ABCRESSO1.vmdk is not vstorage object. Legacy disks are not considered for state change consumed. Skip this disk.

 

 

Conclusion:

 

 

 

  • In our scenario we see the Error: VM is in an invalid state while trying to turn it on and the VM is not able to find its dependencies.

 

  • In these issues it’s better to capture the logs at the time we are seeing the issue, as currently we cannot see the current status of the Datastores that were presented, not the VMX file for the Virtual Machine which is showing as invalid.

 

  • Unfortunately the logs have been rolled over for the VMKernel Logs due to which we were not able to isolate this even further hence we would request if the issue can be reproduce.

 

 

Action Plan:

 

  • Engage storage vendor and identify why do we see these check conditions all the time “H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.”

 

2020-10-04T05:17:48.650Z cpu71:2098321)ScsiDeviceIO: 3435: Cmd(0x45a3416b2700) 0x1a, CmdSN 0xf2e43 from world 0 to dev “naa.66666660212f220022317f3e14aeb3d0” failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.
2020-10-04T05:27:32.707Z cpu11:2098275)DVFilter: 5963: Checking disconnected filters for timeouts
2020-10-04T05:28:21.685Z cpu56:2098321)ScsiDeviceIO: 3435: Cmd(0x45a5a12bcc80) 0x1a, CmdSN 0xff151 from world 0 to dev “naa.66666660212f220022317f3e14aeb3d0” failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.
2020-10-04T05:37:32.712Z cpu26:2098275)DVFilter: 5963: Checking disconnected filters for timeouts
2020-10-04T05:37:49.305Z cpu28:2098320)ScsiDeviceIO: 3435: Cmd(0x459d86f3e5c0) 0x1a, CmdSN 0x106e09 from world 0 to dev “naa.66666660212f220022317f3e14aeb3d0” failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x24 0x0.
2020-10-04T05:45:54.920Z cpu25:2098320)ScsiDeviceIO: 3435: Cmd(0x459db0839480) 0x85, CmdSN 0x113c from world 2106407 to dev “naa.66666660212f220022317f3e14aeb3d0” failed H:0x0 D:0x2 P:0x0 Valid sense data: 0x5 0x20 0x0.

 

  • The sense code D:0x2 indicates that there is a check condition received for the device.

 

 

  • At this point I will recommend you reproduce the issue again and let us know the time when you can reproduce it so that we can join the call.

 

Option 1: Reproduce the issue by using the same procedure datastore and VM that was being recovered last time.  

 

Option 2: If above options is not possible, you may use test replicated datastores and VM’s

  • Provision 5 replicated datastores
  • Provision 1 test VM and the disk to be located on those 5 datastores.
  • Simulate the activity to reproduce the issue.

 

  • Incase if you want to do this in the in Downtime after hours, please capture the below details.

 

  • Reproduce the issue by Mounting the Datastore with esxcfg-volume -r.
  • Try to register the VM and start it.
  • If it fails, Capture the ESXi Host Bundle as this will capture the VMX Details along with the Datastores which will be mounted.

 

Ashutosh Dixit

I am currently working as a Senior Technical Support Engineer with VMware Premier Services for Telco. Before this, I worked as a Technical Lead with Microsoft Enterprise Platform Support for Production and Premier Support. I am an expert in High-Availability, Deployments, and VMware Core technology along with Tanzu and Horizon.

Leave a Reply