VMware Cloud Community
TomasCorey
Enthusiast
Enthusiast
Jump to solution

VM stuck, powered off and consolidation fail

Hello

I have a virtual machine that shut down after consolidating the disks (failed), I was looking at the logs (vmware.log) and I can't determine why the VM failed and shut down. (there was an installation of vmware tools, after install the vm was turned off, its strange, (automatic install).

I attach the logs,

Thanks a lot

Thomas Esteban Corey

Reply
0 Kudos
1 Solution

Accepted Solutions
TheBobkin
Champion
Champion
Jump to solution

Hello Thomas,

That looks more like the ESXi host lost access to the backing storage that the snapshots/base-disks reside on as reason for the power-off - that or something prevented access to the base-disks (like it was hot-added to a backup proxy).

The subsequent fail to power on could be for any number of reasons e.g. the initial power-off failure cause was still occurring or there were stale locks/processes on the VMs files.

Bob

View solution in original post

Reply
0 Kudos
3 Replies
TheBobkin
Champion
Champion
Jump to solution

Hello Thomas,

Welcome (back) to Communities.

"I have a virtual machine that shut down after consolidating the disks (failed)"

How exactly are you determining that consolidation "failed"?

I ask as the logs indicate otherwise:

See each disks combine and close complete:

2020-06-21T17:43:14.530Z| vcpu-0| I125: ConsolidateDiskCloseCB: Closing disk node 'scsi0:0' after combining '/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVD (10.228.1.8)/FVF-SAPCVD (10.228.1.8)_4-000001.vmdk' -> '/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVD (10.228.1.8)/FVF-SAPCVD (10.228.1.8)_4.vmdk'.

...

2020-06-21T17:43:26.490Z| vcpu-0| I125: ConsolidateDiskCloseCB: Closing disk node 'scsi0:5' after combining '/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVD (10.228.1.8)/FVF-SAPCVD (10.228.1.8)_6-000001.vmdk' -> '/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVD (10.228.1.8)/FVF-SAPCVD (10.228.1.8)_6.vmdk'.

And then end of task:

2020-06-21T17:43:26.760Z| vcpu-0| I125: ConsolidateEnd: Snapshot consolidate complete: The operation completed successfully (0).

From the previous timestamped log it indicates the VM shutdown after attempted vMotion not consolidation:

2020-06-21T00:05:46.583Z| vmx| I125:    OpType: vmotion

What is the current state of the VM? From the latest log you posted, it appears to be powered on.

Bob

Reply
0 Kudos
TomasCorey
Enthusiast
Enthusiast
Jump to solution

Hello Bob,

               I'm sorry I attached the wrongs logs, my mistake, I'M REALLY SORRY.

Now, I attached logs because of vMware vSphere Client in the task view shows failed:

We had to power on the vm.

Now, the vm is running, but after this we saw latency in this ESXi (60ms). I think was by consolidation, we have 16 disk with 2.8TB total space.

In this logs I see  (bold type):

2020-06-21T04:46:58.687Z| vcpu-0| I125: DISKLIB-CHAINESX : ChainESXOpenSubChainNode: can't create deltadisks node 41190668-FVF-SAPCVP  (10.228.1.6)_22-000001-sesparse.vmdk failed with error Bad address (0xbad0089, Address temporarily unmapped)

2020-06-21T04:46:58.687Z| vcpu-0| I125: DISKLIB-CHAIN : "/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVP  (10.228.1.6)/FVF-SAPCVP  (10.228.1.6)_22-000001.vmdk" : failed to open (Bad address).

2020-06-21T04:46:58.687Z| vcpu-0| I125: OBJLIB-FILEBE : FileBEIoctl: ioctl operation IOCTLCMD_VMFS_DELTADISKS(3033) failed on '/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVP  (10.228.1.6)/FVF-SAPCVP  (10.228.1.6)_22-000001-sesparse.vmdk' : Inappropriate ioctl for device (1638402)

2020-06-21T04:46:58.688Z| vcpu-0| I125: OBJLIB-FILEBE : FileBEClose: could not close handle: 917508

