Johnny's Random Tips

VMware logs (Operation: VM creation and modification)

noreply@blogger.com (Unknown) — Tue, 12 Apr 2011 17:55:00 +0000

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

Changed memory from size
Change vCPU count
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.

VMware logs (VMotion)

noreply@blogger.com (Unknown) — Thu, 07 Apr 2011 21:29:00 +0000

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:

All we need is the name of the VMotioned VM (in this example “vmotion-test”)
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: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: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

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

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:

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

How to find the VM's ip address from ESX host?

noreply@blogger.com (Unknown) — Thu, 09 Dec 2010 22:51:00 +0000

Now, you are not suppose to find the VM's IP address from the host. But if you really want to. Here is the steps.
We talked about the use of "ft-stats" and "vmware-vimdump". so we can use those two command together to find the guest IP address that we are looking for

1. Let's find the VM's name by using "ft-stats -lv" (let's use BCS-VC40-1)
2. Now we can use "vmware-vimdump | less" and search for hostname (/hostname)

What ft-stats gives you even you don't have a ft VM?

noreply@blogger.com (Unknown) — Thu, 09 Dec 2010 22:35:00 +0000

Not many people are running FT VMs. and even less people know about the ft-stats command. Now if you don't use a FT vm what this command can give you?

Answer: a fast report on the vmid and path to your VMs

"ft-stats -lv"
Now Why the state is set as "Not Configured"? Because none of the VM was configured as a FT VM

vmware-vimdump. You now know too much

noreply@blogger.com (Unknown) — Wed, 01 Dec 2010 19:40:00 +0000

This tip is just for Scott. We had a conference meeting, Scott requested an update on my blog. I save the best for you!

We talked about collecting information from vCenter. What about ESX? the "vmware-vimdump" command will print out what vmkernel knows about the system it's running on, which is EVERYTHING!

Let's show some examples:

How do I know which path I'm using to connect to the storage?

How about I want to see the policy used?

What about the storage team ask me for the WWP?

Ok enough on storage, what about virtual switch?

You got the idea. Now you know too much!

Fast way to collect vCenter information

noreply@blogger.com (Unknown) — Tue, 05 Oct 2010 19:26:00 +0000

From time to time, you may want to know how many ESX servers in your vCenter, what are their build levels, how many VMs are registered, how many powered on, etc. There is a fast way to give you all those information. All you need to look is the vpxd-profiler.log on your vCenter server. This log is in the same directory as your vpxd.log file

for example on a Windows 2008 server the log is at
\Users\All Users\VMware\VMware VirtualCenter\Logs\

What you need look for is the "InventoryStats". You are going to see something like this
those logs update every 5 minutes, you can show your boss, you are on top of things.

Note: this log can be large enough to hung notepad or wordpad. I do suggest you to move to a Linux to read it.

How to setup sudo with active directory accounts in ESX 4.1

noreply@blogger.com (Unknown) — Wed, 15 Sep 2010 15:47:00 +0000

Customer using Active directory integration function in 4.1. the user logged in is DOMAIN/user_name, and since the user is not in the sudoer file, they can not view logs

You can add AD groups into sudoer file

for example, you have a domain called "MYDOMAIN" and the group call "ESX Admins" (or MYDOMAIN\ESX Admins)

you add this under group %wheel:

%MYDOMAIN//ESX/ Admins ALL=(ALL) ALL

Note: if it did not prompt for password, you may need to restart the server, and everything will work from here)

Change virtaul hardware version from 7 back to 4

noreply@blogger.com (Unknown) — Tue, 14 Sep 2010 21:51:00 +0000

Some times customers may want to change the virtual hardware version back from 7 to 4, there is a way to do this

the first is the VM's vmx file
the part you need to change is:

virtualHW.version = "7" you change this to
virtualHW.version = "4"

No need to change config.version = "8" since ESX 3.x already using this version

Next what you need to change is:
scsi0.virtualDev = "lsisas1068"

this is default for version 7 of the virtual hardware. Version 4 will not understand this virtual controller

You can change to
scsi0.virtualDev = "lsilogic"

The next step is change the .vmdk file of the VM (pointer file)
ddb.virtualHWVersion = "7"

you need to change this to
ddb.virtualHWVersion = "4"

and after that, you should able to power on the VM as hardware version 4

(please note, this is not supported by VMware)

vCenter and SQL 2008

noreply@blogger.com (Unknown) — Tue, 25 May 2010 01:58:00 +0000

