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
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
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
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
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