2020-06-21T04:46:58.688Z| vcpu-0| I125: OBJLIB-LIB: Failed to close object 2FA3A7CB8 : Bad address (917508).

2020-06-21T04:46:58.688Z| vcpu-0| I125: DISKLIB-VMFS  :VmfsExtentCommonClose: Failed to close objHandle 0: Bad address (e0004)

2020-06-21T04:46:58.688Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVP  (10.228.1.6)/FVF-SAPCVP  (10.228.1.6)_22-000001-sesparse.vmdk" : closed.

2020-06-21T04:46:58.689Z| vcpu-0| I125: DISKLIB-VMFS  : "/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVP  (10.228.1.6)/FVF-SAPCVP  (10.228.1.6)_22-flat.vmdk" : closed.

2020-06-21T04:46:58.689Z| vcpu-0| I125: DISKLIB-LIB   : Failed to open '/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVP  (10.228.1.6)/FVF-SAPCVP  (10.228.1.6)_22-000001.vmdk' with flags 0xa Bad address (917513).

2020-06-21T04:46:58.689Z| vcpu-0| I125: DISK: Cannot open disk '/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVP  (10.228.1.6)/FVF-SAPCVP  (10.228.1.6)_22-000001.vmdk': Bad address (917513).

2020-06-21T04:46:58.690Z| vcpu-0| I125: VMXNET3 user: Ethernet0 Driver Info: version = 14217867 gosBits = 2 gosType = 2, gosVer = 25344, gosMisc = 212

2020-06-21T04:46:58.690Z| vcpu-0| I125: Msg_Post: Error

2020-06-21T04:46:58.690Z| vcpu-0| I125: [vob.fss.closefile.failed] Failed to close file with handle 1092159080

2020-06-21T04:46:58.690Z| vcpu-0| I125: [vob.fssvec.FileIO.file.failed] File system specific implementation of FileIO[file] failed

2020-06-21T04:46:58.690Z| vcpu-0| I125: [vob.fssvec.FileIO.file.failed] File system specific implementation of FileIO[file] failed

2020-06-21T04:46:58.690Z| vcpu-0| I125: [vob.fssvec.Ioctl.file.failed] File system specific implementation of Ioctl[file] failed

2020-06-21T04:46:58.690Z| vcpu-0| I125: [vob.fssvec.FileIO.file.failed] File system specific implementation of FileIO[file] failed

2020-06-21T04:46:58.690Z| vcpu-0| I125: [msg.literal] Bad address

2020-06-21T04:46:58.690Z| vcpu-0| I125: [msg.disk.noBackEnd] Cannot open the disk '/vmfs/volumes/5ccc071b-f4275b2b-f52f-34e6d7e27a0e/FVF-SAPCVP  (10.228.1.6)/FVF-SAPCVP  (10.228.1.6)_22-000001.vmdk' or one of the snapshot disks it depends on.

2020-06-21T04:46:58.690Z| vcpu-0| I125: [msg.checkpoint.continuesync.error] An operation required the virtual machine to quiesce and the virtual machine was unable to continue running.

2020-06-21T04:46:58.690Z| vcpu-0| I125: ----------------------------------------

2020-06-21T04:46:58.690Z| vcpu-0| I125: Locale_Errno2LocalString: "C" locale found. LC_ALL=(null), LANG=C

2020-06-21T04:46:58.690Z| vcpu-0| I125: Locale_Errno2LocalString: locale(LC_ALL)=C locale(LC_MESSAGES)=C

2020-06-21T04:46:58.791Z| vcpu-0| I125: SnapshotVMX_ConsolidateCancel: Requesting snapshot consolidate cancel.

2020-06-21T04:46:58.791Z| vcpu-0| I125: Msg_Post: Error

2020-06-21T04:46:58.791Z| vcpu-0| I125: [msg.poweroff.commitOn] Performing disk cleanup. Cannot power off.

2020-06-21T04:46:58.791Z| vcpu-0| I125: ----------------------------------------

2020-06-21T04:46:58.793Z| vcpu-0| I125: ConsolidateItemCombine: Failed to unstun the virtual machine while consolidating disks.

