How to determine Virtual Machine Operations looking at the Virtual machine logs

Products

• VMware vSphere ESXi

Issue/Introduction

This is an informational KB to show log snippets of each virtual machine's operations.

Environment

VMware vSphere ESXi 7.0
VMware vSphere ESXi 8.0

Resolution

1-Power on virtual machine

vcpu-1| I125: Guest: PVSCSI: driver StorPort v1.3.8.0 starts. obj=FFFFE00055883590 reg=FFFFF80130778970 
vcpu-1| I125: Guest: vsep: AUDIT: DriverEntry : vfileFilter build-4286645 loaded 
vcpu-0| I125: Guest: vnet: AUDIT: DriverEntry : vnetFilter build-4325502 loaded 
vcpu-1| I125: VMXNET3 user: Ethernet0 Driver Info: version = 4062452 gosBits = 2 gosType = 2, gosVer = 25344, gosMisc = 212
| vcpu-1| I125: Guest: vm3d: SVGA WDDM Display Only driver, Version: 8.15.01.0050, Build Number: 4784527 
| vmx| I125: Guest: toolbox: Version: build-5055683 
| vcpu-0| W115: GuestRpc: application toolbox, changing channel 65535 -> 0
vcpu-0| I125: GuestRpc: Channel 0, guest application toolbox.
vmx| I125: TOOLS autoupgrade protocol version 2
vmx| I125: TOOLS Received tools.set.version rpc call, version = 10277.
vmx| I125: Guest: toolbox-dnd: Version: build-5055683 <===
vcpu-1| W115: GuestRpc: application toolbox-dnd, changing channel 65535 -> 1
vcpu-1| I125: GuestRpc: Channel 1, guest application toolbox-dnd 

2- Guest Reboot

vmx| I125: VigorTransportProcessClientPayload: opID=592113de seq=228026: Receiving PowerState.InitiateReset request.
vmx| I125: Tools: sending 'OS_Reboot' (state = 2) state change request
vmx| I125: Vix: [1016936 vmxCommands.c:670]: VMAutomation_ResetImpl: SoftReboot succeeded.
vmx| I125: VigorTransport_ServerSendResponse opID=592113de seq=228026: Completed PowerState request.
  ... <=== Above logs apply to reboot guest from vSphere API only, not guest self reboot.
vcpu-0| I125: CPU reset: soft (mode 1)
| vcpu-1| I125: CPU reset: soft (mode 1)
...
vmx| I125: Guest: toolbox: Version: build-5055683
vcpu-0| W115: GuestRpc: application toolbox, changing channel 65535 -> 0
vcpu-0| I125: GuestRpc: Channel 0, guest application toolbox.
vmx| I125: TOOLS soft reset detected.

3- VM hard reset

vmx| I125: VigorTransportProcessClientPayload: opID=592114a6 seq=228679: Receiving PowerState.InitiateReset request.
vmx| I125: Vix: [1016936 vmxCommands.c:685]: VMAutomation_Reset. Trying hard reset
vmx| W115+ VMXRequestReset
vmx| I125: Vigor_Reset: Attaching to reset.
vmx| I125: Stopping VCPU threads...
vcpu-0| I125: VMMon_WaitForExit: vcpu-0: worldID=1016937
vcpu-1| I125: VMMon_WaitForExit: vcpu-1: worldID=1016939
svga| I125: SVGA thread is exiting
... <=== Follows VM power on afterwards

4- VM hard poweroff

vmx| I125: VigorTransportProcessClientPayload: opID=59211602 seq=229469: Receiving PowerState.InitiatePowerOff request.
vmx| I125: Vix: [1016936 vmxCommands.c:556]: VMAutomation_InitiatePowerOff. Trying hard powerOff
vmx| I125: VigorTransport_ServerSendResponse opID=59211602 seq=229469: Completed PowerState request.
vmx| I125: Stopping VCPU threads...
vcpu-0| I125: VMMon_WaitForExit: vcpu-0: worldID=1019717
vcpu-1| I125: VMMon_WaitForExit: vcpu-1: worldID=1019720
svga| I125: SVGA thread is exiting

5- Guest shutdown