I was setting up the BCS team lab, and one of the steps is to install a new vCenter 4.0 U1 server with a SQL 2008 back end. During the installation, the installer complained about port 80 was in use. From the past experience, I quickly checked if IIS is running on the server. There was not.

A quick “netstat –a” shows port 80 is listening to any incoming request. To find what service was using the port you can use “netstat –bna” the result shows the service that using the port was “SQLserver.exe” Wow, since when SQL server starts to use port 80? I took a look at SQL server configuration manager. There a list of services. One that came into the spot light was “SQL server reporting service” I recalls on SQL 2005 when Microsoft introduces the reporting service, IIS was a required service. Since IIS is not running, how did reporting service start itself? Right after I turn off SQL reporting service I can move the installation forward. (So the reporting service was the one holding port 80). Did a quick research on SQL 2008’s reporting service, here is the reason:

“Reporting Services no longer depends on IIS to provide access to the SOAP endpoint. URLs no longer include Web sites in IIS. Reporting Services uses HTTP.SYS directly to listen for requests on a specific port that you define for report server URLs.”

In case you need to use SQL 2008 reporting service on the same server where vCenter installed, keep in mind this could prevent vCenter from starting even it already installed. Make sure you either change the port for the reporting service or your vCenter’s port to avoid any issues

“A general system error occurred” when try to add a ESX 3.5 server into vCenter 4.0

noreply@blogger.com (Unknown) — Thu, 20 May 2010 21:41:00 +0000

Since most of you are upgrading form VI 3 to vSphere, I'd like to share with you on this issue I worked with one of the BCS customers.

I received this call when customer failed to add their ESX 3.5 U4 host to their new vCenter 4.0 server. The error message they hit was “A general system error occurred” (Always nice to see a message does not give any direction). So for the first step, we tested viclient connect directly to ESX server and that worked for us. Normally, that means hostd is working (This is actually the key issue). So we focused on vpxa.
from the vpxa logs:

[2010-05-20 11:29:01.793 server_name error 'App'] [VpxaHalCnxHostagent] caught InvalidProperty::Exception - filter creati
on failed, temptorary versioning workaround
[2010-05-20 11:29:01.820 server_name verbose 'App'] [VpxVmomi] Invoke error: vpxapi.VpxaService.login session: 5238dc5c-bd8b-fcdd-f450-ab23a826a413 Throw: vmodl.fault.SystemError

So we tried many things and nothing worked... I then want to see what hostd report during that time

Here is the hostd log:
[2010-05-20 13:04:36.281 'App' 52411312 error] AdapterServer caught unexpected exception: vector::reserve
[2010-05-20 13:04:36.281 'App' 52411312 trivia] Completing task haTask vim.event.EventManager.createColle
ctor-389 as 3
[2010-05-20 13:04:36.281 'PropertyProvider' 52411312 trivia] RecordOp 2: info, haTask--vim.event.EventMana
ger.createCollector-389
[2010-05-20 13:04:36.281 'Vmomi' 52411312 info] Activation [N5Vmomi10ActivationE:0x9fd9780] : Invoke done
[createCollector] on [vim.event.EventManager:ha-eventmgr]
[2010-05-20 13:04:36.281 'Vmomi' 52411312 info] Throw vmodl.fault.SystemError
[2010-05-20 13:04:36.281 'Vmomi' 52411312 info] Result:
(vmodl.fault.SystemError) {
dynamicType = ,
reason = "",
msg = ""
}
[2010-05-20 13:04:36.325 'Proxysvc Req00153' 18353072 trivia] Client HTTP stream read error
[2010-05-20 13:04:36.325 'Proxysvc Req00153' 18353072 trivia] Closed

The error message "AdapterServer caught unexpected exception: vector::reserve" lead me to a problem report. However, the report had no vCenter involved. I asked customer to bring up the ESX server via viclient, click on any virtual machine, then click on "event" tab, sure enough, it hits “A general system error occurred” message, just like the problem report. The good news is patch 19 fixed this issue. We installed patch 19 ( ESX350-200912401-BG - PATCH ) and able to add those ESX server to the new vCenter 4.0.

If you already have patch 19 installed, you should not have this issue. If you don't, then put this on the side, it would be handy in case you need it.

Case study: Cannot insert duplicate key in object 'dbo.VPX_IP_ADDRESS'

noreply@blogger.com (Unknown) — Fri, 12 Mar 2010 21:27:00 +0000

This is a case I worked with one of the BCS customers on their vCenter issue.

Problem: vCenter starts, but soon after, it will crash on it's own. From the log we saw:

[2010-03-12 11:44:18.178 'App' 4500 error] An unrecoverable problem has occurred, stopping the VMware VirtualCenter service. Check database connectivity before restarting. Error: Error[VdbODBCError] (-1) "ODBC error: (23000) - [Microsoft][SQL Native Client][SQL Server]Violation of PRIMARY KEY constraint 'PK_VPX_IP_ADDRESS'. Cannot insert duplicate key in object 'dbo.VPX_IP_ADDRESS'." is returned when executing SQL statement "INSERT INTO VPX_IP_ADDRESS (ENTITY_ID, DEVICE_ID, IP_ADDRESS) VALUES (?, ?, ?)"
[2010-03-12 11:44:18.178 'App' 4500 verbose] Backtrace:
[2010-03-12 11:44:18.178 'App' 4500 info] Forcing shutdown of VMware VirtualCenter now

So we know the cause of this problem was something try to insert into the table dbo.VPX_IP_ADDRESS. Note the thread ID is 4500, so we can trace back to the problem virtual machine or host. In our case, this was a VM

[2010-03-12 11:44:17.865 'App' 4500 verbose] [VpxdMoEventManager] Event[2567833]: SOME_VM on SOME_ESX_HOST in SOME_CLUSTER is powered on

Now we could:

Shut down the vm
Remove the host from vCenter
Stop hostd/vpxa service(s) on that ESX server
Start vCenter and confirm everything is working as designed
Power down the VM, unregister it
Add the host back in vCenter
Check database to make sure the VM is not there
Register the VM

Now, please don't ask me why one VM can bring down vCenter, it would be off topic :)

Try this before look for the backup

noreply@blogger.com (Unknown) — Tue, 29 Dec 2009 02:28:00 +0000

I was working with one of the BCS customer on a case. The customer was originally planing to extend a Windows 2003 VM's OS disk to a larger size. However, after extend the VMDK files with VI client, and extend the NTFS inside Windows (Since this was a Windows 2003 guest, the customer needs to use a helper VM to do the job) after failed to power on the VM, the customer found a shocking fact: there was a snapshot. Then the customer tried to shrink the VMDK file back to the original size... and number of other things was also tried. So when we start to work on this issue, the VMDK file was broken in many different ways alone with the snapshot. To make the thing worse the last and only backup was created right after the extension of the VMDK file.

The end story was, we did recover all the data on the VMDK, the VMDK was not good enough to power on as a boot disk, but that was good enough to save the day. Here was how we did it:

First, list the size of the flat file by using "ls -l" in the VM directory
Keep in mind the number we need is the size of the flat file. In my test set up it's 8589934592. We need this number later. Now we need open the VMDK file (The pointer). In my case snap_test.vmdk:
Note, we need the CID and the RW number.
The RW number is the flat disk size divide by 512.
in my case 8589934592 / 512 = 16777216. If this number is wrong, you will not able to power on the VM. (So first we fix this part).

Now let's open the snapshot VMDK file. snap-test-000001.vmdk

In this file the "parentCID" should be the same as the snap-test.vmdk's CID. In my case 4cc5f033. If this is wrong, then the VM will not power on. (We fixed this one as well). The RW size would be also wrong, since it will only record the original size. Change this to the same size as the parent RW (16777216).
Now we need a helper VM to attach this disk as a second VMDK file (Not boot disk). When the OS boots up it will automatically run check disk against the VMDK and auto fix the errors. Now you should able to mount the disk inside the helper VM and copy over the data.

What "memory usage" in vCenter 4.0 really shows

noreply@blogger.com (Unknown) — Thu, 17 Dec 2009 20:55:00 +0000

In vCenter 4.0 we now have some easy to used monitor tools for ESX server performance. One of the chart is the memory usage
This usages is NOT the active memory that is currently used by the ESX server or the VM. So when you see very high usage, don't be panic.
In fact, this chart shows the total "Consumed Host Memory" by all the VMs running on the host.
As we can see from the graph the "Consumed Host memory" is 2277.00MB and the "Active Guest Memory" is only 122.00MB. Why a big different?

This is by design, the "Consumed Host Memory" shows the highest memory used by that VM.
OS such like Windows will touch all the memory assigned to it during start up, so most likely you will see the consumed memory is close or little more then the memory assigned to the VM (Overhead to power on the VM is also added here). ESX server will NOT take back the memory if there is no resource contention on the server. The reason is, once the VM need more memory it can access them faster than send the request to vmkernel again.
If you want to know the real time memory usage you can look into the advanced chart to find it out.