2020-06-21T04:46:58.793Z| vcpu-0| I125: ConsolidateEnd: Failed to stun/unstun virtual machine while consolidating disks.

2020-06-21T04:46:58.793Z| vcpu-0| I125: VigorTransport_ServerSendResponse opID=151afb84-bf-b88e seq=187392: Completed Snapshot request with messages.

2020-06-21T04:46:58.793Z| vcpu-0| I125: Turning off snapshot info cache.

2020-06-21T04:46:58.794Z| vcpu-0| I125: Turning off snapshot disk cache.

2020-06-21T04:46:58.794Z| vcpu-0| I125: ConsolidateEnd: Snapshot consolidate complete: Unable to save snapshot file (13).

2020-06-21T04:46:58.794Z| vcpu-0| I125: Vix: [mainDispatch.c:4239]: VMAutomation_ReportPowerOpFinished: statevar=3, newAppState=1881, success=1 additionalError=0

2020-06-21T04:46:58.794Z| vcpu-0| I125: ConsolidateEnd: Snapshot consolidate requesting to power-off.

I think 2020-06-21T04:46:58.794Z| vcpu-0| I125: ConsolidateEnd: Snapshot consolidate requesting to power-off. shutdown the machine.

2020-06-22T06:29:59.907Z| vmx| I125: Log for VMware ESX pid=2171176 version=6.7.0 build=build-16316930 option=Release

2020-06-22T06:29:59.907Z| vmx| I125: The process is 64-bit.

2020-06-22T06:29:59.907Z| vmx| I125: Host codepage=UTF-8 encoding=UTF-8

2020-06-22T06:29:59.907Z| vmx| I125: Host is unknown

2020-06-22T06:29:59.843Z| vmx| I125: VTHREAD 243808294912 "vmx" wid 2171176

2020-06-22T06:29:59.844Z| vmx| I125: Msg_SetLocaleEx: HostLocale=UTF-8 UserLocale=NULL

2020-06-22T06:29:59.844Z| vmx| I125: DictionaryLoad: Cannot open file "/usr/lib/vmware/config": No such file or directory.

2020-06-22T06:29:59.844Z| vmx| I125: ConfigDB: Failed to load /usr/lib/vmware/config

2020-06-22T06:29:59.844Z| vmx| I125: DictionaryLoad: Cannot open file "//.vmware/config": No such file or directory.

2020-06-22T06:29:59.844Z| vmx| I125: ConfigDB: Failed to load ~/.vmware/config

Seems weird "Host is unknown" and "Failed to load"

2020-06-22T06:29:59.914Z| vmx| I125: Transitioned vmx/execState/val to poweredOff

2020-06-22T06:29:59.952Z| vmx| I125: Vix: [mainDispatch.c:4239]: VMAutomation_ReportPowerOpFinished: statevar=1, newAppState=1873, success=1 additionalError=0

2020-06-22T06:29:59.952Z| vmx| I125: Vix: [mainDispatch.c:4239]: VMAutomation_ReportPowerOpFinished: statevar=2, newAppState=1878, success=1 additionalError=0

2020-06-22T06:29:59.953Z| vmx| I125: FILE: FileCreateDirectoryEx: Failed to create /tmp. Error = 17

2020-06-22T06:29:59.953Z| vmx| I125: FILE: FileCreateDirectoryEx: Failed to create /tmp/vmware-root. Error = 17

2020-06-22T06:30:00.009Z| vmx| W115: PowerOn

I think vMware try to start the machine. But we had to power on.

Thanks Rob.


Regards,

Thomas Esteban Corey

Reply
0 Kudos
TheBobkin
Champion
Champion
Jump to solution

Hello Thomas,

That looks more like the ESXi host lost access to the backing storage that the snapshots/base-disks reside on as reason for the power-off - that or something prevented access to the base-disks (like it was hot-added to a backup proxy).

The subsequent fail to power on could be for any number of reasons e.g. the initial power-off failure cause was still occurring or there were stale locks/processes on the VMs files.

Bob

Reply
0 Kudos