3 Replies Latest reply on Jun 25, 2020 12:10 PM by TheBobkin

    VM stuck, powered off and consolidation fail

    TomasCorey Novice

      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

        • 1. Re: VM stuck, powered off and consolidation fail
          TheBobkin Virtuoso
          VMware EmployeesvExpert

          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

          • 2. Re: VM stuck, powered off and consolidation fail
            TomasCorey Novice

            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

            • 3. Re: VM stuck, powered off and consolidation fail
              TheBobkin Virtuoso
              vExpertVMware Employees

              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