How To Work With VMware Log Files

(Part 2 – Operation: VM creation and modification)

Johnny Zhang

The goal for this document is how to quickly find the needed information for some of the operations that you do every day such as creating VMs, modify it etc. The example of the log file are collect from VMware ESX 4.1.0 and Vcenter 4.1 with all tasks triggered from VIClient connected to vCenter (I will work on a different document for tasks triggered from ESX host)

Log locations:

VMware ESX 4.1.0:

• messages: /var/log/messages* (Those logs show you what happened inside service console)

• vmkernel: /var/log/vmkernel* (Those logs give you information about VMkernel and interaction between the VMkernel and attached hardware such as physical NICs, HBAs etc

• hostd: /var/log/vmware/hostd*.log (The most important logs to show the interactions between VMkerenl and VMs hosted on this ESX server)

• vpxa: /var/log/vmware/vpx/vpxa*.log (vpxa is the agent running on ESX server, it reports everything from the host to vCenter and vice versa. Those logs are used when the issue is not on the ESX host, but between the host and vCenter)

VM used in this example: Johnny-test

Create A VM

We start with the name of the VM (in this example “Johnny-test”)

“grep -i johnny-test /var/log/vmware/hostd* | grep -i "Create called" | less”

In this command we are looking for the VM named “johnny-test” from all hostd logs, and looking for the keyword “Create called” from the output of the first “grep”.

You can also do this from vCenter side, but I’d like to get the complete opID, you will see why later.

Output from this command:

hostd-12.log:[2011-04-11 11:07:45.971 F5ADCB90 info 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-0000006E-b8] Create called: /vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx

hostd.log:[2011-04-11 11:07:45.971 F5ADCB90 info 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-0000006E-b8] Create called: /vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx

What we are looking for:

Now we know the log file that content the VM creation is hostd-12.log, this is nice to know since we may have many hostd logs in this directory, narrowing down the log would make our life easier. opID=D935FB67-0000006E-b8. If you read my first document about VMotion, you may already know the opID is a support aid put by engineering in ESX 4.1. It’s extremely useful since the same ID is consistent across all logs (ESX and vCenter). We can see there is a “create called” so we know hostd received a create VM call from vCenter via VIClient. It will also list the path of the VM. (If you wonder why a VM did not show up at the location it suppose to be, this will tell you, if this is instructed to do so or the VM was moved later after the creation) Please keep in mind this opID is the same on the ESX server, but only content the first part for vCenter logs (vpxd-*.log)

opID=D935FB67-0000006E

More from logs:

Let’s work our way down: vCenter (vpxd-*log) --> vpxa (/var/log/vmware/vpx/vpxa*.log on ESX) --> hostd (/var/log/vmware/hostd*.log)

vCenter log:

The logs are located in %ALLUSERSPROFILE%\Application Data\VMware\VMware VirtualCenter\Logs, which translates to C:\Documents and Settings\All Users\Application Data\VMware\VirtualCenter\logs in Windows 2003 and C:\ProgramData\VMware\VMware VirtualCenter\Logs in Windows 2008.

“grep -i D935FB67-0000006E vpxd-[1-9]*.log | less”

Remember we need to use the only the first part of the opID, we are looking for information from vpxd-*logs. Since vpxd-profile*.log are also in the same directory, we look for any files after “vpxd-“ start with a number. Because vpxd-profile*.logs are huge, it can take a long time for grep to finish.

Output of the logs:

vpxd-106.log:[2011-04-11 11:10:32.478 06260 info 'App' opID=D935FB67-0000006E] [VpxLRO] -- BEGIN task-1619 -- group-v22 -- vim.Folder.createVm -- 0B4CA1AE-6FF5-4CAD-8912-FD3150C93CD8(657B630E-620A-47AB-AD72-7D949C5F7F25)

vpxd-106.log:[2011-04-11 11:10:32.899 06260 warning 'App' opID=D935FB67-0000006E] [JrnlFilePersistenceProvider] Got EOF while reading file

vpxd-106.log:[2011-04-11 11:10:32.948 06260 info 'App' opID=D935FB67-0000006E] [VpxdVmprovXaction] Starting journal rollback

vpxd-106.log:[2011-04-11 11:10:32.948 06260 info 'App' opID=D935FB67-0000006E] [VpxdVmprovXaction] Vm provision transaction rollback done

vpxd-106.log:[2011-04-11 11:10:33.083 06260 error 'App' opID=D935FB67-0000006E] [VpxdInvtId::VpxdInvtIdGetVpxApplicationId] The application vcid size cannot be <= 0 or > 64

vpxd-106.log:[2011-04-11 11:10:37.629 06260 info 'App' opID=D935FB67-0000006E] [VpxLRO] -- FINISH task-1619 -- group-v22 -- vim.Folder.createVm -- 0B4CA1AE-6FF5-4CAD-8912-FD3150C93CD8(657B630E-620A-47AB-AD72-7D949C5F7F25)

vpxd-106.log: 06260 verbose 'PropertyProvider' opID=D935FB67-0000006E] RecordOp ASSIGN: info.progress, task-1619

vpxd-106.log:[2011-04-11 11:10:34.988 06260 verbose 'App' opID=D935FB67-0000006E] [TaskInfoListener] Waiting on channel task-45062

vpxd-106.log:[2011-04-11 11:10:34.988 06260 verbose 'App' opID=D935FB67-0000006E] [TaskInfoChannel::GetTaskInfoAsync] task: task-45062 setup for async notification

vpxd-106.log:[2011-04-11 11:10:34.988 06260 verbose 'App' opID=D935FB67-0000006E] [TaskInfoChannel::GetTaskInfo] Ready to block - task: task-45062

vpxd-106.log:[2011-04-11 11:10:35.158 06260 verbose 'App' opID=D935FB67-0000006E] [VpxdVmprovUtil] CreateVm on host returned sanfs://vmfs_uuid:4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx

vpxd-106.log:[2011-04-11 11:10:35.158 06260 verbose 'App' opID=D935FB67-0000006E] [TaskInfoListener::~TaskInfoListener] Connection number = 6277

