Restart-VMGuest VM shuts down instead of a reboot BSOD

[nettech1]

Hi,

I am using Restart-VMGuest to reboot hundreds of VMs (Windows and Linux) in a cluster. (6.7.0 build-17167734)

One Windows Server 2019 VM (HW Ver 15) shuts down instead of the reboot with BSOD in the VMWare logs, but no indication in the OS that there was a BS. 

Why would VM logs indicate a BSOD when there wasn't ?

Suspect VMWare Tools is at fault - https://kb.vmware.com/s/article/1019064

Spoiler

2021-01-31T03:05:37.754Z| vmx| I125: VigorTransportProcessClientPayload: opID=7508ca18-de-01b0 seq=877509: Receiving Sched.SetResourceGroup request.
2021-01-31T03:05:37.754Z| vmx| I125: VigorTransport_ServerSendResponse opID=7508ca18-de-01b0 seq=877509: Completed Sched request.
2021-01-31T03:05:37.755Z| vmx| I125: VigorTransportProcessClientPayload: opID=7508ca18-de-01b0 seq=877510: Receiving PowerState.InitiateReset request.
2021-01-31T03:05:37.755Z| vmx| I125: Tools: sending 'OS_Reboot' (state = 2) state change request
2021-01-31T03:05:37.755Z| vmx| I125: Tools: Changing running status: 1 => 2.
2021-01-31T03:05:37.755Z| vmx| I125: Vix: [vmxCommands.c:671]: VMAutomation_ResetImpl: SoftReboot succeeded.
2021-01-31T03:05:37.866Z| vcpu-0| I125: TOOLS state change 2 returned status 1
2021-01-31T03:05:37.866Z| vcpu-0| I125: VigorTransport_ServerSendResponse opID=7508ca18-de-01b0 seq=877510: Completed PowerState request.
2021-01-31T03:05:37.866Z| vcpu-0| I125: Tools: Changing running status: 2 => 1.
2021-01-31T03:05:38.460Z| vcpu-0| I125: TOOLS installed legacy version 11329, available legacy version 11297
2021-01-31T03:05:38.460Z| vcpu-0| I125: TOOLS manifest update status is 4
2021-01-31T03:05:38.460Z| vcpu-0| I125: TOOLS can be autoupgraded.
2021-01-31T03:05:38.501Z| vcpu-0| I125: TOOLS autoupgrade protocol version 0
2021-01-31T03:05:38.576Z| vcpu-0| I125: GuestRpc: Reinitializing Channel 0(toolbox)
2021-01-31T03:05:53.215Z| vcpu-2| W115: WinBSOD: Synthetic MSR[0x40000100] 0x3b
2021-01-31T03:05:53.215Z| vcpu-2| W115+
2021-01-31T03:05:53.215Z| vcpu-2| W115: WinBSOD: Synthetic MSR[0x40000101] 0xc0000005
2021-01-31T03:05:53.215Z| vcpu-2| W115+
2021-01-31T03:05:53.215Z| vcpu-2| W115: WinBSOD: Synthetic MSR[0x40000102] 0xfffff8017da58f10
2021-01-31T03:05:53.215Z| vcpu-2| W115+
2021-01-31T03:05:53.215Z| vcpu-2| W115: WinBSOD: Synthetic MSR[0x40000103] 0xfffff300ca7dfec0
2021-01-31T03:05:53.215Z| vcpu-2| W115+
2021-01-31T03:05:53.215Z| vcpu-2| W115: WinBSOD: Synthetic MSR[0x40000104] 0x0
2021-01-31T03:05:53.215Z| vcpu-2| W115+
2021-01-31T03:05:54.317Z| svga| I125: SVGA disabling SVGA
2021-01-31T03:05:54.766Z| vcpu-2| I125: LSI: Invalid PageType [21] pageNo 0 Action 0
2021-01-31T03:05:58.767Z| vcpu-2| I125: PIIX4: PM Soft Off. Good-bye.
2021-01-31T03:05:58.767Z| vcpu-2| I125: Chipset: Issuing power-off request...
2021-01-31T03:05:58.768Z| vcpu-2| A100: ConfigDB: Setting softPowerOff = "TRUE"
2021-01-31T03:05:58.927Z| vmx| I125: Stopping VCPU threads...
2021-01-31T03:05:58.927Z| vcpu-0| I125: VMMon_WaitForExit: vcpu-0: worldID=2102946
2021-01-31T03:05:58.927Z| vcpu-3| I125: VMMon_WaitForExit: vcpu-3: worldID=2102952
2021-01-31T03:05:58.927Z| vcpu-2| I125: VMMon_WaitForExit: vcpu-2: worldID=2102951
2021-01-31T03:05:58.927Z| vcpu-1| I125: VMMon_WaitForExit: vcpu-1: worldID=2102950
2021-01-31T03:05:58.928Z| svga| I125: SVGA thread is exiting
2021-01-31T03:05:58.928Z| vmx| I125: MKS thread is stopped
2021-01-31T03:05:58.928Z| vmx| I125: MKS thread is stopped
2021-01-31T03:05:58.928Z| vmx| I125:
2021-01-31T03:05:58.928Z| vmx| I125+ OvhdMem: Final (Power Off) Overheads
2021-01-31T03:05:58.928Z| vmx| I125: reserved | used
2021-01-31T03:05:58.929Z| vmx| I125: OvhdMem excluded cur max avg | cur max avg
2021-01-31T03:05:58.929Z| vmx| I125: OvhdMem OvhdUser_MainMem : 4194304 4194304 - | 4194304 4194304 -
.......
2021-01-31T03:05:58.929Z| vmx| I125: OvhdMem Actual maximum : 18363 | 7427
2021-01-31T03:05:58.929Z| vmx| I125+
2021-01-31T03:05:58.929Z| vmx| I125: OvhdMem: memsize 16384 MB VMK fixed 3462 pages var(mem) 529 pages var(cpu) 8 cbrcOverhead 0 pages total 11963 pages
2021-01-31T03:05:58.929Z| vmx| I125: VMMEM: Maximum Reservation: 299MB (MainMem=16384MB) VMK=46MB
2021-01-31T03:05:58.930Z| vmx| I125: Tools: ToolsRunningStatus_Exit, delayedRequest is 0x88F0392360
2021-01-31T03:05:58.930Z| vmx| I125: Tools: Changing running status: 1 => 0.
2021-01-31T03:05:58.930Z| vmx| I125: SVMotion_PowerOff: Not running Storage vMotion. Nothing to do
2021-01-31T03:05:58.932Z| vmx| I125: Destroying virtual dev for scsi0:0 vscsi=10808
2021-01-31T03:05:58.932Z| vmx| I125: VMMon_VSCSIStopVports: No such target on adapter
2021-01-31T03:05:58.932Z| vmx| I125: Destroying virtual dev for scsi0:1 vscsi=10809
2021-01-31T03:05:58.932Z| vmx| I125: VMMon_VSCSIStopVports: No such target on adapter
2021-01-31T03:05:58.932Z| vmx| I125: Destroying virtual dev for scsi0:2 vscsi=10810
2021-01-31T03:05:58.932Z| vmx| I125: VMMon_VSCSIStopVports: No such target on adapter
2021-01-31T03:05:58.947Z| vmx| I125: MKS thread was already stopped
2021-01-31T03:05:58.947Z| mks| I125: MKS-RenderMain: Stopping MKSBasicOps
2021-01-31T03:05:58.947Z| mks| I125: MKS PowerOff
2021-01-31T03:05:58.947Z| mks| I125: MKS thread is exiting
2021-01-31T03:05:58.947Z| vmx| I125: SVMotion_PowerOff: Not running Storage vMotion. Nothing to do
2021-01-31T03:05:58.947Z| vmx| I125: scsi0:2: numIOs = 0 numMergedIOs = 0 numSplitIOs = 0 ( 0.0%)
2021-01-31T03:05:58.947Z| vmx| I125: Closing disk 'scsi0:2'
2021-01-31T03:05:58.948Z| vmx| I125: DISKLIB-CBT : Shutting down change tracking for untracked fid 1122042857.
2021-01-31T03:05:58.948Z| vmx| I125: DISKLIB-CBT : Successfully disconnected CBT node.
2021-01-31T03:05:59.145Z| vmx| I125: DISKLIB-VMFS : "/vmfs/volumes/5851a8b7-a18462e6-aadf-0023b500008a/WS_2019/WS_2019_3-flat.vmdk" : closed.
2021-01-31T03:05:59.169Z| vmx| I125: scsi0:1: numIOs = 0 numMergedIOs = 0 numSplitIOs = 0 ( 0.0%)
2021-01-31T03:05:59.169Z| vmx| I125: Closing disk 'scsi0:1'
2021-01-31T03:05:59.170Z| vmx| I125: DISKLIB-CBT : Shutting down change tracking for untracked fid 944636897.
2021-01-31T03:05:59.170Z| vmx| I125: DISKLIB-CBT : Successfully disconnected CBT node.
2021-01-31T03:05:59.526Z| vmx| I125: DISKLIB-VMFS : "/vmfs/volumes/5851a8b7-a18462e6-aadf-0023b500008a/WS_2019/WS_2019_1-flat.vmdk" : closed.
2021-01-31T03:05:59.549Z| vmx| I125: scsi0:0: numIOs = 0 numMergedIOs = 0 numSplitIOs = 0 ( 0.0%)
2021-01-31T03:05:59.549Z| vmx| I125: Closing disk 'scsi0:0'
2021-01-31T03:05:59.551Z| vmx| I125: DISKLIB-CBT : Shutting down change tracking for untracked fid 1102119900.
2021-01-31T03:05:59.551Z| vmx| I125: DISKLIB-CBT : Successfully disconnected CBT node.
2021-01-31T03:06:00.232Z| vmx| I125: DISKLIB-VMFS : "/vmfs/volumes/5851a8b7-a18462e6-aadf-0023b500008a/WS_2019/WS_2019-flat.vmdk" : closed.
2021-01-31T03:06:00.245Z| vmx| I125: Vix: [mainDispatch.c:1180]: VMAutomationPowerOff: Powering off.
2021-01-31T03:06:00.247Z| vmx| I125: WORKER: asyncOps=1169 maxActiveOps=3 maxPending=2 maxCompleted=0
2021-01-31T03:06:07.807Z| vmx| I125: Vix: [mainDispatch.c:4239]: VMAutomation_ReportPowerOpFinished: statevar=1, newAppState=1873, success=1 additionalError=0
2021-01-31T03:06:07.807Z| vmx| I125: Vix: [mainDispatch.c:4258]: VMAutomation: Ignoring ReportPowerOpFinished because the VMX is shutting down.
2021-01-31T03:06:07.807Z| vmx| A100: ConfigDB: Setting cleanShutdown = "TRUE"
2021-01-31T03:06:07.862Z| vmx| I125: Vix: [mainDispatch.c:4239]: VMAutomation_ReportPowerOpFinished: statevar=0, newAppState=1870, success=1 additionalError=0
2021-01-31T03:06:07.862Z| vmx| I125: Vix: [mainDispatch.c:4258]: VMAutomation: Ignoring ReportPowerOpFinished because the VMX is shutting down.
2021-01-31T03:06:07.862Z| vmx| I125: Transitioned vmx/execState/val to poweredOff
2021-01-31T03:06:07.862Z| vmx| I125: Vigor_ClientRequestCb: failed to do op=5 on unregistered device 'ConfigParams' (cmd=(null))
2021-01-31T03:06:07.862Z| vmx| I125: VMX idle exit
2021-01-31T03:06:08.148Z| vmx| I125: Vix: [mainDispatch.c:832]: VMAutomation_LateShutdown()
2021-01-31T03:06:08.148Z| vmx| I125: Vix: [mainDispatch.c:781]: VMAutomationCloseListenerSocket. Closing listener socket.
2021-01-31T03:06:08.154Z| vmx| I125: Flushing VMX VMDB connections
2021-01-31T03:06:08.154Z| vmx| I125: VigorTransport_ServerCloseClient: Closing transport 88F019D9B0 (err = 0)
2021-01-31T03:06:08.154Z| vmx| I125: VigorTransport_ServerDestroy: server destroyed.
2021-01-31T03:06:08.155Z| vmx| I125: VMX exit (0).
2021-01-31T03:06:08.156Z| vmx| I125: OBJLIB-LIB: ObjLib cleanup done.
2021-01-31T03:06:08.156Z| vmx| I125: AIOMGR-S : stat o=507 r=900 w=172 i=150 br=13810215 bw=4965431
2021-01-31T03:06:08.156Z| vmx| W115: VMX has left the building: 0.

[scott28tt]

@nettech1 

Moderator: I have edited your post above to place the log text dump into a “spoiler” which makes the thread easier to read. The “spoiler” is added to a post with the “triangle with exclamation mark” icon on the extended toolbar of the post creator/editor.