Increasing hosts connection pool

noreply@blogger.com (Unknown) — Wed, 02 Dec 2009 14:58:00 +0000

Note: This is tip is based on communications between engineering and myself. In most cases there is no need to make any change. This is just for you to know. (This also only based on VI3, not sure if there are changes on vSphere)

Sometimes we see ESX hosts disconnected from vCenter. from the vpxa log files:

['App' 7644 error] [VpxdVmomi] Got vmacore exception: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.

This error is common in an environment which hosts are under load.
There could be multiple causes for this kind of connection request failure:

1. Network glitch
2. proxy server on hostd is not able to respond the request due to stress.
3. hostd process is busy or crashed at the time the request arrives.

Now, vCenter has a host connection pool, it will store idle connections between ESX server and vCenter. So when there is a need to connect the server, vCenter will not need to create the connections all over again (Which in some cases we will hit the above issues). The default connection size is set at 20. you can increase this (for example to 50)

You need to add to vpxd.cfg files:

Personally, I believe this will help for a large set-up by reducing the connection requests. please note, the active connection is not put into this pool, so in most cases 20 is good enough.

Two fast ways to locate your console root on ESX 4.x

noreply@blogger.com (Unknown) — Mon, 30 Nov 2009 02:18:00 +0000

vShpere change the way to store the console OS. It's now running on a VMDK file. It's a real virtual machine. There are times you may want to know where is your root VMDK file for your console OS. Here is two fast ways to locate it.

1. From /proc/vmware: "rootFsVMDKPath" under /proc/vmware will give you the location of your root VMDK

2. Use of "vsd" command: You can use "vsd -g" to list your root VMDK file.

How to clean event from vCenter database

noreply@blogger.com (Unknown) — Mon, 23 Nov 2009 05:04:00 +0000

Please keep in mind, clean up event is not recommended, do it ONLY when you are running out of space because both vpx_event_arg and vpx_event tables are filled with many GB of data.
Always shut down vCenter service before you do anything with the database.
You can check the space usage by each table:

********************************************
use "name_of_the_vcdb"
CREATE TABLE #TemptableforspaceUsed
(name SYSNAME,
rows bigINT,
reserved VARCHAR(20),
data VARCHAR(20),
index_size VARCHAR(20),
unused VARCHAR(20))
GO
INSERT #TemptableforspaceUsed
EXEC sp_MSforeachtable 'sp_spaceused "?"'

select *
from #TemptableforspaceUsed

drop table #TemptableforspaceUsed

******************************************

You can now clean the event tables.

use "name_of_the_vcdb"
truncate table vpx_event_arg;
delete from vpx_event;

Because there are foreign keys inside vpx_event, you can not truncate the data inside. You must remove those data before start the vCenter service, the service might not start if there are data that is missing link. Please also keep in mind, "delete" will always save a copy of the change, so you will see increase in transaction logs, sometimes it can be huge, depends on the amount of data you have.

What "vmware -v" really shows you

noreply@blogger.com (Unknown) — Mon, 16 Nov 2009 03:09:00 +0000

Many of us believe "vmware -v" will show you the current version of your ESX server (With all the patches applied). This is actually not true. This command only shows the version of a component.
In ESX 3.x "vmware -v" will show you the version number of "VMware-esx-vmx"
And in ESX 4.x "vmware -v" will show you the version of "vmware-esx-vmware-release"

In addition, vCenter will show the version of your "vmware-hostd"
Please keep in mind those numbers can all be different.

More information about your storage

noreply@blogger.com (Unknown) — Mon, 26 Oct 2009 02:29:00 +0000

You always want to know more about your servers, your network settings your storage options. "esxcfg-info" is the best place to dig things up. You want to know more about your storage? Type:
"esxcfg-info -s | less -RS"
You can check your VMFS alignment here, when the Starting sector set as 128 you know your VMFS is aligned correctly (VMFS aligned on 64KB boundary)
You can map the LUN back to your service console device. It will also show you the type of the file system on the LUN. In this case fb is VMFS

Display VMkernel's devices' drivers

noreply@blogger.com (Unknown) — Mon, 26 Oct 2009 02:11:00 +0000

There are times we want to find out what drivers are configured to load up when VMkernel boots up.
You can find this out by typing:
"esxcfg-modele -q"
You can also check what drivers are currently loaded:
" esxcfg-modele -l"

How to read your VMFS datastore information

noreply@blogger.com (Unknown) — Mon, 26 Oct 2009 01:55:00 +0000