vmx| I125: VigorTransportProcessClientPayload: opID=5921169b seq=230046: Receiving PowerState.InitiatePowerOff request.
vmx| I125: Tools: sending 'OS_Halt' (state = 1) state change request
vmx| I125: Vix: [1020511 vmxCommands.c:534]: VMAutomation_InitiatePowerOff. Tried to soft halt. Success = 1
vmx| I125: TOOLS state change 1 returned status 1
vmx| I125: VigorTransport_ServerSendResponse opID=5921169b seq=230046: Completed PowerState request.
... <=== Above logs apply to shut down guest from vSphere API only, not guest self shut down.
vcpu-0| I125: PIIX4: PM Soft Off.  Good-bye.
vcpu-0| I125: Chipset: Issuing power-off request...
vcpu-0| A100: ConfigDB: Setting softPowerOff = "TRUE"
vmx| I125: Stopping VCPU threads...
vcpu-0| I125: VMMon_WaitForExit: vcpu-0: worldID=1020512
vcpu-1| I125: VMMon_WaitForExit: vcpu-1: worldID=1020514
svga| I125: SVGA thread is exiting

6- VM suspend

vmx| I125: VigorTransportProcessClientPayload: opID=59211771 seq=230779: Receiving PowerState.InitiateSuspend request.
vmx| I125: SUSPEND: Start (flags=0 prog=A8E6640 progData=32521840 cb=A8E6620 cbData=32521840)
  ... <=== Progress percentage
vcpu-0| I125: SUSPEND: Completed suspend: 'Operation completed successfully' (0)
vcpu-0| I125: VigorTransport_ServerSendResponse opID=59211771 seq=230779: Completed PowerState request.
vmx| I125: Stopping VCPU threads...
vcpu-0| I125: VMMon_WaitForExit: vcpu-0: worldID=1020718
vcpu-1| I125: VMMon_WaitForExit: vcpu-1: worldID=1020734
svga| I125: SVGA thread is exiting

7- Quiesced snapshot/ VM backup

vmx| I125: VigorTransportProcessClientPayload: opID=59211c2d seq=232505: Receiving Snapshot.Take request.
vmx| I125: SnapshotVMX_TakeSnapshot start: 'QuiescedSnapshot-test', deviceState=0, lazy=0, logging=0, quiesced=1, forceNative=0, tryNative=1, saveAllocMaps=0 cb=1403E3A0, cbData=3262AF80
vcpu-0| I125: ToolsBackup: changing quiesce state: IDLE -> STARTED
vmx| I125: ToolsBackup: changing quiesce state: STARTED -> COMMITTED

vcpu-0| I125: Checkpoint_Unstun: vm stopped for 1634233 us
vcpu-0| I125: ToolsBackup: changing quiesce state: COMMITTED -> FINISHING
vcpu-0| I125: HBACommon: First write on scsi0:0.fileName='/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2_0-000002.vmdk'
vcpu-0| I125: HBACommon: First write on scsi0:2.fileName='/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2_0-000003.vmdk'
vmx| I125: ToolsBackup: changing quiesce state: FINISHING -> DONE_WAIT
vmx| I125: ToolsBackup: changing quiesce state: DONE_WAIT -> GET_MANIFEST
vcpu-0| I125: ToolsBackup: changing quiesce state: GET_MANIFEST -> IDLE
vcpu-0| I125: ToolsBackup: changing quiesce state: IDLE -> DONE
vcpu-0| I125: SnapshotVMXTakeSnapshotComplete: Done with snapshot 'QuiescedSnapshot-test': 3
vcpu-0| I125: VigorTransport_ServerSendResponse opID=59211c2d seq=232505: Completed Snapshot request.

vmx| I125: VigorTransportProcessClientPayload: opID=59211d5f seq=233119: Receiving Snapshot.Delete request.
vmx| I125: SNAPSHOT: SnapshotDeleteWork '/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx' : 3
vmx| I125: VigorTransport_ServerSendResponse opID=59211d5f seq=233119: Completed Snapshot request.
vmx| I125: VigorTransportProcessClientPayload: opID=59211d5f seq=233120: Receiving Snapshot.Consolidate request.
vmx| I125: SnapshotVMX_Consolidate: Starting online snapshot consolidate operation.
vcpu-0| I125: Checkpoint_Unstun: vm stopped for 93274 us
vcpu-0| I125: Checkpoint_Unstun: vm stopped for 558416 us
vcpu-0| I125: Checkpoint_Unstun: vm stopped for 381794 us
vcpu-0| I125: VigorTransport_ServerSendResponse opID=59211d5f seq=233120: Completed Snapshot request.
vcpu-0| I125: ConsolidateEnd: Snapshot consolidate complete: The operation completed successfully (0).

