VMware Cloud Community
multirotor
Contributor
Contributor
‎11-30-2018 07:11 AM

VMs powering off for no reason

Hello,

I have recently upgraded two hosts from 5.5 to 6.0.

Since then, I have several Win7 VM's that are found powered off in the morning. It doesn't happen every night and not always to the same VM's.

The Windows OS knows nothing about the shutdown. Actually, it reports an "unexpected shutdown" after the power on.

The vmware.log only shows the power on activity the next morning.

Windows OS is activated.

hostd.log contains the below information. It is similar to what you find if you power off a VM from CLI. However, then hostd.log also contains the CLI command. That is not the case here.

I am starting to think this is a bug.

Anything else I can check ?

Thanks !

....

2018-11-29T00:52:18.877Z warning hostd[64A1EB70] [Originator@6876 sub=VigorStatsProvider(1644290120)] AddVirtualMachine: VM '212' already registered
2018-11-29T00:52:18.877Z warning hostd[64A1EB70] [Originator@6876 sub=VigorStatsProvider(1644290120)] AddVirtualMachine: VM '214' already registered
2018-11-29T00:52:18.877Z warning hostd[64A1EB70] [Originator@6876 sub=VigorStatsProvider(1644290120)] AddVirtualMachine: VM '218' already registered
2018-11-29T00:52:18.877Z warning hostd[64A1EB70] [Originator@6876 sub=VigorStatsProvider(1644290120)] AddVirtualMachine: VM '220' already registered
2018-11-29T00:52:18.877Z warning hostd[64A1EB70] [Originator@6876 sub=VigorStatsProvider(1644290120)] AddVirtualMachine: VM '222' already registered
2018-11-29T00:52:19.019Z info hostd[61740B70] [Originator@6876 sub=Libs] SOCKET 46 (50)
2018-11-29T00:52:19.019Z info hostd[61740B70] [Originator@6876 sub=Libs] recv detected client closed connection
2018-11-29T00:52:19.019Z info hostd[61740B70] [Originator@6876 sub=Libs] VigorTransportClientProcessError: Remote connection failure
2018-11-29T00:52:19.019Z info hostd[61740B70] [Originator@6876 sub=Libs] VigorTransportClientDrainRecv: draining read.
2018-11-29T00:52:19.019Z info hostd[61740B70] [Originator@6876 sub=Libs] SOCKET 46 (50)
2018-11-29T00:52:19.019Z info hostd[61740B70] [Originator@6876 sub=Libs] recv detected client closed connection
2018-11-29T00:52:19.019Z info hostd[61740B70] [Originator@6876 sub=Libs] VigorTransportClientProcessError: closing connection.
2018-11-29T00:52:19.019Z info hostd[61740B70] [Originator@6876 sub=Libs] VigorTransportClientManageConnection: connection closed.
2018-11-29T00:52:19.057Z info hostd[61740B70] [Originator@6876 sub=Libs] CnxAuthdProtoSecureConnect: Unencrypted connection, skipping thumbprint exchange.
2018-11-29T00:52:19.061Z info hostd[61740B70] [Originator@6876 sub=Libs] CnxConnectAuthd: Returning false because CnxAuthdProtoConnect failed
2018-11-29T00:52:19.061Z info hostd[61740B70] [Originator@6876 sub=Libs] Cnx_Connect: Returning false because CnxConnectAuthd failed
2018-11-29T00:52:19.061Z info hostd[61740B70] [Originator@6876 sub=vm:Cnx_Connect: Error message: There is no VMware process running for config file /vmfs/volumes/5bc5c0f2-a6bd4ef8-20d9-901b0e21b988/VMNAME/VMNAME.vmx]
2018-11-29T00:52:19.061Z warning hostd[61740B70] [Originator@6876 sub=vm:VigorTransportClientManageConnection: Failed to re-connect to VM /vmfs/volumes/5bc5c0f2-a6bd4ef8-20d9-901b0e21b988/VMNAME/VMNAME.vmx]
2018-11-29T00:52:19.070Z info hostd[61740B70] [Originator@6876 sub=Libs] VigorOnlineDisconnectCb: connection closed (is final).
2018-11-29T00:52:19.070Z info hostd[6495CB70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5bc5c0f2-a6bd4ef8-20d9-901b0e21b988/VMNAME/VMNAME.vmx] State Transition (VM_STATE_ON -> VM_STATE_OFF)
2018-11-29T00:52:19.071Z info hostd[6495CB70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5bc5c0f2-a6bd4ef8-20d9-901b0e21b988/VMNAME/VMNAME.vmx] Upgrade is required for virtual machine, version: 9
2018-11-29T00:52:19.071Z warning hostd[6495CB70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5bc5c0f2-a6bd4ef8-20d9-901b0e21b988/VMNAME/VMNAME.vmx] Failed to find activation record, event user unknown.
2018-11-29T00:52:19.071Z info hostd[6499DB70] [Originator@6876 sub=Guestsvc.GuestFileTransferImpl] Entered VmPowerStateListener
2018-11-29T00:52:19.071Z info hostd[6499DB70] [Originator@6876 sub=Guestsvc.GuestFileTransferImpl] VmPowerStateListener succeeded
2018-11-29T00:52:19.071Z info hostd[6499DB70] [Originator@6876 sub=Hbrsvc] Replicator: powerstate change VM: 160 Old: 1 New: 0
2018-11-29T00:52:19.071Z info hostd[6499DB70] [Originator@6876 sub=Hbrsvc] Replicator: Poweroff for VM: (id=160)
2018-11-29T00:52:19.071Z info hostd[6495CB70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 773 : VMNAME on  HOSTNAME in ha-datacenter is powered off
2018-11-29T00:52:19.101Z info hostd[6495CB70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5bc5c0f2-a6bd4ef8-20d9-901b0e21b988/VMNAME/VMNAME.vmx] Send config update invoked
2018-11-29T00:52:19.126Z error hostd[6495CB70] [Originator@6876 sub=VigorStatsProvider(1644290120).GuestStats(160)] VigorCallback received fault: Disconnected from virtual machine.
2018-11-29T00:52:27.519Z info hostd[6499DB70] [Originator@6876 sub=Vimsvc.TaskManager opID=HB-host-3179@50590-51a9e052-b4-d281 user=vpxuser] Task Created : haTask--vim.OverheadService.downloadVMXConfig-5260700
2018-11-29T00:52:27.529Z info hostd[6499DB70] [Originator@6876 sub=Vimsvc.TaskManager opID=HB-host-3179@50590-51a9e052-b4-d281 user=vpxuser] Task Completed : haTask--vim.OverheadService.downloadVMXConfig-5260700 Status success
2018-11-29T00:53:00.060Z warning hostd[64105B70] [Originator@6876 sub=Statssvc.vim.PerformanceManager] Calculated write I/O size 1048576 for scsi0:3 is out of range -- 1048576,prevBytes = 2540508160 curBytes = 2541556736 prevCommands = 2702curCommands = 2703
2018-11-29T00:54:00.010Z warning hostd[64F6FB70] [Originator@6876 sub=Statssvc.vim.PerformanceManager] Calculated write I/O size 1048576 for scsi0:3 is out of range -- 1048576,prevBytes = 60791742976 curBytes = 60792791552 prevCommands = 83086curCommands = 83087
2018-11-29T00:54:00.033Z warning hostd[64F6FB70] [Originator@6876 sub=Statssvc.vim.PerformanceManager] Calculated write I/O size 1048576 for scsi0:3 is out of range -- 1048576,prevBytes = 3610337280 curBytes = 3611385856 prevCommands = 3724curCommands = 3725
2018-11-29T00:54:18.880Z warning hostd[64CA8B70] [Originator@6876 sub=VigorStatsProvider(1644290120)] AddVirtualMachine: VM '141' already registered
2018-11-29T00:54:18.880Z warning hostd[64CA8B70] [Originator@6876 sub=VigorStatsProvider(1644290120)] AddVirtualMachine: VM '142' already registered
2018-11-29T00:54:18.880Z warning hostd[64CA8B70] [Originator@6876 sub=VigorStatsProvider(1644290120)] AddVirtualMachine: VM '150' already registered
2018-11-29T00:54:18.880Z warning hostd[64CA8B70] [Originator@6876 sub=VigorStatsProvider(1644290120)] AddVirtualMachine: VM '152' already registered
2018-11-29T00:54:18.880Z warning hostd[64CA8B70] [Originator@6876 sub=VigorStatsProvider(1644290120)] AddVirtualMachine: VM '154' already registered

....

0 Kudos
3 Replies
dbalcaraz
Expert
Expert
‎11-30-2018 09:19 AM

Hi,

What about the log you shared?

2018-11-29T00:52:19.071Z info hostd[6495CB70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 773 : VMNAME on  HOSTNAME in ha-datacenter is powered off

Did you check the vxpd log from vCenter?

-------------------------------------------------------- "I greet each challenge with expectation"
0 Kudos
sjesse
Leadership
Leadership
‎11-30-2018 09:37 AM

Do you have vsphere replication installed, and is it enabled for this vm?

0 Kudos
multirotor
Contributor
Contributor
‎12-03-2018 02:47 AM

Thanks for the replies!

We are not using Replication and HA is also turned off.

This is on a host that is not even a cluster member.

I have searched the vpxd.log for anything happening around the same time but found nothing.

I could be wrong but I believe both messages from Replicator and from Vimsvc.ha-eventmgr are simply "noticing" the VM is now powered off.

Actually, a little up in the log is this entry:

There is no VMware process running for config file /vmfs/volumes/5bc5c0f2-a6bd4ef8-20d9-901b0e21b988/VMNAME/VMNAME.vmx

Any other ideas ?

Thank you.

0 Kudos