Every time when you create a VMFS datastore, a copy of VMFS metadata will write to your LUN with following information:

Block size
Number of extents
Volume capacity
VMFS version
Label
VMFS UUID

You can use "vmkfstools -P -h /vmfs/volumes/LUN_Lable" to query the file system information

Note: information based on Infrastructure 3 DSA Manual

Get your own vCenter table and relations on MS Visio

noreply@blogger.com (Unknown) — Tue, 06 Oct 2009 18:42:00 +0000

It will take only few clicks to get your vCenter's table and relations in a Visio file. (I'm using visio 2007 I think the older one will work the same way as well) (Tested on visio 2007 SQL 2005 with vCenter 4.0)

Open your Visio 2007 --> File-->New --> Software and Database --> Database Model Diagram (Metric). This will open a new file for you.
Now click on Database --> reverse Engineer

Pick "Microsoft SQL Server" from Installed Visio drivers
Now click on "New --> System Data Source (Applies to this machine only) --> Next --> Pick "SQL Server" for the data source driver --> Next --> Finish

Now you will see the New data Source box
Give it a name, and the name/ip of your vCenter database (The normal way you setup your ODBC to your vCenter database). Make sure your change your database to your vCenter database.
Now you should see your ODBC connection that you just created --> click Next. It will ask for the connection password. Type in and click OK.
You might not want views or stored Procedures. so you can uncheck them.
Click Next and select all tables
Pick "Yes, add the shapes to the current page." few more clicks you should have your vCenter tables in your Visio file.

Did my ESX host's vmkernel boot up fine?

noreply@blogger.com (Unknown) — Mon, 21 Sep 2009 03:37:00 +0000

You can do a quick check on your ESX server right after it powered on. This log is a little different from what we know about (/var/log/messages). It also called messages log and it located at /var/log/initrdlogs/messages

tail -n 30 messages (check the last 30 line of the messages log)
We can see all VMkernel modules were loaded, and the system was "(forcing normal run)" Then we enter the service console booting process.

VMware ESX server logs - HA (2)

noreply@blogger.com (Unknown) — Mon, 21 Sep 2009 03:14:00 +0000

You can find out the members of the HA cluster from vmware-sites file. This file is located at /etc/opt/vmware/aam/ directory
[root@bs-bcs-h132 aam]# cat vmware-sites
FULLTIME_SITES_TID 00000030
+ 1:8042,8042,8043 bs-bcs-h132 vmware #FT_Agent_Port=8045
+ 2:8042,8042,8043 bs-bcs-h133 vmware

This file will list all members of the HA cluster and the port used. One thing it's helpful here is the P "+" sign. This means the hosts is currently in the HA cluster. If you see a "-" sign then the host is not connected to the HA cluster (either powered of or agent is not running)

NicInfo is a file in the same directory, this file will list all available NICs that HA cluster can see and use
[root@bs-bcs-h132 aam]# cat NicInfo
interface { ipaddress:10.21.49.132 subnetmask:255.255.252.0 }

How do I know if HV (Hardware Virtualization) is enabled on my host?

noreply@blogger.com (Unknown) — Mon, 21 Sep 2009 03:02:00 +0000

Normally when you hit a VMotion issue, or a 64 bit VM can not be power on from your 64 bit ESX server. You might asked to reboot the host and check the BIOS if HV (Hardware Virtualization) is enabled. You can check this without reboot your server
esxcfg-info | grep -i "hv support'

It will return a number between 0 to 3

0 is Not present
1 is Not supported
2 is disabled
3 is enabled

So in my case my server supports HV but is disabled under the BIOS.

Use vmware-devices.map to check if the device is supported

noreply@blogger.com (Unknown) — Mon, 21 Sep 2009 02:31:00 +0000

Sometimes we will get a hardware device just won't work on ESX server. There are many different reasons for that. We'd like to first find out if the device is supported and the right device driver is loaded. You can check the HCL online, but what about you are in front of the ESX server and it does not have Internet connection?
You can check the device against vmware-devices.map file. this file is located at /etc/vmware directory on your ESX server.
Let's use a NIC on my server as an example
esxcfg-nics -l
We can see the device is Broadcom Corporation NetXtreme II 5706 Gigabit Ethernet and the driver is bnx2.
Now we will chaeck this against vmware-devices.map file
grep -i "bnx2" vmware-devices.map
We can see the line "device,0x14e4,0x164a,nic,NetXtreme II 5706 Gigabit Ethernet,bnx2.o" We know the device is supported, and the loaded driver is also correct. Now we need look elsewhere for the problem.