All VM's rebooting for no reason same time every Saturday after Exchange 2010 SP3 Update
Hey Guys
I've got an IBM x3650 M2 server running VMware vSphere 4 Hypervisor ESXi 4.1.
I'm running 5X vm's (all server 2008 - DC + TS + Exchange + 3CX + SQL) on it and it had been happily going along until recently.
I had a hard drive go in the raid set about 5 weeks ago. That got replaced by IBM and the raid set rebuilt ok. Everything was stable.
It was about time for me to run some updates, so 3 weeks ago (on a Friday night) I updated Exchange 2010 to SP3 with rollup 6. I also installed the latest windows updates on the 3CX phone server.
The 3CX server didn't like the updates and after the reboot the network card wouldn't connect. A few reboots then it was ok.
I finished everything about 6am that morning. Everything was running well, Went to sleep and woke up that afternoon to a notification that the VM's had rebooted at 2.45pm that Saturday.
I checked the IBM host and that hadn't rebooted, no errors in the logs.
I checked the VMware Console, just had a restart notification in the events. I checked the VM logs from the datastore and it just said the VM's had restarted. Here is a snippit of the logs:
--------------------------
Last logs from the day before were:
Jul 25 05:54:00.222: vcpu-0| CDROM: Emulate GET CONFIGURATION RT 2 starting feature 65
Jul 25 05:54:00.222: vcpu-0| CDROM: Emulate GET CONFIGURATION RT 2 starting feature 259
Then the shutdown day events are:
Jul 26 06:40:27.928: vmx| SCSIDiskESXPopulateVDevDes
Jul 26 06:40:27.928: vmx| Creating virtual dev for scsi0:2
Jul 26 06:40:27.928: vmx| DumpDiskInfo: scsi0:2 createType=11, capacity = 1048576000, numLinks = 1, allocationType = 1
Jul 26 06:40:27.936: vmx| StateLogger::VM has zeroedthick disk scsi0:2; FT enable will be disallowedSCSIDiskESXPopul
Jul 26 06:40:27.937: vmx| SVGA: Device capabilities 0x001f83e2
Jul 26 06:40:28.023: vmx| SVGA: FIFO capabilities 0x0000007f
Jul 26 06:40:28.024: vmx| Ethernet0 MAC Address: 00:0c:29:ca:5a:62
Jul 26 06:40:28.119: vmx| VMXVmdb_LoadRawConfig: Loading raw config
Jul 26 06:40:28.125: vmx| MStat: Creating Stat vm.heartbeat
Jul 26 06:40:28.125: vmx| TOOLS Generated SessionId 2209456672923899303
Jul 26 06:40:28.125: vmx| VMXVmdbGuest_GetToolsVersi
Jul 26 06:40:28.125: vmx| DISKUTIL: scsi0:2 : toolsVersion = 8290
Jul 26 06:40:28.125: vmx| DISKUTIL: scsi0:0 : toolsVersion = 8290
Jul 26 06:40:28.125: vmx| VMXVmdbGuest_GetToolsVersi
Jul 26 06:40:28.125: vmx| TOOLS setting legacy tools version to '8290', manifest status is 5
Jul 26 06:40:28.125: vmx| VMXVmdb_SetToolsVersionSta
Jul 26 06:40:28.125: vmx| VMXVmdb_SetToolsVersionSta
Jul 26 06:40:28.126: vmx| TOOLS INSTALL initializing state to IDLE on power on.
Jul 26 06:40:28.135: vmx| PTSC to VMI Wallclock (nsec) 196170238342 @ 2266747000Hz -> 1406356828000000000 @ 1000000000Hz
Jul 26 06:40:28.135: vmx| PTSC to VMI Wallclock (nsec) ((x * 3789542720) >> 33) + 1406356741457373787
Jul 26 06:40:28.135: vmx| PTSC to ParaTime RealCycles 0 @ 2266747000Hz -> 0 @ 2266747000Hz
Jul 26 06:40:28.135: vmx| PTSC to ParaTime RealCycles ((x * 1) >> 0) + 0
Jul 26 06:40:28.135: vmx| ParaTime RealCycles to PTSC 0 @ 2266747000Hz -> 0 @ 2266747000Hz
Jul 26 06:40:28.135: vmx| ParaTime RealCycles to PTSC ((x * 1) >> 0) + 0
Jul 26 06:40:28.135: vmx| memoryHotplug: Current size = 4096MB, Minimum size = 4096MB, Maximum size = 4096MB
Jul 26 06:40:28.135: vmx| memoryHotplug: Entry[0]: 00000000000000A0-000000000
Jul 26 06:40:28.135: vmx| memoryHotplug: Entry[1]: 00000000001000A0-00000000C
Jul 26 06:40:28.135: vmx| memoryHotplug: Entry[2]: 00000001000000A0-000000014
Jul 26 06:40:28.135: vmx| VMMEM: Initial Reservation: 193MB (MainMem=4096MB SVGA=32MB)
Jul 26 06:40:28.135: vmx| VMMEM: Precise Reservation: 94MB (MainMem=4096MB SVGA=32MB)
Jul 26 06:40:28.136: vmx| guestCpuFeatures = 0x404001fd
Jul 26 06:40:28.223: vmx| VMXVmdb_LoadRawConfig: Loading raw config
Jul 26 06:40:28.228: vmx| Guest CPUID differences from hostCPUID.
Jul 26 06:40:28.228: vmx| guestCPUID level 00000001, 0: 0x000106a5 0x00010800 0x80982201 0x0febfbff
Jul 26 06:40:28.228: vmx| guestCPUID level 40000000, 0: 0x40000010 0x61774d56 0x4d566572 0x65726177
Jul 26 06:40:28.228: vmx| guestCPUID level 40000010, 0: 0x0022967b 0x000101d0 0x00000000 0x00000000
Jul 26 06:40:28.230: vmx| BusMemSample: touched: initPct 75 pages 0 : dirtied: initPct 75 pages 0
Jul 26 06:40:28.230: vmx| Vix: [6290 mainDispatch.c:717]: VMAutomation_PowerOn. Powering on.
Jul 26 06:40:28.230: vmx| VMX_PowerOn: ModuleTable_PowerOn = 1
Jul 26 06:40:28.230: vmx| Setting thread 1 stack size to 2097152.
Jul 26 06:40:28.230: mks| Async MKS thread is alive
Jul 26 06:40:28.231: vmx| Setting thread 4 stack size to 1048576.
Jul 26 06:40:28.231: vcpu-0| VMMon_Start: vcpu-0: worldID=6292
Jul 26 06:40:28.233: vcpu-0| APIC: version = 0x15, max LVT = 6
Jul 26 06:40:28.233: vcpu-0| APIC: LDR = 0x20000000, DFR = 0xffffffff
Jul 26 06:40:28.236: vcpu-0| LSI:Initialize adapter 0
Jul 26 06:40:28.236: vcpu-0| CPU reset: hard (mode 2)
Jul 26 06:40:28.236: vcpu-0| memoryHotplug: Entry[0]: 00000000000000A0-000000000
Jul 26 06:40:28.236: vcpu-0| memoryHotplug: Entry[1]: 00000000001000A0-00000000C
Jul 26 06:40:28.236: vcpu-0| memoryHotplug: Entry[2]: 00000001000000A0-000000014
Jul 26 06:40:28.236: vcpu-0| PIIX4: PM Resuming from suspend type 0x0, chipset.onlineStandby 1
Jul 26 06:40:28.236: vcpu-0| Intel VT: FlexPriority enabled.
Jul 26 06:40:28.236: vcpu-0| Intel VT: VPID enabled.
Jul 26 06:40:28.236: vcpu-0| HV enabled
Jul 26 06:40:28.238: vcpu-0| Setting thread 5 stack size to 1048576.
Jul 26 06:40:28.238: vcpu-1| VMMon_Start: vcpu-1: worldID=6294
Jul 26 06:40:28.238: vcpu-0| Vix: [6470 mainDispatch.c:3571]: VMAutomation_ReportPowerOp
Jul 26 06:40:28.287: vcpu-0| Vix: [6470 mainDispatch.c:3492]: VMAutomationReportPowerSta
Jul 26 06:40:28.287: vcpu-0| Vix: [6470 mainDispatch.c:3492]: VMAutomationReportPowerSta
Jul 26 06:40:28.287: vcpu-0| Transitioned vmx/execState/val to poweredOn
Jul 26 06:40:28.354: vcpu-1| APIC: version = 0x15, max LVT = 6
Jul 26 06:40:28.354: vcpu-1| APIC: LDR = 0x1000000, DFR = 0xffffffff
Jul 26 06:40:28.354: vcpu-1| CPU reset: hard (mode 2)
Jul 26 06:40:28.354: vcpu-1| Intel VT: FlexPriority enabled.
Jul 26 06:40:28.354: vcpu-1| Intel VT: VPID enabled.
Jul 26 06:40:28.354: vcpu-1| HV enabled
Jul 26 06:40:28.356: vcpu-1| VMM64 initialized
Jul 26 06:40:28.356: vcpu-0| VMM64 initialized
Jul 26 06:40:28.430: vcpu-0| MonitorInitNumaUnmapVMM64
Jul 26 06:40:28.494: vcpu-1| CPU reset: soft (mode 2)
Jul 26 06:40:28.740: vcpu-0| SVGA: Registering MemSpace at 0xd4000000(0x0) and 0xd8000000(0x0)
Jul 26 06:40:28.744: vcpu-0| SVGA: Unregistering MemSpace at 0xd4000000(0xd4000000) and 0xd8000000(0xd8000000)
Jul 26 06:40:28.746: mks| MKSHostOps_HideCursor before defineCursor!
Jul 26 06:40:28.919: vcpu-0| SVGA: Registering MemSpace at 0xd4000000(0xd4000000) and 0xd8000000(0xd8000000)
Jul 26 06:40:28.925: vcpu-0| SVGA: Unregistering MemSpace at 0xd4000000(0xd4000000) and 0xd8000000(0xd8000000)
Jul 26 06:40:28.934: vcpu-0| SVGA: Registering IOSpace at 0x10d0
Jul 26 06:40:28.934: vcpu-0| SVGA: Registering MemSpace at 0xd4000000(0xd4000000) and 0xd8000000(0xd8000000)
Jul 26 06:40:28.939: vcpu-0| PCIBridge4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.940: vcpu-0| pciBridge4:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.941: vcpu-0| pciBridge4:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.942: vcpu-0| pciBridge4:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.943: vcpu-0| pciBridge4:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.944: vcpu-0| pciBridge4:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.945: vcpu-0| pciBridge4:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.946: vcpu-0| pciBridge4:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.947: vcpu-0| PCIBridge5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.948: vcpu-0| pciBridge5:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.949: vcpu-0| pciBridge5:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.950: vcpu-0| pciBridge5:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.951: vcpu-0| pciBridge5:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.952: vcpu-0| pciBridge5:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.953: vcpu-0| pciBridge5:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.954: vcpu-0| pciBridge5:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.955: vcpu-0| PCIBridge6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.957: vcpu-0| pciBridge6:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.958: vcpu-0| pciBridge6:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.959: vcpu-0| pciBridge6:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.960: vcpu-0| pciBridge6:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.961: vcpu-0| pciBridge6:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.962: vcpu-0| pciBridge6:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.963: vcpu-0| pciBridge6:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.964: vcpu-0| PCIBridge7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.965: vcpu-0| pciBridge7:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.966: vcpu-0| pciBridge7:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.967: vcpu-0| pciBridge7:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.968: vcpu-0| pciBridge7:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.969: vcpu-0| pciBridge7:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.970: vcpu-0| pciBridge7:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.971: vcpu-0| pciBridge7:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.973: vcpu-1| CPU reset: soft (mode 2)
Jul 26 06:40:29.149: vcpu-0| PCIBridge4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.150: vcpu-0| pciBridge4:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.151: vcpu-0| pciBridge4:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.152: vcpu-0| pciBridge4:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.153: vcpu-0| pciBridge4:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.154: vcpu-0| pciBridge4:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.155: vcpu-0| pciBridge4:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.156: vcpu-0| pciBridge4:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.157: vcpu-0| PCIBridge5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.158: vcpu-0| pciBridge5:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.159: vcpu-0| pciBridge5:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.160: vcpu-0| pciBridge5:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.161: vcpu-0| pciBridge5:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.163: vcpu-0| pciBridge5:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.164: vcpu-0| pciBridge5:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.165: vcpu-0| pciBridge5:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.166: vcpu-0| PCIBridge6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.167: vcpu-0| pciBridge6:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.168: vcpu-0| pciBridge6:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.169: vcpu-0| pciBridge6:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.170: vcpu-0| pciBridge6:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.171: vcpu-0| pciBridge6:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.172: vcpu-0| pciBridge6:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.173: vcpu-0| pciBridge6:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.174: vcpu-0| PCIBridge7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.175: vcpu-0| pciBridge7:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.176: vcpu-0| pciBridge7:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.177: vcpu-0| pciBridge7:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.178: vcpu-0| pciBridge7:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.179: vcpu-0| pciBridge7:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.180: vcpu-0| pciBridge7:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.181: vcpu-0| pciBridge7:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.310: vcpu-0| DISKUTIL: scsi0:0 : geometry=10439/255/63
Jul 26 06:40:29.340: vcpu-0| DISKUTIL: scsi0:0 : capacity=167702535
Jul 26 06:40:29.340: vcpu-0| DISKUTIL: scsi0:2 : geometry=65270/255/63
Jul 26 06:40:29.351: vcpu-0| DISKUTIL: scsi0:2 : capacity=1048576000
Jul 26 06:40:29.378: vcpu-1| CPU reset: soft (mode 2)
Jul 26 06:40:29.407: vcpu-0| BIOS-UUID is 56 4d d3 9d d0 1e 5c de-aa 5d e5 ae f5 ca 5a 62
Jul 26 06:40:29.748: mks| MKSHostOps_HideCursor before defineCursor!
Jul 26 06:40:31.928: mks| MKSHostOps_HideCursor before defineCursor!
Jul 26 06:40:32.192: vcpu-0| HBACommon: First write on scsi0:0.fileName='/vmfs/vo
--------------------------
Everything looked ok, so I figured just a random restart.
However, next Saturday at 2.45pm the exact same thing happened, at the exact same time!
I waited a week and sure enough at 2.45pm on Saturday same thing.
I am at a loss as to what's causing this. I couldn't find any scheduled tasks that might be doing it and if it was hardware I figured the IBM host should be restarting. It's not an overheating issue, we're in winter and the heat sensors on the IBM look normal.
It's most perplexing. Has anyone seen anything like this before? What do you guys think might be happening?
Kind Regards
Aaron
I've got an IBM x3650 M2 server running VMware vSphere 4 Hypervisor ESXi 4.1.
I'm running 5X vm's (all server 2008 - DC + TS + Exchange + 3CX + SQL) on it and it had been happily going along until recently.
I had a hard drive go in the raid set about 5 weeks ago. That got replaced by IBM and the raid set rebuilt ok. Everything was stable.
It was about time for me to run some updates, so 3 weeks ago (on a Friday night) I updated Exchange 2010 to SP3 with rollup 6. I also installed the latest windows updates on the 3CX phone server.
The 3CX server didn't like the updates and after the reboot the network card wouldn't connect. A few reboots then it was ok.
I finished everything about 6am that morning. Everything was running well, Went to sleep and woke up that afternoon to a notification that the VM's had rebooted at 2.45pm that Saturday.
I checked the IBM host and that hadn't rebooted, no errors in the logs.
I checked the VMware Console, just had a restart notification in the events. I checked the VM logs from the datastore and it just said the VM's had restarted. Here is a snippit of the logs:
--------------------------
Last logs from the day before were:
Jul 25 05:54:00.222: vcpu-0| CDROM: Emulate GET CONFIGURATION RT 2 starting feature 65
Jul 25 05:54:00.222: vcpu-0| CDROM: Emulate GET CONFIGURATION RT 2 starting feature 259
Then the shutdown day events are:
Jul 26 06:40:27.928: vmx| SCSIDiskESXPopulateVDevDes
Jul 26 06:40:27.928: vmx| Creating virtual dev for scsi0:2
Jul 26 06:40:27.928: vmx| DumpDiskInfo: scsi0:2 createType=11, capacity = 1048576000, numLinks = 1, allocationType = 1
Jul 26 06:40:27.936: vmx| StateLogger::VM has zeroedthick disk scsi0:2; FT enable will be disallowedSCSIDiskESXPopul
Jul 26 06:40:27.937: vmx| SVGA: Device capabilities 0x001f83e2
Jul 26 06:40:28.023: vmx| SVGA: FIFO capabilities 0x0000007f
Jul 26 06:40:28.024: vmx| Ethernet0 MAC Address: 00:0c:29:ca:5a:62
Jul 26 06:40:28.119: vmx| VMXVmdb_LoadRawConfig: Loading raw config
Jul 26 06:40:28.125: vmx| MStat: Creating Stat vm.heartbeat
Jul 26 06:40:28.125: vmx| TOOLS Generated SessionId 2209456672923899303
Jul 26 06:40:28.125: vmx| VMXVmdbGuest_GetToolsVersi
Jul 26 06:40:28.125: vmx| DISKUTIL: scsi0:2 : toolsVersion = 8290
Jul 26 06:40:28.125: vmx| DISKUTIL: scsi0:0 : toolsVersion = 8290
Jul 26 06:40:28.125: vmx| VMXVmdbGuest_GetToolsVersi
Jul 26 06:40:28.125: vmx| TOOLS setting legacy tools version to '8290', manifest status is 5
Jul 26 06:40:28.125: vmx| VMXVmdb_SetToolsVersionSta
Jul 26 06:40:28.125: vmx| VMXVmdb_SetToolsVersionSta
Jul 26 06:40:28.126: vmx| TOOLS INSTALL initializing state to IDLE on power on.
Jul 26 06:40:28.135: vmx| PTSC to VMI Wallclock (nsec) 196170238342 @ 2266747000Hz -> 1406356828000000000 @ 1000000000Hz
Jul 26 06:40:28.135: vmx| PTSC to VMI Wallclock (nsec) ((x * 3789542720) >> 33) + 1406356741457373787
Jul 26 06:40:28.135: vmx| PTSC to ParaTime RealCycles 0 @ 2266747000Hz -> 0 @ 2266747000Hz
Jul 26 06:40:28.135: vmx| PTSC to ParaTime RealCycles ((x * 1) >> 0) + 0
Jul 26 06:40:28.135: vmx| ParaTime RealCycles to PTSC 0 @ 2266747000Hz -> 0 @ 2266747000Hz
Jul 26 06:40:28.135: vmx| ParaTime RealCycles to PTSC ((x * 1) >> 0) + 0
Jul 26 06:40:28.135: vmx| memoryHotplug: Current size = 4096MB, Minimum size = 4096MB, Maximum size = 4096MB
Jul 26 06:40:28.135: vmx| memoryHotplug: Entry[0]: 00000000000000A0-000000000
Jul 26 06:40:28.135: vmx| memoryHotplug: Entry[1]: 00000000001000A0-00000000C
Jul 26 06:40:28.135: vmx| memoryHotplug: Entry[2]: 00000001000000A0-000000014
Jul 26 06:40:28.135: vmx| VMMEM: Initial Reservation: 193MB (MainMem=4096MB SVGA=32MB)
Jul 26 06:40:28.135: vmx| VMMEM: Precise Reservation: 94MB (MainMem=4096MB SVGA=32MB)
Jul 26 06:40:28.136: vmx| guestCpuFeatures = 0x404001fd
Jul 26 06:40:28.223: vmx| VMXVmdb_LoadRawConfig: Loading raw config
Jul 26 06:40:28.228: vmx| Guest CPUID differences from hostCPUID.
Jul 26 06:40:28.228: vmx| guestCPUID level 00000001, 0: 0x000106a5 0x00010800 0x80982201 0x0febfbff
Jul 26 06:40:28.228: vmx| guestCPUID level 40000000, 0: 0x40000010 0x61774d56 0x4d566572 0x65726177
Jul 26 06:40:28.228: vmx| guestCPUID level 40000010, 0: 0x0022967b 0x000101d0 0x00000000 0x00000000
Jul 26 06:40:28.230: vmx| BusMemSample: touched: initPct 75 pages 0 : dirtied: initPct 75 pages 0
Jul 26 06:40:28.230: vmx| Vix: [6290 mainDispatch.c:717]: VMAutomation_PowerOn. Powering on.
Jul 26 06:40:28.230: vmx| VMX_PowerOn: ModuleTable_PowerOn = 1
Jul 26 06:40:28.230: vmx| Setting thread 1 stack size to 2097152.
Jul 26 06:40:28.230: mks| Async MKS thread is alive
Jul 26 06:40:28.231: vmx| Setting thread 4 stack size to 1048576.
Jul 26 06:40:28.231: vcpu-0| VMMon_Start: vcpu-0: worldID=6292
Jul 26 06:40:28.233: vcpu-0| APIC: version = 0x15, max LVT = 6
Jul 26 06:40:28.233: vcpu-0| APIC: LDR = 0x20000000, DFR = 0xffffffff
Jul 26 06:40:28.236: vcpu-0| LSI:Initialize adapter 0
Jul 26 06:40:28.236: vcpu-0| CPU reset: hard (mode 2)
Jul 26 06:40:28.236: vcpu-0| memoryHotplug: Entry[0]: 00000000000000A0-000000000
Jul 26 06:40:28.236: vcpu-0| memoryHotplug: Entry[1]: 00000000001000A0-00000000C
Jul 26 06:40:28.236: vcpu-0| memoryHotplug: Entry[2]: 00000001000000A0-000000014
Jul 26 06:40:28.236: vcpu-0| PIIX4: PM Resuming from suspend type 0x0, chipset.onlineStandby 1
Jul 26 06:40:28.236: vcpu-0| Intel VT: FlexPriority enabled.
Jul 26 06:40:28.236: vcpu-0| Intel VT: VPID enabled.
Jul 26 06:40:28.236: vcpu-0| HV enabled
Jul 26 06:40:28.238: vcpu-0| Setting thread 5 stack size to 1048576.
Jul 26 06:40:28.238: vcpu-1| VMMon_Start: vcpu-1: worldID=6294
Jul 26 06:40:28.238: vcpu-0| Vix: [6470 mainDispatch.c:3571]: VMAutomation_ReportPowerOp
Jul 26 06:40:28.287: vcpu-0| Vix: [6470 mainDispatch.c:3492]: VMAutomationReportPowerSta
Jul 26 06:40:28.287: vcpu-0| Vix: [6470 mainDispatch.c:3492]: VMAutomationReportPowerSta
Jul 26 06:40:28.287: vcpu-0| Transitioned vmx/execState/val to poweredOn
Jul 26 06:40:28.354: vcpu-1| APIC: version = 0x15, max LVT = 6
Jul 26 06:40:28.354: vcpu-1| APIC: LDR = 0x1000000, DFR = 0xffffffff
Jul 26 06:40:28.354: vcpu-1| CPU reset: hard (mode 2)
Jul 26 06:40:28.354: vcpu-1| Intel VT: FlexPriority enabled.
Jul 26 06:40:28.354: vcpu-1| Intel VT: VPID enabled.
Jul 26 06:40:28.354: vcpu-1| HV enabled
Jul 26 06:40:28.356: vcpu-1| VMM64 initialized
Jul 26 06:40:28.356: vcpu-0| VMM64 initialized
Jul 26 06:40:28.430: vcpu-0| MonitorInitNumaUnmapVMM64
Jul 26 06:40:28.494: vcpu-1| CPU reset: soft (mode 2)
Jul 26 06:40:28.740: vcpu-0| SVGA: Registering MemSpace at 0xd4000000(0x0) and 0xd8000000(0x0)
Jul 26 06:40:28.744: vcpu-0| SVGA: Unregistering MemSpace at 0xd4000000(0xd4000000) and 0xd8000000(0xd8000000)
Jul 26 06:40:28.746: mks| MKSHostOps_HideCursor before defineCursor!
Jul 26 06:40:28.919: vcpu-0| SVGA: Registering MemSpace at 0xd4000000(0xd4000000) and 0xd8000000(0xd8000000)
Jul 26 06:40:28.925: vcpu-0| SVGA: Unregistering MemSpace at 0xd4000000(0xd4000000) and 0xd8000000(0xd8000000)
Jul 26 06:40:28.934: vcpu-0| SVGA: Registering IOSpace at 0x10d0
Jul 26 06:40:28.934: vcpu-0| SVGA: Registering MemSpace at 0xd4000000(0xd4000000) and 0xd8000000(0xd8000000)
Jul 26 06:40:28.939: vcpu-0| PCIBridge4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.940: vcpu-0| pciBridge4:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.941: vcpu-0| pciBridge4:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.942: vcpu-0| pciBridge4:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.943: vcpu-0| pciBridge4:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.944: vcpu-0| pciBridge4:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.945: vcpu-0| pciBridge4:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.946: vcpu-0| pciBridge4:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.947: vcpu-0| PCIBridge5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.948: vcpu-0| pciBridge5:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.949: vcpu-0| pciBridge5:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.950: vcpu-0| pciBridge5:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.951: vcpu-0| pciBridge5:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.952: vcpu-0| pciBridge5:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.953: vcpu-0| pciBridge5:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.954: vcpu-0| pciBridge5:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.955: vcpu-0| PCIBridge6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.957: vcpu-0| pciBridge6:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.958: vcpu-0| pciBridge6:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.959: vcpu-0| pciBridge6:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.960: vcpu-0| pciBridge6:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.961: vcpu-0| pciBridge6:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.962: vcpu-0| pciBridge6:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.963: vcpu-0| pciBridge6:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.964: vcpu-0| PCIBridge7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.965: vcpu-0| pciBridge7:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.966: vcpu-0| pciBridge7:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.967: vcpu-0| pciBridge7:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.968: vcpu-0| pciBridge7:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.969: vcpu-0| pciBridge7:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.970: vcpu-0| pciBridge7:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.971: vcpu-0| pciBridge7:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:28.973: vcpu-1| CPU reset: soft (mode 2)
Jul 26 06:40:29.149: vcpu-0| PCIBridge4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.150: vcpu-0| pciBridge4:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.151: vcpu-0| pciBridge4:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.152: vcpu-0| pciBridge4:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.153: vcpu-0| pciBridge4:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.154: vcpu-0| pciBridge4:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.155: vcpu-0| pciBridge4:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.156: vcpu-0| pciBridge4:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.157: vcpu-0| PCIBridge5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.158: vcpu-0| pciBridge5:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.159: vcpu-0| pciBridge5:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.160: vcpu-0| pciBridge5:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.161: vcpu-0| pciBridge5:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.163: vcpu-0| pciBridge5:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.164: vcpu-0| pciBridge5:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.165: vcpu-0| pciBridge5:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.166: vcpu-0| PCIBridge6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.167: vcpu-0| pciBridge6:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.168: vcpu-0| pciBridge6:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.169: vcpu-0| pciBridge6:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.170: vcpu-0| pciBridge6:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.171: vcpu-0| pciBridge6:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.172: vcpu-0| pciBridge6:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.173: vcpu-0| pciBridge6:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.174: vcpu-0| PCIBridge7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.175: vcpu-0| pciBridge7:1: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.176: vcpu-0| pciBridge7:2: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.177: vcpu-0| pciBridge7:3: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.178: vcpu-0| pciBridge7:4: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.179: vcpu-0| pciBridge7:5: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.180: vcpu-0| pciBridge7:6: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.181: vcpu-0| pciBridge7:7: ISA/VGA decoding enabled (ctrl 0004)
Jul 26 06:40:29.310: vcpu-0| DISKUTIL: scsi0:0 : geometry=10439/255/63
Jul 26 06:40:29.340: vcpu-0| DISKUTIL: scsi0:0 : capacity=167702535
Jul 26 06:40:29.340: vcpu-0| DISKUTIL: scsi0:2 : geometry=65270/255/63
Jul 26 06:40:29.351: vcpu-0| DISKUTIL: scsi0:2 : capacity=1048576000
Jul 26 06:40:29.378: vcpu-1| CPU reset: soft (mode 2)
Jul 26 06:40:29.407: vcpu-0| BIOS-UUID is 56 4d d3 9d d0 1e 5c de-aa 5d e5 ae f5 ca 5a 62
Jul 26 06:40:29.748: mks| MKSHostOps_HideCursor before defineCursor!
Jul 26 06:40:31.928: mks| MKSHostOps_HideCursor before defineCursor!
Jul 26 06:40:32.192: vcpu-0| HBACommon: First write on scsi0:0.fileName='/vmfs/vo
--------------------------
Everything looked ok, so I figured just a random restart.
However, next Saturday at 2.45pm the exact same thing happened, at the exact same time!
I waited a week and sure enough at 2.45pm on Saturday same thing.
I am at a loss as to what's causing this. I couldn't find any scheduled tasks that might be doing it and if it was hardware I figured the IBM host should be restarting. It's not an overheating issue, we're in winter and the heat sensors on the IBM look normal.
It's most perplexing. Has anyone seen anything like this before? What do you guys think might be happening?
Kind Regards
Aaron
Also check your hardware and the following logs for clues
/var/log/vmkernel.log
/var/log/vmkernel.log
ASKER
Hey sparvtek
I checked the guest event logs. there's a gap between 2.15pm-2.43pm there. which is strange.
I checked the guest event logs. there's a gap between 2.15pm-2.43pm there. which is strange.
ASKER
Hey Andrew Hancock
Can I check the vmkernel log from vsphere client?
If i log in I can click on administration, then logs. The logs there only show today unfortunately so I might have to wait until the weekend to see that days log.
Can I check the vmkernel log from vsphere client?
If i log in I can click on administration, then logs. The logs there only show today unfortunately so I might have to wait until the weekend to see that days log.
it's best to, remotely login to the ESXi host....(console) or remotely via ssh.
if using vCenter Server, you can select File > Export > Export System Logs
if using vCenter Server, you can select File > Export > Export System Logs
Is there anything in the guest event logs about "unexpected shutdown" somewhere around the end of the gap?
Is syslog enabled for the VMware hosts? Might be interesting to see what happens around the guest restarts.
The strange thing is that it happens at the exact same time every Saturday, which makes me think about backup or updates or something. Scheduled Anti-Virus scan maybe??
Is syslog enabled for the VMware hosts? Might be interesting to see what happens around the guest restarts.
The strange thing is that it happens at the exact same time every Saturday, which makes me think about backup or updates or something. Scheduled Anti-Virus scan maybe??
ASKER
hi Andrew Hancock
I re-exported the logs successfully but unfortunately it's only showing the last two days. I can't go back to the last Saturday. I'll re-export the logs again just after the reboot this weekend and see what shows up :)
I re-exported the logs successfully but unfortunately it's only showing the last two days. I can't go back to the last Saturday. I'll re-export the logs again just after the reboot this weekend and see what shows up :)
ASKER
hi spravtek i believe syslog enabled are enabled :)
ASKER
hey guys so I was logged onto the server when the restart occurred this afternoon. I have managed to get more log information. I believe the restart happened at about 2.30pm my time (6.30 UTM time).
I can't see anything obvious in there though as there's a gap in the logs between 6.30-6.43. :(
I also noticed on the IBM host that the network dropped out at the same time and got a screenshot of that from the management web console.
I'll post and see what you guys think?
Edit: Also note I performed a physical host reboot after the VM's and VMHostClient went down. Just in case it was needed (so you will noticed that in the logs around 6.50ish).
ibm-console-log.jpg
hostdlog.docx
messagelog.docx
I can't see anything obvious in there though as there's a gap in the logs between 6.30-6.43. :(
I also noticed on the IBM host that the network dropped out at the same time and got a screenshot of that from the management web console.
I'll post and see what you guys think?
Edit: Also note I performed a physical host reboot after the VM's and VMHostClient went down. Just in case it was needed (so you will noticed that in the logs around 6.50ish).
ibm-console-log.jpg
hostdlog.docx
messagelog.docx
Are you using VMware HA ?
ASKER
not using VMware HA but have got resource allocation settings in place
ASKER
it's so weird, it's always the exact same time each week. spot on 2.30pm on Saturday. It's got to be some scheduled task, i just can't see any *pulls hair out*
ASKER
just a question, i did have one hdd fail in the first raid set (was raid1), about 6weeks ago. If a drive is replaced in a raid set do I need to perform a rescan on the volume? could that cause this issue?
I don't think a rescan of the raid set has anything to do with VM's rebooting each week at exactly the same time ... It has to be either a schedule somewhere, or something to do with backup maybe ... Scheduled tasks on all the VM's seems unlikely ... vCenter? ...We don't know enough of your setup to give more hints I'm afraid.
ASKER
do you know where I can check scheduled tasks in the vcenter by ssh login? i don't have physical access to the console.
Login to vCenter Server, and check the Schedule.
ASKER
i am using vsphere esxi 4.1 and logging in with vmwwareclient , i googled where the schedule should in be vcenter but i don't have that option in my client login. is my version too old, or is that option unavailable for vsphere?
are you connecting to vCenter Server or directly to ESXi ?
ASKER
i'm logging in from a desktop machine using "vmware vsphere client 4.1" to the ip address of the esxi host.
here is a screenshot of the login and the inventory screen :)
1.-vmwareclient-logon-screen.jpg
2.vsphereclientinventoryscreen.jpg
here is a screenshot of the login and the inventory screen :)
1.-vmwareclient-logon-screen.jpg
2.vsphereclientinventoryscreen.jpg
Okay, so you have no vCenter Server, and hence no Scheduled Tasks!
ESXi 4.1 260247 is very very very old!!!!
That's the first GA release in 2010-07-13!
The last version is....
ESXi/ESX 4.1 Patch 11
Release Date 2014-04-10
Build 1682698
I would try an upgrade! at least....
and for support you would need to be on at least SP1 of WIndows 2008...
That's the first GA release in 2010-07-13!
The last version is....
ESXi/ESX 4.1 Patch 11
Release Date 2014-04-10
Build 1682698
I would try an upgrade! at least....
and for support you would need to be on at least SP1 of WIndows 2008...
ASKER
I think you're right.
I've checked pretty much everything. backup software doesn't look like the cause.
I did find adobe flash update scheduled taskrunning each Saturday at the same time. I just deleted but surely its not that.
One thing I do want to check is the vmkernel.
can I do that from cli with vphere 4.1? When I run the connect command its not recognized. I don't have access to the console as I am remote atm
I've checked pretty much everything. backup software doesn't look like the cause.
I did find adobe flash update scheduled taskrunning each Saturday at the same time. I just deleted but surely its not that.
One thing I do want to check is the vmkernel.
can I do that from cli with vphere 4.1? When I run the connect command its not recognized. I don't have access to the console as I am remote atm
ASKER
Hey Andrew
So I finally solved the reboot issue!
One of the batteries died in the UPS this week so we needed to replace it. We decided to put a new UPS in, since then no reboots!! So the old UPS must have been a bit unstable and was causing the host to reboot. Just so weird that it was the exact same time each week.
I can now sleep easier! :)
So I finally solved the reboot issue!
One of the batteries died in the UPS this week so we needed to replace it. We decided to put a new UPS in, since then no reboots!! So the old UPS must have been a bit unstable and was causing the host to reboot. Just so weird that it was the exact same time each week.
I can now sleep easier! :)
ASKER CERTIFIED SOLUTION
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
ASKER
the UPS was APC too!
Yes I thought it was.
In the log you posted following can be found: CPU reset: soft (mode 2)
Which indicates that the Guest OS initiated the reboot...
So I'd definitely check if for some reason all the guest VM's do a reboot on the same time, did you check event logs of the VM's? to see if there is something of interest around the time of reboot? Windows Update (other updates) ... Backup...