vpxd-106.log:[2011-04-11 11:10:36.164 06260 verbose 'App' opID=D935FB67-0000006E] [VpxdInvtHost::WaitForSync] moHost = bs-bcs-h137.bsl.vmware.com [vim.HostSystem:host-261], masterGenNo = 17765, syncGenNo = 17780

vpxd-106.log:[2011-04-11 11:10:36.164 06260 verbose 'App' opID=D935FB67-0000006E] [VpxdInvtHost] Queuing sync LRO for host: bs-bcs-h137.bsl.vmware.com

vpxd-106.log:[2011-04-11 11:10:37.600 06260 verbose 'App' opID=D935FB67-0000006E] [VpxdMoHost::RequestResPoolUpdate] Incremented ResPoolSpecGenNo to 682

vpxd-106.log:[2011-04-11 11:10:37.617 06260 verbose 'App' opID=D935FB67-0000006E] [JrnlFilePersistenceProvider::DeleteJournal] Deleting C:\ProgramData\VMware\VMware VirtualCenter\journal\1302534632.2.

vpxd-106.log:[2011-04-11 11:10:37.628 06260 verbose 'PropertyProvider' opID=D935FB67-0000006E] RecordOp ASSIGN: disabledMethod, vm-381

vpxd-106.log:[2011-04-11 11:10:37.629 06260 verbose 'PropertyProvider' opID=D935FB67-0000006E] RecordOp ASSIGN: info.state, task-1619

vpxd-106.log:[2011-04-11 11:10:37.629 06260 verbose 'PropertyProvider' opID=D935FB67-0000006E] RecordOp ASSIGN: info.cancelable, task-1619

vpxd-106.log:[2011-04-11 11:10:37.629 06260 verbose 'PropertyProvider' opID=D935FB67-0000006E] RecordOp ASSIGN: info.result, task-1619

vpxd-106.log:[2011-04-11 11:10:37.629 06260 info 'App' opID=D935FB67-0000006E] [VpxLRO] -- FINISH task-1619 -- group-v22 -- vim.Folder.createVm -- 0B4CA1AE-6FF5-4CAD-8912-FD3150C93CD8(657B630E-620A-47AB-AD72-7D949C5F7F25)

vpxd-106.log:[2011-04-11 11:10:38.600 02796 verbose 'PropertyProvider' opID=D935FB67-0000006E] RecordOp ASSIGN: disabledMethod, vm-381

opID=D935FB67-0000006E] [VpxLRO] -- BEGIN task-1619 -- group-v22 -- vim.Folder.createVm -- 0B4CA1AE-6FF5-4CAD-8912-FD3150C93CD8(657B630E-620A-47AB-AD72-7D949C5F7F25)

Every task will have a task ID which will be send to vCenter DB. All tasks have a “BEGIN” and a “FINISH”. In this case, we have a task number 1619, the first UUID is instance UUID, and the one in the brackets is the VM UUID.

error 'App' opID=D935FB67-0000006E] [VpxdInvtId::VpxdInvtIdGetVpxApplicationId] The application vcid size cannot be <= 0 or > 64

Here, this is not an error. vCenter did a pre-check and sure enough find the VCID to be 0 (since the ID never existed before). You can ignore this message in most cases.

FINISH task-1619 -- group-v22 -- vim.Folder.createVm -- 0B4CA1AE-6FF5-4CAD-8912-FD3150C93CD8(657B630E-620A-47AB-AD72-7D949C5F7F25)

Task 1619 finished

Vpxa logs:

“grep -i D935FB67-0000006E-b8 /var/log/vmware/vpx/vpxa* | less”

I will only put part of the logs output here:

vpxa-205.log:[2011-04-11 11:07:44.854 F701CB90 verbose 'PropertyProvider' opID=D935FB67-0000006E-b8] RecordOp ASSIGN: info.state, task-45062

vpxa-205.log:[2011-04-11 11:07:44.854 F701CB90 verbose 'PropertyProvider' opID=D935FB67-0000006E-b8] RecordOp ASSIGN: info.cancelable, task-45062

vpxa-205.log:[2011-04-11 11:07:44.854 F701CB90 info 'App' opID=D935FB67-0000006E-b8] [VpxLRO] -- BEGIN task-45062 -- -- vpxapi.VpxaService.createVm -- 5239f0b1-2f5c-8f6a-a2c4-aa1114ef6178

vpxa-205.log:[2011-04-11 11:07:44.854 F701CB90 verbose 'App' opID=D935FB67-0000006E-b8] [VpxaDatastoreContext] Resolved URL sanfs://vmfs_uuid:4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx to localPath /vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx

:

:

pxa-205.log:[2011-04-11 11:07:46.813 F701CB90 verbose 'PropertyProvider' opID=D935FB67-0000006E-b8] RecordOp ASSIGN: info, task-45062

vpxa-205.log:[2011-04-11 11:07:46.813 F701CB90 trivia 'PropertyCollector' opID=D935FB67-0000006E-b8] TriggerProcessGUReqs: Session 5239f0b1-2f5c-8f6a-a2c4-aa1114ef6178

vpxa-205.log:[2011-04-11 11:07:46.813 F701CB90 info 'App' opID=D935FB67-0000006E-b8] [VpxLRO] -- FINISH task-45062 -- -- vpxapi.VpxaService.createVm -- 5239f0b1-2f5c-8f6a-a2c4-aa1114ef6178

When vCenter send the request, the ESX host itself has their own task ID, you can see in our case the task on the host was 45062, and the UUID of the session which was 5239f0b1-2f5c-8f6a-a2c4-aa1114ef6178

Hostd logs:

“grep -i D935FB67-0000006E-b8 /var/log/vmware/hostd-* | less”

Part of the logs’ output:

hostd-12.log:[2011-04-11 11:07:45.960 F5ADCB90 info 'TaskManager' opID=D935FB67-0000006E-b8] Task Created : haTask-ha-folder-vm-vim.Folder.createVm-179078

hostd-12.log:[2011-04-11 11:07:45.970 F5ADCB90 verbose 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-0000006E-b8] Enabling disk uuid for Windows 2008 VM

:

:

hostd-12.log:[2011-04-11 11:07:46.340 F558AB90 info 'DiskLib' opID=D935FB67-0000006E-b8] DISKLIB-LIB : CREATE: "/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmdk" -- vmfs capacity=4194304 (2 GB) adapter=lsilogic cowGran=0

hostd-12.log:[2011-04-11 11:07:46.410 F558AB90 info 'DiskLib' opID=D935FB67-0000006E-b8] DISKLIB-DSCPTR: "/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmdk" : creation successful.

:

:

hostd-12.log:[2011-04-11 11:07:46.435 F558AB90 verbose 'VmDiskMgr' opID=D935FB67-0000006E-b8] Disk created successfully.

:

:

hostd-12.log:[2011-04-11 11:07:46.445 F558AB90 info 'ha-eventmgr' opID=D935FB67-0000006E-b8] Event 60 : Assign a new instance UUID (5021b940-e1a5-bb6c-18ef-5b653290d94d) to

hostd-12.log:[2011-04-11 11:07:46.445 F558AB90 info 'HostsvcPlugin' opID=D935FB67-0000006E-b8] Lookupvm: World ID not set for VM 112

:

:

hostd-12.log:[2011-04-11 11:07:46.778 F558AB90 info 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-0000006E-b8] State Transition (VM_STATE_INITIALIZING -> VM_STATE_OFF)

:

:

hostd-12.log:[2011-04-11 11:07:46.778 F558AB90 info 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-0000006E-b8] Initialized virtual machine.

hostd-12.log:[2011-04-11 11:07:46.779 F558AB90 verbose 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-0000006E-b8] Create DONE: /vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx

hostd-12.log:[2011-04-11 11:07:46.786 F558AB90 info 'TaskManager' opID=D935FB67-0000006E-b8] Task Completed : haTask-ha-folder-vm-vim.Folder.createVm-179078 Status success

hostd-12.log:[2011-04-11 11:07:46.786 F558AB90 info 'ha-eventmgr' opID=D935FB67-0000006E-b8] Event 61 : Created virtual machine on bs-bcs-h137.bsl.vmware.com in ha-datacenter

hostd-12.log:[2011-04-11 11:07:46.786 F558AB90 verbose 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-0000006E-b8] Create worker thread completed successfully

We can see some details from hostd logs. We know the VM was a “Windows 2008 VM” we know the VMDK size for this VM was 2GB, we know the virtual SCSI controller is “lsilogic”

State Transition (VM_STATE_INITIALIZING -> VM_STATE_OFF)

This is the first time hostd have the record of the VM’s power state. And at the end, the “create worker” finished its job.

VM modifications (Edit setting on VM)

Three modifications done to the VM

1. Changed memory from size

2. Change vCPU count

3. Add a virtual NIC

We also start by locating the opID

“grep -i johnny-test /var/log/vmware/hostd-* | grep "vim.vm.ConfigSpec" | less”

We are using the key word “vim.vm.ConfigSpec” to find any changes to the VM

Log output:

hostd-12.log:[2011-04-11 11:08:23.647 F579CB90 info 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-0000008F-35] Reconfigure: (vim.vm.ConfigSpec) {

hostd-12.log:[2011-04-11 11:08:45.954 F5508B90 info 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-000000A2-e] Reconfigure: (vim.vm.ConfigSpec) {

hostd-12.log:[2011-04-11 11:09:22.018 F6350900 info 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-000000B9-32] Reconfigure: (vim.vm.ConfigSpec) {

Here are the 3 modifications that I performed on the VM, and we see 3 different opIDs

For the VM modification, the only useful log to us is hostd logs. From the first output, we know the log we need to look at is hostd-12.log. Let’s get to details

“less -RS hostd-12.log” now search for the opID “/D935FB67-0000008F-35”

What we are looking for is this section:

[2011-04-11 11:08:23.645 F579CB90 info 'TaskManager' opID=D935FB67-0000008F-35] Task Created : haTask-112-vim.VirtualMachine.reconfigure-179094

[2011-04-11 11:08:23.647 F579CB90 info 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-0000008F-35] Reconfigure: (vim.vm.ConfigSpec) {

dynamicType = ,

changeVersion = "2011-04-11T15:07:46.665679Z",

name = ,

version = ,

uuid = ,

instanceUuid = ,

npivWorldWideNameType = ,

npivDesiredNodeWwns = ,

npivDesiredPortWwns = ,

npivTemporaryDisabled = ,

npivOnNonRdmDisks = ,

npivWorldWideNameOp = ,

locationId = ,

guestId = ,

alternateGuestName = ,

annotation = ,

files = (vim.vm.FileInfo) {

dynamicType = ,

vmPathName = "[]/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx",

snapshotDirectory = ,

suspendDirectory = ,

logDirectory = ,

},

tools = (vim.vm.ToolsConfigInfo) null,

flags = (vim.vm.FlagInfo) null,

consolePreferences = (vim.vm.ConsolePreferences) null,

powerOpInfo = (vim.vm.DefaultPowerOpInfo) null,

numCPUs = ,

memoryMB = 3072,

memoryHotAddEnabled = ,

cpuHotAddEnabled = ,

cpuHotRemoveEnabled = ,

cpuAllocation = (vim.ResourceAllocationInfo) null,

memoryAllocation = (vim.ResourceAllocationInfo) null,

cpuAffinity = (vim.vm.AffinityInfo) null,

memoryAffinity = (vim.vm.AffinityInfo) null,

networkShaper = (vim.vm.NetworkShaperInfo) null,

swapPlacement = ,

swapDirectory = ,

preserveSwapOnPowerOff = ,

bootOptions = (vim.vm.BootOptions) null,

vAppConfig = (vim.vApp.VmConfigSpec) null,

ftInfo = (vim.vm.FaultToleranceConfigInfo) null,

vAppConfigRemoved = ,

vAssertsEnabled = ,

changeTrackingEnabled = ,

What I did was changed the memory size from whatever was before to 3072 (3GB) and there was no change on any other components.

Now keep going with the second part:

“less -RS hostd-12.log” now search for the opID “/D935FB67-000000A2-e”

Let’s see the change:

[2011-04-11 11:08:45.952 F5508B90 info 'TaskManager' opID=D935FB67-000000A2-e] Task Created : haTask-112-vim.VirtualMachine.reconfigure-179103

[2011-04-11 11:08:45.954 F5508B90 info 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-000000A2-e] Reconfigure: (vim.vm.ConfigSpec) {

:

:

tools = (vim.vm.ToolsConfigInfo) null,

flags = (vim.vm.FlagInfo) null,

consolePreferences = (vim.vm.ConsolePreferences) null,

powerOpInfo = (vim.vm.DefaultPowerOpInfo) null,

numCPUs = 2,

memoryMB = ,

memoryHotAddEnabled = ,

cpuHotAddEnabled = ,

cpuHotRemoveEnabled = ,

cpuAllocation = (vim.ResourceAllocationInfo) null,

memoryAllocation = (vim.ResourceAllocationInfo) null,

cpuAffinity = (vim.vm.AffinityInfo) null,

memoryAffinity = (vim.vm.AffinityInfo) null,

networkShaper = (vim.vm.NetworkShaperInfo) null,

swapPlacement = ,

swapDirectory = ,

preserveSwapOnPowerOff = ,

bootOptions = (vim.vm.BootOptions) null,

vAppConfig = (vim.vApp.VmConfigSpec) null,

ftInfo = (vim.vm.FaultToleranceConfigInfo) null,

vAppConfigRemoved = ,

vAssertsEnabled = ,

changeTrackingEnabled = ,

In here, I changed the number of vCPUs from default 1 to 2.

The last part:

“less -RS hostd-12.log” now search for the opID “/D935FB67-000000B9-32”

[2011-04-11 11:09:22.016 F6350900 info 'TaskManager' opID=D935FB67-000000B9-32] Task Created : haTask-112-vim.VirtualMachine.reconfigure-179114

[2011-04-11 11:09:22.018 F6350900 info 'vm:/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Johnny-test/Johnny-test.vmx' opID=D935FB67-000000B9-32] Reconfigure: (vim.vm.ConfigSpec) {

:

:

tools = (vim.vm.ToolsConfigInfo) null,

flags = (vim.vm.FlagInfo) null,

consolePreferences = (vim.vm.ConsolePreferences) null,

powerOpInfo = (vim.vm.DefaultPowerOpInfo) null,

numCPUs = ,

memoryMB = ,

memoryHotAddEnabled = ,

cpuHotAddEnabled = ,

cpuHotRemoveEnabled = ,

deviceChange = (vim.vm.device.VirtualDeviceSpec) [

(vim.vm.device.VirtualDeviceSpec) {

dynamicType = ,

operation = "add",

fileOperation = ,

device = (vim.vm.device.VirtualE1000) {

dynamicType = ,

key = -100,

deviceInfo = (vim.Description) null,

backing = (vim.vm.device.VirtualEthernetCard.NetworkBackingInfo) {

dynamicType = ,

deviceName = "Virtual Machine Network",

useAutoDetect = ,

network = ,

inPassthroughMode = ,

},

connectable = (vim.vm.device.VirtualDevice.ConnectInfo) {

dynamicType = ,

startConnected = true,

allowGuestControl = true,

connected = true,

status = ,

},

controllerKey = 100,

unitNumber = ,

addressType = "Assigned",

macAddress = "00:50:56:a1:00:0a",

wakeOnLanEnabled = true,

},

}

],

cpuAllocation = (vim.ResourceAllocationInfo) null,

memoryAllocation = (vim.ResourceAllocationInfo) null,

cpuAffinity = (vim.vm.AffinityInfo) null,

memoryAffinity = (vim.vm.AffinityInfo) null,

networkShaper = (vim.vm.NetworkShaperInfo) null,

swapPlacement = ,

swapDirectory = ,

preserveSwapOnPowerOff = ,

bootOptions = (vim.vm.BootOptions) null,

vAppConfig = (vim.vApp.VmConfigSpec) null,

ftInfo = (vim.vm.FaultToleranceConfigInfo) null,

vAppConfigRemoved = ,

vAssertsEnabled = ,

changeTrackingEnabled = ,

Ok, I think you got the idea, here is the virtual NIC added to this VM with assigned mac address and settings.

You can use the opID to filter vpxa and vpxd logs, but for what change was made, hostd is the place you want to look into.

How To Work With VMware Log Files

(Part 1 - VMotion)

Johnny Zhang

The goal for this document is how to quickly find the needed information for a VMotion event. The example of the log file are collect from VMware ESX 4.1.0 build-348481

and VMware ESXi 4.1.0 build-348481

. There maybe some differences in the earlier version of ESX logs, but the steps should be same.

Log locations:

VMware ESX 4.1.0: We care about hostd logs (/var/log/vmware/hostd*.log). Although the vmkerenl logs locate at /var/log/ will also content some information, we can safely focus on the hostd logs to find the information we need.

VMware ESXi 4.1.0: ESXi has the same hostd logs locate at /var/log/vmware/hostd*.log. However, in current version of ESXi, both vmkernel logs and hostd logs are also put into /var/log/messages*. So you can choose which one you like to work with. (I prefer /var/log/vmware/hostd*.log, since it will have less noise from other logs, and it will return the “grep” faster, just because it has less contents)

VM used in this example: Vmotion-test

Steps to work with the logs:

1. All we need is the name of the VMotioned VM (in this example “vmotion-test”)

2. Find the VMotion ID of this incident. The VMotion ID is a unique ID that generated for each VMotion, the ID is consistent across all logs on both source and destination ESX hosts.

“grep -i vmotion-test /var/log/vmware/hostd* | grep -i vmotionprepare | less”

In this command we are looking for the VM named “vmotion-test” from all hostd logs, and looking for the keyword “vmotionprepare” from the out put of the first “grep”. (keep in mind Linux is a case sensitive OS, we put “-i” option for the grep to make our life easier.)

Out put from this command:

hostd-11.log:[2011-04-01 15:14:34.203 F5A5AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-d] VMotionPrepare (1301685441034055): Sending 'to' srcIp=10.21.51.137 dstIp=10.21.53.102, type=1, encrypted=false, remoteThumbprint=

hostd-11.log:[2011-04-01 15:14:34.203 F5A5AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-d] VMotionPrepare: srcMgmtIp=10.21.49.137

hostd-11.log:[2011-04-01 15:14:34.203 F5A5AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-d] VMotionPrepare: dstMgmtIp=10.21.49.138

hostd-11.log:[2011-04-01 15:17:09.134 F5A9BB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000008E9-59] VMotionPrepare (1301685587877584): Sending 'from' srcIp=10.21.53.102 dstIp=10.21.51.137, type=1, encrypted=false, remoteThumbprint=

hostd-11.log:[2011-04-01 15:17:09.134 F5A9BB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000008E9-59] VMotionPrepare: srcMgmtIp=10.21.49.138

hostd-11.log:[2011-04-01 15:17:09.134 F5A9BB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000008E9-59] VMotionPrepare: dstMgmtIp=10.21.49.137

hostd-11.log:[2011-04-01 15:17:58.891 F558AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-00000931-68] VMotionPrepare (1301685636815010): Sending 'to' srcIp=10.21.51.137 dstIp=10.21.51.137, type=2, encrypted=false, remoteThumbprint=

hostd-11.log:[2011-04-01 15:17:58.891 F558AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-00000931-68] VMotionPrepare: srcMgmtIp=10.21.49.137

hostd-11.log:[2011-04-01 15:17:58.891 F558AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-00000931-68] VMotionPrepare: dstMgmtIp=10.21.49.137

hostd-11.log:[2011-04-01 15:17:58.891 F558AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-00000931-68] VMotionPrepare: dstVmDirPath=/vmfs/volumes/4cc0989b-5f6597b4-5fa3-001b2132c111/Vmotion-test/

What we are looking for:

We are looking for the vmotion ID, every time there is VMotion triggered, a VMotion ID will be created first. As we can see here, there were three different VMotion happened on this VM named “vmotion-test” With ID 1301685441034055, 1301685587877584, and 1301685636815010. Now depend on which one we want to analyze, we can look into details of each VMotion. (Vcenter has a record of time for each VMotion, we can find the corresponding time on the ESX servers)

What else:

There are some good information we can see from this output. Let's use vmotion ID 1301685441034055 as the example.

Sending 'to' srcIp=10.21.51.137 dstIp=10.21.53.102

As we can see here, the log tells us we are on the source ESX host with the “Sending 'to'” statement. (You will see Sending 'from' on the destination host)

“srcIp=10.21.51.137” the source VMotion IP is 10.21.51.137. (Note this is different from the Service Console IP address or management IP address on ESXi)

“dstIp=10.21.53.102” The destination host VMotion IP is 10.21.53.102

“VMotionPrepare: srcMgmtIp=10.21.49.137

” This is the management IP of the source host

“VMotionPrepare: dstMgmtIp=10.21.49.138

” This is the management IP of the destination host

3. Now we can find the details. Again use 1301685441034055 as an example

“grep -i 1301685441034055 hostd* | less” (You don't have to put “less”, just a habit of my own)

In this command, we are grepping for all logs related to VMotion ID 1301685441034055.

Out put from this command: (Long out put, I will go one section at a time)

hostd-11.log:[2011-04-01 15:14:34.135 F5A5AB90 info 'VMotion' opID=F6FC49D5-000007E6-d] PrepareSourceEx [1301685441034055], VM = '32'

hostd-11.log:[2011-04-01 15:14:34.135 F5A5AB90 info 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-d] VMotionEntry: migrateType = 1

hostd-11.log:[2011-04-01 15:14:34.203 F5A5AB90 verbose 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-d] JrnlCreate: Created 1301685274.0

hostd-11.log:[2011-04-01 15:14:34.203 F5A5AB90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-d] VMotionPrepare (1301685441034055): Sending 'to' srcIp=10.21.51.137 dstIp=10.21.53.102, type=1, encrypted=false, remoteThumbprint=

hostd-11.log:[2011-04-01 15:14:34.205 F5A5AB90 verbose 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-d] Migration changed state from NONE to BEGIN

hostd-11.log:[2011-04-01 15:14:34.205 F5A5AB90 info 'VMotion' opID=F6FC49D5-000007E6-d] Completed scheduling PrepareSourceEx [1301685441034055].

hostd-11.log:[2011-04-01 15:14:34.231 F5549B90 verbose 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx'] VMotionCmdCb [1301685441034055] 'to': done

hostd-11.log:[2011-04-01 15:14:34.231 F5549B90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx'] VMotionCmdCb [1301685441034055] : Prepare task completed successfully

hostd-11.log:[2011-04-01 15:14:35.055 F5549B90 info 'VMotion' opID=F6FC49D5-000007E6-a1] InitiateSource [1301685441034055], WID = 6947903

opID is “operation ID” some what new from engineering that to act as a debugging aid. You may not see those in the earlier version of ESX logs. This is very nice for support or whoever need to look into the logs, since this ID is designed to consistent across ESX server and vCenter logs as well. In this example you can see there are many different opIDs for the same VMotion ID.

“migrateType” There are 6 different type of migrations. For what we care, the first three are:

• migrateType = 1 VMotion

• migrateType = 2 Storage VMotion (FSR)

• migrateType = 3 Fault Tolerant (FT)

“JrnlCreate” Every VMotion will have a journal create, in case any migration failure, the source host can rollback with the journal. The VMotion journal management is 5 steps process

• Create

• Begin

• PutWID

• End

• Delete

“Migration changed state from NONE to BEGIN

” This is the beginning of the VMotion process

“VmotionCmdCb” VMotion command call back is a process that update VMDB on the ESX host with the path to the VM's configuration file and vmdk files in case there was some changes on the VM. (As you can see it followed by the path to the vmx file)

“InitiateSource [1301685441034055], WID = 6947903

” After all the preparation and checking now the VMotion process need to find the world ID of the VM which is 6947903 in our case.

Out Put Continued:

hostd-11.log:[2011-04-01 15:14:35.221 F5549B90 verbose 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-a1] JrnlBegin: VM objID=32 srcIp=10.21.51.137 migrateType=MIGRATE_TYPE_VMOTION

hostd-11.log:[2011-04-01 15:14:35.243 F5549B90 verbose 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-a1] JrnlPutWid: Wrote wid=4868

hostd-11.log:[2011-04-01 15:14:35.243 F5549B90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-a1] VMotionInitiateSrc (1301685441034055): wid=6947903

hostd-11.log:[2011-04-01 15:14:35.244 F5549B90 verbose 'VMotionSrc (1301685441034055)' opID=F6FC49D5-000007E6-a1] Migration changed state from BEGIN to MIGRATING

hostd-11.log:[2011-04-01 15:14:35.261 F579CB90 verbose 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx'] VMotionCmdCb [1301685441034055] 'start': done

hostd-11.log:[2011-04-01 15:14:39.143 F558AB90 info 'VMotionSrc (1301685441034055)'] ResolveCb: VMX reports needsUnregister = true for migrateType MIGRATE_TYPE_VMOTION

hostd-11.log:[2011-04-01 15:14:39.143 F558AB90 info 'VMotionSrc (1301685441034055)'] ResolveCb: Succeeded

hostd-11.log:[2011-04-01 15:14:39.143 F558AB90 verbose 'VMotionSrc (1301685441034055)'] Migration changed state from MIGRATING to UNREGISTERING

hostd-11.log:[2011-04-01 15:14:39.143 F558AB90 verbose 'VMotionSrc (1301685441034055)'] Finish called

hostd-11.log:[2011-04-01 15:14:41.232 F558AB90 verbose 'VMotionSrc (1301685441034055)'] Migration changed state from UNREGISTERING to DONE

hostd-11.log:[2011-04-01 15:14:41.390 F558AB90 verbose 'VMotionSrc (1301685441034055)'] JrnlEnd: Wrote active=0

hostd-11.log:[2011-04-01 15:14:41.416 F558AB90 verbose 'VMotionSrc (1301685441034055)'] JrnlEnd: Finished journal

hostd-11.log:[2011-04-01 15:14:41.416 F558AB90 verbose 'VMotionSrc (1301685441034055)'] [JrnlFilePersistenceProvider::DeleteJournal] Deleting /var/lib/vmware/hostd/journal/1301685274.0.

hostd-11.log:[2011-04-01 15:14:41.416 F558AB90 verbose 'VMotionSrc (1301685441034055)'] JrnlDelete: Deleted journal

hostd-11.log:[2011-04-01 15:14:41.416 F558AB90 info 'VMotionSrc (1301685441034055)'] CompleteOp: Vmotion task succeeded with result:

hostd-11.log:[2011-04-01 15:14:42.468 F5A5AB90 info 'VMotion' opID=F6FC49D5-000007E6-38] CompleteSource [1301685441034055]

“migrateType=MIGRATE_TYPE_VMOTION” Once again, it shows the migration type.

“JrnlPutWid: Wrote wid=4868

” Create a Journal world ID for this VM.

“Migration changed state from BEGIN to MIGRATING

” We passed the first 10%, now we are moving the memory from one host to another

The normal VMotion process is like this:

• 00% - 05% - copy VM files (and initial pool switch if necessary)

• 05% - 10% - copy or reconfigure VM config file

• 10% - 95% - progress reported by destination

• 95% - 100% - any other time needed by source, plus final sync

Storage VMotion process:

• 00% - 00% - copy VM files (and initial pool switch if necessary)

• 00% - 01% - copy VM config file

• 01% - 10% - progress reported by destination

• 10% - 10% - any other time needed by source, plus sync

• 10% - 90% - copy disks

• 90% - 99% - reparent/commit disks

• 99% - 100% - delete source disks, plus final sync

“VMotionCmdCb [1301685441034055] 'start': done

” We are now at 95% Which the memory is moved over to the other host.

“ResolveCb: VMX reports needsUnregister = true for migrateType MIGRATE_TYPE_VMOTION

” Now we need to unregister the VM from this host.

“ResolveCb: Succeeded ” Resolve the status of the VMotion operation when the VMX reports that it has completed. And here the VMX file reported success. 

“Migration changed state from MIGRATING to UNREGISTERING

” We are now in the unregister process.

“'VMotionSrc (1301685441034055)'] Migration changed state from UNREGISTERING to DONE

” The VM is now unregistered from the source host.

“JrnlDelete: Deleted journal

” The journal is ended and deleted.

“CompleteOp: Vmotion task succeeded with result” The VM was successfully moved away from the source host.

On The Destination Host:

[2011-04-01 19:17:20.154 6AF47B90 verbose 'VMotionDst (1301685441034055)' opID=F6FC49D5-000007E6-8b] JrnlBegin: VM objID=672 srcIp=10.21.51.137 migrateType=MIGRATE_TYPE_VMOTION

[2011-04-01 19:17:20.168 6AF47B90 info 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx' opID=F6FC49D5-000007E6-8b] VMotionPrepare (1301685441034055): Sending 'from' srcIp=10.21.51.137 dstIp=10.21.53.102, type=1, encrypted=false, remoteThumbprint=

[2011-04-01 19:17:20.169 6AF47B90 info 'VMotionDst (1301685441034055)' opID=F6FC49D5-000007E6-8b] Initiate: Waiting for WID

[2011-04-01 19:17:20.654 6AF47B90 verbose 'VMotionDst (1301685441034055)' opID=F6FC49D5-000007E6-8b] JrnlPutWid: Wrote wid=6947903

[2011-04-01 19:17:20.654 6AF47B90 info 'VMotionDst (1301685441034055)' opID=F6FC49D5-000007E6-8b] Initiate: Got WID 6947903

[2011-04-01 19:17:20.654 6AF47B90 verbose 'VMotionDst (1301685441034055)' opID=F6FC49D5-000007E6-8b] Migration changed state from BEGIN to MIGRATING

[2011-04-01 19:17:20.654 6A625B90 verbose 'vm:/vmfs/volumes/4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx'] VMotionCmdCb [1301685441034055] 'from': done

[2011-04-01 19:17:21.693 6A694B90 info 'VMotionDst (1301685441034055)'] ResolveCb: VMX reports needsUnregister = false for migrateType MIGRATE_TYPE_VMOTION

[2011-04-01 19:17:21.693 6A694B90 info 'VMotionDst (1301685441034055)'] ResolveCb: Succeeded

[2011-04-01 19:17:21.693 6A694B90 verbose 'VMotionDst (1301685441034055)'] Migration changed state from MIGRATING to DONE

[2011-04-01 19:17:21.693 6A694B90 verbose 'VMotionDst (1301685441034055)'] Finish called

[2011-04-01 19:17:21.693 6A694B90 verbose 'VMotionDst (1301685441034055)'] Set dest task result vm downtime to 226017

[2011-04-01 19:17:21.693 6A694B90 verbose 'VMotionDst (1301685441034055)'] Set dest task result stuntime 0

[2011-04-01 19:17:21.694 6A694B90 verbose 'VMotionDst (1301685441034055)'] Set dest task result pageSrcTime to 0

[2011-04-01 19:17:21.694 6A694B90 verbose 'VMotionDst (1301685441034055)'] Set dest task result remotePageFaults 0

[2011-04-01 19:17:21.734 6A694B90 verbose 'VMotionDst (1301685441034055)'] JrnlEnd: Wrote active=0

[2011-04-01 19:17:21.738 6A694B90 verbose 'VMotionDst (1301685441034055)'] JrnlEnd: Finished journal

[2011-04-01 19:17:21.738 6A694B90 verbose 'VMotionDst (1301685441034055)'] [JrnlFilePersistenceProvider::DeleteJournal] Deleting /var/lib/vmware/hostd/journal/1301685439.0.

[2011-04-01 19:17:21.739 6A694B90 verbose 'VMotionDst (1301685441034055)'] JrnlDelete: Deleted journal

[2011-04-01 19:17:21.739 6A694B90 info 'VMotionDst (1301685441034055)'] CompleteOp: Vmotion task succeeded with result: (vim.host.VMotionManager.VMotionResult) {

[2011-04-01 19:17:32.842 6ACFEB90 info 'VMotion' opID=F6FC49D5-000007E6-45] CompleteDestination [1301685441034055]

We will skip the duplications.

“ResolveCb: VMX reports needsUnregister = false for migrateType MIGRATE_TYPE_VMOTION

” Here, since this is destination host, which the VM will be running, that's why needsUnregister = false.

“Set dest task result vm downtime to 226017

” This is the “down” time for the VM during VMotion (You will not see this in versions before 4.1, but I will show you where you can find the information later) The down time is in microsecond, so for my VMotion test, the down time was 0.226 seconds.

“ Set dest task result vm downtime to 226017

” “ Set dest task result pageSrcTime to 0

” “Set dest task result remotePageFaults 0

” Because my test VM has nothing in it, so the page in time was really fast. You may see different numbers depends on how busy is the VM, but nothing to be alert of if you see something different.

“CompleteOp: Vmotion task succeeded with result: (vim.host.VMotionManager.VMotionResult)” “ CompleteDestination” VMotion process finished on destination host.

VMware.log files:

You may see many vmware.log files under the VM directory, use the same VMotion ID to find which logs is useful to us. As summing you are in the VM's directory already

“grep -i 1301685441034055 vmware* | less” Here is the output

vmware-1.log:Apr 01 15:14:34.205: vmx| Received migrate 'to' request for mid id 1301685441034055, src ip <10.21.51.137>, dst ip <10.21.53.102>.

vmware-1.log:Apr 01 15:14:34.230: vmx| MigrateSetInfo: state=1 srcIp=<10.21.51.137> dstIp=<10.21.53.102> mid=1301685441034055 uuid=34353939-3630-4d58-5138-353141344d36 priority=high

vmware-1.log:Apr 01 15:14:35.244: vmx| Received migrate 'start' request for mig id 1301685441034055, dest world id 6947903.

vmware-1.log:Apr 01 15:14:35.691: vmx| Migrate_Open: Migrating to <10.21.53.102> with migration id 1301685441034055

vmware-2.log:Apr 01 19:17:20.422: vmx| Received migrate 'from' request for mid id 1301685441034055, src ip <10.21.51.137>.

vmware-2.log:Apr 01 19:17:20.423: vmx| MigrateSetInfo: state=7 srcIp=<10.21.51.137> dstIp=<10.21.53.102> mid=1301685441034055 uuid=34353939-3630-4d58-5139-30334132594b priority=high

vmware-2.log:Apr 01 19:17:21.369: vmx| Migrate_Open: Restoring from <10.21.51.137> with migration id 1301685441034055

vmware-2.log:Apr 01 19:17:21.472: vmx| Migrate_Open: Restoring from <10.21.51.137> with migration id 1301685441034055

We can see there are two logs that may help us vmware-1.log and vmware-2.log. It shows the information we already know from hostd log. Now let's take a closer look at the vmware.log file.

“less vmware-1.log” and find the starting point “/1301685441034055” this should lead us to the starting point

Apr 01 15:14:34.205: vmx| Received migrate 'to' request for mid id 1301685441034055, src ip <10.21.51.137>, dst ip <10.21.53.102>.

Apr 01 15:14:34.230: vmx| MigrateSetInfo: state=1 srcIp=<10.21.51.137> dstIp=<10.21.53.102> mid=1301685441034055 uuid=34353939-3630-4d58-5138-353141344d36 priority=high

Apr 01 15:14:34.230: vmx| MigrateSetState: Transitioning from state 0 to 1.

Apr 01 15:14:35.244: vmx| VMXVmdbCbVmVmxMigrate: Got SET callback for /vm/#_VMX/vmx/migrateState/cmd/##1_72/op/=start

Apr 01 15:14:35.244: vmx| VMXVmdbVmVmxMigrateGetStartParam: mid=49fe042527747 dstwid=6947903

Apr 01 15:14:35.244: vmx| Received migrate 'start' request for mig id 1301685441034055, dest world id 6947903.

The VMotion process will wait for the destination world ID before start to migrate.

Apr 01 15:14:35.534: vcpu-0| Migrate: Preparing to suspend.

Apr 01 15:14:35.534: vcpu-0| CPT current = 0, requesting 1

Apr 01 15:14:35.534: vcpu-0| Migrate: VM stun started, waiting 100 seconds for go/no-go message.

By default, the VMotion time out set 100 seconds, if the destination host's VMotion network cannot be reached more than 100 seconds, the VMotion will fail.

Apr 01 15:14:35.930: vmx| Migrate: Powering off

Apr 01 15:14:35.930: vmx| Stopping VCPU threads...

Apr 01 15:14:35.931: vcpu-0| VMMon_WaitForExit: vcpu-0: worldID=4868

Apr 01 15:14:35.931: vcpu-1| VMMon_WaitForExit: vcpu-1: worldID=4870

Apr 01 15:14:37.094: mks| Ending MKSRole pseudocalls, state was 1

Apr 01 15:14:37.094: mks| Async MKS thread is exiting

Apr 01 15:14:37.094: vmx| Vix: [104867 mainDispatch.c:907]: VMAutomation_PowerOff: Powering off.

Apr 01 15:14:37.118: vmx| VMXVmdb_SetToolsVersionState: status value set to 'ok'

Apr 01 15:14:37.118: vmx| Migrate: cleaning up migration state.

Apr 01 15:14:37.118: vmx| MigrateSetState: Transitioning from state 5 to 0.

Apr 01 15:14:37.120: vmx| MKSHostOps_HideCursor before defineCursor!

Apr 01 15:14:37.125: vmx| Virtual Device for scsi0:0 was already successfully destroyed

Apr 01 15:14:37.150: vmx| MKS local poweroff

We should able to tell from the logs, after the migration, there are some clean up steps. Stopping the VCPU threads, and power off the MKS (mouse, keyboard, screen)

Apr 01 15:14:39.046: vmx| VMX idle exit

Apr 01 15:14:39.055: vmx| VMIOP: Exit

Apr 01 15:14:39.056: vmx| Vix: [104867 mainDispatch.c:652]: VMAutomation_LateShutdown()

Apr 01 15:14:39.056: vmx| Vix: [104867 mainDispatch.c:602]: VMAutomationCloseListenerSocket. Closing listener socket.

Apr 01 15:14:39.065: vmx| Flushing VMX VMDB connections

Apr 01 15:14:39.075: vmx| VMX exit (0).

Apr 01 15:14:39.075: vmx| AIOMGR-S : stat o=2 r=6 w=0 i=0 br=98304 bw=0

Apr 01 15:14:39.075: vmx| VMX has left the building: 0.

More clean up updating VMDB, and at the end “VMX has left the building: 0.

” This is not a bad message. You will see this for every VMotion process. Just show the VMotion completed.

VPXD logs:

The logs are located in %ALLUSERSPROFILE%\Application Data\VMware\VMware VirtualCenter\Logs, which translates to C:\Documents and Settings\All Users\Application Data\VMware\VirtualCenter\logs in Windows 2003 and C:\ProgramData\VMware\VMware VirtualCenter\Logs in Windows 2008.

We do the same grep with vpxd-xx.log

“grep -i 1301685441034055 vpxd*.log | less” Here we got the vCenter information for this VMotion process

vpxd-83.log:[2011-04-01 15:17:21.040 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) VMotion started

vpxd-83.log:[2011-04-01 15:17:21.040 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) VM: Vmotion-test (/vpx/vm/#369/)

vpxd-83.log:[2011-04-01 15:17:21.040 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) host: bs-bcs-h137.bsl.vmware.com (/vpx/host/#261/) -> bs-bcs-h138.bsl.vmware.com (/vpx/host/#227/)

vpxd-83.log:[2011-04-01 15:17:21.040 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) pool: Resources (/vpx/resgroup/#27/) -> Resources (/vpx/resgroup/#27/)

vpxd-83.log:[2011-04-01 15:17:21.483 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) config: sanfs://vmfs_uuid:4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx -> sanfs://vmfs_uuid:4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx

vpxd-83.log:[2011-04-01 15:17:21.483 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) vmotion IP: 10.21.51.137 -> 10.21.53.102

vpxd-83.log:[2011-04-01 15:17:21.483 03364 info 'App' opID=F6FC49D5-000007E6] [MIGRATE] (1301685441034055) mgmt IP: 10.21.49.137 -> 10.21.49.138

“MIGRATE] (1301685441034055) VM: Vmotion-test (/vpx/vm/#369/)

” Here we can see the virtual machine ID in vCenter database (#369)

“host: bs-bcs-h137.bsl.vmware.com (/vpx/host/#261/) -> bs-bcs-h138.bsl.vmware.com (/vpx/host/#227/)

”

In vCenter 4.1 the log is nice enough to give you the host ID in vCenter database. In our case, bs-bcs-h137 (#261) is the source and bs-bcs-h138 (#227) is the destination

“config: sanfs://vmfs_uuid:4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx -> sanfs://vmfs_uuid:4d6579ec-23f981cb-465c-00237da0cfee/Vmotion-test/Vmotion-test.vmx

”

Once again we can see this is a VMotion process, since the path to the configuration file did not change. Storage VMotion will have different path.

What Else Is Useful?

ESX/ESXi hosts will keep a list of VMotion until a reboot occur. You can find the list under /proc

ESX: /proc/vmware/migration/history

“less -RS /proc/vmware/migration/history”

id status | Total PreCopy Quiesce CptXfer CptLoad PageIn DownTime

1301685636815010 (#3) vm 4881: Ok migrating to <10.21.51.137> | 3.609013 1.500298 N/A N/A N/A N/A N/A

1301685636815010 (#2) vm 4894: Ok migrating from <10.21.51.137> | 3.890556 N/A N/A N/A 0.281297 N/A N/A

1301685587877584 (#1) vm 4881: Ok migrating from <10.21.53.102> | 1.554031 0.755715 N/A 0.133118 0.368116 0.001499 0.503789

1301685441034055 (#0) vm 4868: Ok migrating to <10.21.53.102> | 0.666448 0.277901 0.159037 0.037974 N/A 0.005203 N/A

The part we are interested in is the last column, which is the down time of the VM during VMotion. So why we are seeing “N/A” here? Because this is the source host, it will not know the down time of the migration. This is another way to find out which one is the source host and which one is the destination host. If you look at the line above (in bold) you can see the downtime for that VMotion was 0.5 seconds

ESXi: /proc/migration/rawTS