8- vmtoolsd daemon crash

vmx| I125: GuestRpcSendTimedOut: message to toolbox timed out. <=== First 15 seconds timeout
vmx| I125: GuestRpcSendTimedOut: message to toolbox timed out. <=== Second 15 seconds timeout
vmx| I125: GuestRpc: app toolbox's second ping timeout; assuming app is down <===
vmx| I125: GuestRpc: Reinitializing Channel 0(toolbox)
vmx| I125: GuestMsg: Channel 0, Cannot unpost because the previous post is already completed

hostd log at the time (with verbose log level turned on):
verbose hostd[291C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] guest operations are not ready <===
verbose hostd[291C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] Tools are not auto-upgrade capable
verbose hostd[291C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] Tools are not set-resolution capable
verbose hostd[2A084B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] Updating current heartbeatStatus: red <===
info hostd[2A084B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] Turning off heartbeat checker

9- Window guest BSOD

vcpu-1| W115: WinBSOD: Synthetic MSR[0x40000100] 0xdeaddead
vcpu-1| W115:
vcpu-1| W115: WinBSOD: Synthetic MSR[0x40000101] 0x0
vcpu-1| W115:
vcpu-1| W115: WinBSOD: Synthetic MSR[0x40000102] 0x0
vcpu-1| W115:
vcpu-1| W115: WinBSOD: Synthetic MSR[0x40000103] 0x0
vcpu-1| W115:
vcpu-1| W115: WinBSOD: Synthetic MSR[0x40000104] 0x0
vcpu-1| W115:
vcpu-1| W115: Guest operating system crash detected. <=== There are not detected cases
vcpu-1| I125: LSI: Invalid PageType [21] pageNo 0 Action 0 <=== 
vmx| I125: GuestRpcSendTimedOut: message to toolbox timed out.
vmx| I125: GuestRpcSendTimedOut: message to toolbox-dnd timed out.
vmx| I125: GuestRpcSendTimedOut: message to toolbox timed out.
vmx| I125: GuestRpc: app toolbox's second ping timeout; assuming app is down
vmx| I125: GuestRpcSendTimedOut: message to toolbox-dnd timed out.
vmx| I125: GuestRpc: app toolbox-dnd's second ping timeout; assuming app is down
vmx| I125: GuestRpc: Reinitializing Channel 0(toolbox)
vmx| I125: GuestMsg: Channel 0, Cannot unpost because the previous post is already completed
vmx| I125: GuestRpc: Reinitializing Channel 1(toolbox-dnd)
vmx| I125: GuestMsg: Channel 1, Cannot unpost because the previous post is already completed
vcpu-0| I125: Tools: Tools heartbeat timeout.

hostd log at the time (with verbose log level turned on):

verbose hostd[28880B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] Guest operating system crash detected.
verbose hostd[28A40B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] guest operations are not ready <===
verbose hostd[28A40B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] interactive guest operations are not ready <===
verbose hostd[28A40B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] Tools are not auto-upgrade capable

verbose hostd[28A40B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] Tools are not set-resolution capable
verbose hostd[29F81B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] Updating current heartbeatStatus: red <===
info hostd[29F81B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/.../h10-ws2012r2/h10-ws2012r2.vmx] Turning off heartbeat checker

10- Guest RPC Remote Connection failure Log Spew 

vmx| I125: GuestRpc:Got error for connection 103:Remote connection failure 
vmx| I125: GuestRpc:Got error for connection 203:Remote connection failure
vmx| I125: GuestRpc:Got error for connection 303:Remote connection failure
vmx| I125 GuestRpc:Got error for connection 403:Remote connection failure
vmx| I125 GuestRpc:Got error for connection 503:Remote connection failure
vmx| I125 GuestRpc:Got error for connection 603:Remote connection failure