Home > Blogs > VMware Support Insider > Category Archives: Tech Talk

Category Archives: Tech Talk

Deep-dive technical explorations

Troubleshooting VMs that power-off randomly

Nathan Small

Nathan Small

By Nathan Small

A customer opened a case with us because they experienced an issue where their VMs would simply power off randomly with the following message:

“Cannot power on vmserver0424 on esx-esx128.server.company.com. Could not open/create change tracking file”

This was not isolated to a group or type of VM. It didn’t matter which VM or which cluster. If they attempted to power on the VM immediately following the power off event they observed that sometimes the VM would power up again successfully however other times it would fail to do so until they waited a bit longer.

What I will show you in this blog post is how to troubleshoot this type of problem starting with the logs of the virtual machine, thru the ESX host logs, all the way to vCenter and beyond.

The first thing to do is to review the log file for a virtual machine that powers off in this fashion to try to understand what is causing this to occur. For this example we will take VM in the error message we received from vCenter: vmserver0424:

esx-esx128.server.company.com-2014-10-15–18.56/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmware-6.log

2014-10-05T01:27:02.354Z| vcpu-0| I120: AIOMGR: AIOMgr_OpenWithRetry: Descriptor file ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ locked (try 0)
2014-10-05T01:27:06.661Z| vcpu-0| I120: AIOMGR: AIOMgr_OpenWithRetry: Descriptor file ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ locked (try 1)
2014-10-05T01:27:10.973Z| vcpu-0| I120: AIOMGR: AIOMgr_OpenWithRetry: Descriptor file ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ locked (try 2)
2014-10-05T01:27:15.283Z| vcpu-0| I120: AIOMGR: AIOMgr_OpenWithRetry: Descriptor file ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ locked (try 3)
2014-10-05T01:27:19.693Z| vcpu-0| I120: AIOMGR: AIOMgr_OpenWithRetry: Descriptor file ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ locked (try 4)
2014-10-05T01:27:24.002Z| vcpu-0| I120: OBJLIB-FILEBE : FileBEOpen: can’t open ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ : Failed to lock the file (262146).
2014-10-05T01:27:24.002Z| vcpu-0| I120: DISKLIB-DSCPTR: DescriptorDetermineType: failed to open ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’: 2014-10-05T01:27:24.002Z| vcpu-0| I120: DISKLIB-LINK : “/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk” : failed to open (Failed to lock the file).
2014-10-05T01:27:24.002Z| vcpu-0| I120: DISKLIB-CHAIN : “/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk” : failed to open (Failed to lock the file).
2014-10-05T01:27:24.002Z| vcpu-0| I120: DISKLIB-LIB : Failed to open ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ with flags 0xa Failed to lock the file (16392).
2014-10-05T01:27:24.002Z| vcpu-0| I120: DISK: Cannot open disk “/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk”: Failed to lock the file (16392).
2014-10-05T01:27:24.002Z| vcpu-0| I120: Msg_Post: Error
2014-10-05T01:27:24.002Z| vcpu-0| I120: [msg.fileio.lock] Failed to lock the file
2014-10-05T01:27:24.002Z| vcpu-0| I120: [msg.disk.noBackEnd] Cannot open the disk ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ or one of the snapshot disks it depends on.
2014-10-05T01:27:24.002Z| vcpu-0| I120: —————————————-
2014-10-05T01:27:24.015Z| vcpu-0| I120: VMXNET3 user: Ethernet0 Driver Info: version = 833450 gosBits = 2 gosType = 2, gosVer = 24848, gosMisc = 212
2014-10-05T01:27:24.032Z| vcpu-0| I120: Msg_Post: Error
2014-10-05T01:27:24.032Z| vcpu-0| I120: [msg.checkpoint.continuesync.error] An operation required the virtual machine to quiesce and the virtual machine was unable to continue running.
2014-10-05T01:27:24.032Z| vcpu-0| I120: —————————————-
2014-10-05T01:27:24.039Z| vcpu-0| I120: Msg_Post: Error
2014-10-05T01:27:24.039Z| vcpu-0| I120: [msg.poweroff.commitOn] Performing disk cleanup. Cannot power off.
2014-10-05T01:27:24.039Z| vcpu-0| I120: —————————————-
2014-10-05T01:27:24.042Z| vcpu-0| I120: SnapshotVMXConsolidateOnlineCB: nextState = 2 uid 598
2014-10-05T01:27:24.042Z| vcpu-0| I120: Vix: [15205934 mainDispatch.c:3870]: VMAutomation_ReportPowerOpFinished: statevar=3, newAppState=1881, success=1 additionalError=0
2014-10-05T01:27:24.042Z| vcpu-0| I120: Msg_Post: Error
2014-10-05T01:27:24.042Z| vcpu-0| I120: [msg.snapshotVMX.consolidate.cptError] An error occurred while consolidating disks. The virtual machine will be powered off.
2014-10-05T01:27:24.042Z| vcpu-0| I120: —————————————-
2014-10-05T01:27:24.045Z| vcpu-0| I120: Vix: [15205934 vigorCommands.c:548]: VigorSnapshotManagerConsolidateCallback: snapshotErr = Unable to save snapshot file (13:0)
2014-10-05T01:27:24.045Z| vcpu-0| I120: SnapshotVMXConsolidateOnlineCB: Destroying thread 12
2014-10-05T01:27:24.045Z| vcpu-0| I120: Turning off snapshot info cache.
2014-10-05T01:27:24.047Z| vcpu-0| I120: Turning off snapshot disk cache.
2014-10-05T01:27:24.047Z| vcpu-0| I120: SnapshotVMXConsolidateOnlineCB: Done with consolidate
2014-10-05T01:27:24.047Z| vmx| I120: Stopping VCPU threads…

While there are numerous errors reported here they all stem from the fact that after 4 retries the VMM (Virtual Machine Monitor) is unable to open a file it had previous had access to. Since the VMM process is the only process that should be trying to access this file, this behavior is odd as it appears that something else has a lock on this file.

Next power on fails immediately:

2014-10-05T01:49:08.752Z| Worker#1| I120: AIOMGR: AIOMgr_OpenWithRetry: Descriptor file ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ locked (try 0)
2014-10-05T01:49:13.061Z| Worker#1| I120: AIOMGR: AIOMgr_OpenWithRetry: Descriptor file ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ locked (try 1)
2014-10-05T01:49:17.371Z| Worker#1| I120: AIOMGR: AIOMgr_OpenWithRetry: Descriptor file ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ locked (try 2)
2014-10-05T01:49:21.680Z| Worker#1| I120: AIOMGR: AIOMgr_OpenWithRetry: Descriptor file ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ locked (try 3)
2014-10-05T01:49:26.017Z| Worker#1| I120: AIOMGR: AIOMgr_OpenWithRetry: Descriptor file ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ locked (try 4)
2014-10-05T01:49:30.330Z| Worker#1| I120: OBJLIB-FILEBE : FileBEOpen: can’t open ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ : Failed to lock the file (262146).
2014-10-05T01:49:30.330Z| Worker#1| I120: DISKLIB-DSCPTR: DescriptorDetermineType: failed to open ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’: Failed to lock the file (40002)
2014-10-05T01:49:30.330Z| Worker#1| I120: DISKLIB-LINK : “/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk” : failed to open (Failed to lock the file).
2014-10-05T01:49:30.330Z| Worker#1| I120: DISKLIB-CHAIN : “/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk” : failed to open (Failed to lock the file).
2014-10-05T01:49:30.330Z| Worker#1| I120: DISKLIB-LIB : Failed to open ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ with flags 0xa Failed to lock the file (16392).
2014-10-05T01:49:30.330Z| Worker#1| I120: DISK: Cannot open disk “/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk”: Failed to lock the file (16392).
2014-10-05T01:49:30.330Z| Worker#1| I120: Msg_Post: Error
2014-10-05T01:49:30.330Z| Worker#1| I120: [msg.fileio.lock] Failed to lock the file
2014-10-05T01:49:30.330Z| Worker#1| I120: [msg.disk.noBackEnd] Cannot open the disk ‘/vmfs/volumes/529e2483-9ab715a8-afb5-0017a477208a/vmserver0424/vmserver0424_1-000002.vmdk’ or one of the snapshot disks it depends on.

Let’s take another VM as an example and find out why the VMM process is unable to open the file:

esx-esx134.server.company.com-2014-10-15–16.45/vmfs/volumes/52d076c8-5d86489a-880a-0017a477208a/vmserver0420/vmware-5.log

“2014-09-30T05:58:52.233Z| vcpu-0| I120: DISKLIB-LIB : Failed to open ‘/vmfs/volumes/52d076c8-5d86489a-880a-0017a477208a/vmserver0420/vmserver0420_1-000002.vmdk’ with flags 0xa Failed to lock the file (16392).”

When an attempt to access a file fails we may see corresponding events in /var/log/vmkernel.log. The above VM observed an inability to open the file @ 05:58:52 UTC:

/var/log/vmkernel.log:

2014-09-30T05:58:48.229Z cpu4:6413913)DLX: 3661: vol ‘Production-B-Datastore-14′, lock at 216551424: [Req mode 2] Checking liveness:
2014-09-30T05:58:48.229Z cpu4:6413913)[type 10c00001 offset 216551424 v 10376, hb offset 3284992
gen 5, mode 1, owner 52cb3769-8777cf73-e99e-0017a4772890 mtime 71328484
num 0 gblnum 0 gblgen 0 gblbrk 0]
2014-09-30T05:58:52.233Z cpu4:6413913)DLX: 4185: vol ‘Production-B-Datastore-14′, lock at 216551424: [Req mode: 2] Not free:
2014-09-30T05:58:52.233Z cpu4:6413913)[type 10c00001 offset 216551424 v 10376, hb offset 3284992
gen 5, mode 1, owner 52cb3769-8777cf73-e99e-0017a4772890 mtime 71328484
num 0 gblnum 0 gblgen 0 gblbrk 0]
2014-09-30T05:58:53.109Z cpu22:9723)DLX: 3661: vol ‘Production-B-Datastore-14′, lock at 216551424: [Req mode 1] Checking liveness:
2014-09-30T05:58:53.109Z cpu22:9723)[type 10c00001 offset 216551424 v 10376, hb offset 3284992
gen 5, mode 1, owner 52cb3769-8777cf73-e99e-0017a4772890 mtime 71328484
num 0 gblnum 0 gblgen 0 gblbrk 0]

These messages indicate that we are checking the liveness of a file lock on volume ‘Production-B-Datastore-14′ to see if it is stale and can be freed. 4 seconds later we can see that the lock has not been freed yet.

If we take the lock address “216551424″ and looks this up in the VMFS metadata then we would learn that the file in question is ‘vmserver0420_1-000002.vmdk’. More importantly we can see the UUID of the ESX host that has the open lock, which is owner ’52cb3769-8777cf73-e99e-0017a4772890′. In order to determine which physical ESX server this is you need to take that last part of the UUID which is the MAC address of the first vmkernel port (vmk0). We can do this across the ESX host log bundles with the following command:

grep “00:17:a4:77:28:90″ esx-esx*/commands/nicinfo*
esx-esx130.server.company.com-2014-10-15–16.50/commands/nicinfo.sh.txt:vmnic0 0000:004:00.0 be2net Up 10000 Full 00:17:a4:77:28:90 9000 Emulex Corporation HP FlexFabric 10Gb 2-port 554FLB Adapter

Unfortunately the vmkernel logs on this host do not go back far enough to see the timeframe in question however a very strange behavior observed in the /var/log/vmkernel.log:

2014-10-12T10:09:56.885Z cpu15:23596544)FS3: 1250: vol ‘PCI-Migration’, lock at 47935488: [Req mode: 1] Checking liveness:
2014-10-12T10:09:56.885Z cpu15:23596544)[type 10c00001 offset 47935488 v 1704, hb offset 3284992
gen 42893, mode 2, owner 00000000-00000000-0000-000000000000 mtime 662559
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-12T10:09:56.903Z cpu23:9880)FS3: 1250: vol ‘PCI-Migration’, lock at 55998464: [Req mode: 1] Checking liveness:
2014-10-12T10:09:56.903Z cpu23:9880)[type 10c00001 offset 55998464 v 2941, hb offset 3284992
gen 42893, mode 2, owner 00000000-00000000-0000-000000000000 mtime 1860122
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-12T10:09:56.915Z cpu25:23303194)DLX: 3661: vol ‘Production-B-Datastore-14′, lock at 194387968: [Req mode 1] Checking liveness:
2014-10-12T10:09:56.915Z cpu25:23303194)[type 10c00001 offset 194387968 v 283, hb offset 3284992
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 3146551
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-12T10:09:57.677Z cpu6:9875)FS3: 1393: vol ‘PCI-Migration’, lock at 47556608: [Req mode: 1] Not free:
2014-10-12T10:09:57.677Z cpu6:9875)[type 10c00001 offset 47556608 v 1880, hb offset 3284992
gen 42893, mode 2, owner 00000000-00000000-0000-000000000000 mtime 661885
num 1 gblnum 0 gblgen 0 gblbrk 0]

The vmkernel logs are completely filled with these lock holder messages which is why the log file had rotated so fast:

2014-10-12T09:46:28.305Z cpu2:9878)DLX: 3661: vol ‘Production-B-Datastore-8′, lock at 232120320: [Req mode 1] Checking liveness:
2014-10-12T09:46:28.305Z cpu2:9878)[type 10c00001 offset 232120320 v 9052, hb offset 3284992
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 2863190
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-12T09:46:28.514Z cpu2:9868)DLX: 4185: vol ‘Production-B-Datastore-14′, lock at 193937408: [Req mode: 1] Not free:
2014-10-12T09:46:28.514Z cpu2:9868)[type 10c00001 offset 193937408 v 1488, hb offset 3284992
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 3125883
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-12T09:46:28.527Z cpu2:9868)DLX: 3661: vol ‘Production-B-Datastore-14′, lock at 194019328: [Req mode 1] Checking liveness:
2014-10-12T09:46:28.527Z cpu2:9868)[type 10c00001 offset 194019328 v 1769, hb offset 3428352
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 3124506
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-12T09:46:28.540Z cpu2:24477994)DLX: 4185: vol ‘Production-B-Datastore-14′, lock at 194785280: [Req mode: 1] Not free:
2014-10-12T09:46:28.540Z cpu2:24477994)[type 10c00001 offset 194785280 v 1901, hb offset 3284992
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 3124798
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-12T09:46:28.628Z cpu2:24477994)DLX: 3661: vol ‘Production-B-Datastore-14′, lock at 194791424: [Req mode 1] Checking liveness:
2014-10-12T09:46:28.628Z cpu2:24477994)[type 10c00001 offset 194791424 v 1909, hb offset 3284992
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 3125256
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-12T09:46:28.864Z cpu4:9879)DLX: 4185: vol ‘Production-B-Datastore-14′, lock at 194242560: [Req mode: 1] Not free:
2014-10-12T09:46:28.864Z cpu4:9879)[type 10c00001 offset 194242560 v 1168, hb offset 3284992
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 3124979
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-12T09:46:28.983Z cpu4:9879)DLX: 3661: vol ‘Production-B-Datastore-14′, lock at 194248704: [Req mode 1] Checking liveness:
2014-10-12T09:46:28.983Z cpu4:9879)[type 10c00001 offset 194248704 v 1186, hb offset 3284992
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 3125436
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-12T09:46:29.240Z cpu15:23764342)FS3: 1393: vol ‘PCI-Migration’, lock at 46905344: [Req mode: 1] Not free:
2014-10-12T09:46:29.240Z cpu15:23764342)[type 10c00001 offset 46905344 v 2160, hb offset 3284992
gen 42893, mode 2, owner 00000000-00000000-0000-000000000000 mtime 662629
num 1 gblnum 0 gblgen 0 gblbrk 0]

Here we can see numerous lock checking for different datastore names and file lock addresses, all within the same second. It appears that this host is aggressively trying to check file lock liveliness, which is certainly unusual behavior.

Let’s review another VM that powered off in another cluster to see if the behavior is the same across clusters:

esx-esx0040.server.company.com-2014-10-21–20.20/vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0:
VM: vmserver0260

2014-10-17T13:59:27.457Z| vmx| I120: DISKLIB-LIB : Resuming change tracking.
2014-10-17T13:59:27.461Z| vmx| I120: DISKLIB-CBT : Initializing ESX kernel change tracking for fid 337992562.
2014-10-17T13:59:27.462Z| vmx| I120: DISKLIB-CBT : Successfuly created cbt node 18605b78-cbt.
2014-10-17T13:59:27.462Z| vmx| I120: DISKLIB-CBT : Opening cbt node /vmfs/devices/cbt/18605b78-cbt
2014-10-17T13:59:27.462Z| vmx| I120: DISKLIB-LIB : Opened “/vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0/vmserver0260/vmserver0260_5-000002.vmdk” (flags 0xa, type vmfs).
2014-10-17T13:59:27.462Z| vmx| I120: DISK: Disk ‘/vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0/vmserver0260/vmserver0260_5-000002.vmdk’ has UUID ’60 00 c2 97 27 69 c9 e3-e4 0f 02 13 a1 6d 4c 6d’
2014-10-17T13:59:27.462Z| vmx| I120: DISK: OPEN ‘/vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0/vmserver0260/vmserver0260_5-000002.vmdk’ Geo (1697/255/63) BIOS Geo (0/0/0)
2014-10-17T13:59:31.456Z| Worker#0| I120: DISKLIB-CTK : Could not open tracking file. File open returned IO error 4.
2014-10-17T13:59:31.456Z| Worker#0| I120: DISKLIB-CTK : Could not open change tracking file “/vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0/vmserver0260/vmserver0260-000002-ctk.vmdk”: Could not open/create change tracking file.
2014-10-17T13:59:31.458Z| Worker#0| I120: DISKLIB-LIB : Could not open change tracker /vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0/vmserver0260/vmserver0260-000002-ctk.vmdk: Could not open/create change tracking file.
2014-10-17T13:59:31.461Z| Worker#0| I120: DISKLIB-VMFS : “/vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0/vmserver0260/vmserver0260-000002-delta.vmdk” : closed.
2014-10-17T13:59:31.462Z| Worker#0| I120: DISKLIB-VMFS : “/vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0/vmserver0260/vmserver0260-000001-delta.vmdk” : closed.
2014-10-17T13:59:31.464Z| Worker#0| I120: DISKLIB-VMFS : “/vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0/vmserver0260/vmserver0260-flat.vmdk” : closed.
2014-10-17T13:59:31.464Z| Worker#0| I120: DISKLIB-LIB : Failed to open ‘/vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0/vmserver0260/vmserver0260-000002.vmdk’ with flags 0xa Could not open/create change tracking file (2108).
2014-10-17T13:59:31.464Z| Worker#0| I120: DISK: Cannot open disk “/vmfs/volumes/53694ec4-999f3bd0-156a-9c8e9920e2b0/vmserver0260/vmserver0260-000002.vmdk”: Could not open/create change tracking file (2108).
2014-10-17T13:59:31.467Z| vmx| I120: DISK: Opening disks took 4051 ms.

This error message is slightly different as this time the concern is the change block tracking file instead of the delta snapshot file. Let’s see if the vmkernel.log has the same events:

vmkernel.log:

2014-10-17T13:59:27.454Z cpu18:16729934)DLX: 3733: vol ‘Non-Production-A-Datastore-VMFS5-4′, lock at 71542784: [Req mode 1] Checking liveness:
2014-10-17T13:59:27.454Z cpu18:16729934)[type 10c00001 offset 71542784 v 37061, hb offset 3190784
gen 3, mode 1, owner 53e0181c-c8a6435e-55b0-0017a4770c24 mtime 28048957
num 0 gblnum 0 gblgen 0 gblbrk 0]
2014-10-17T13:59:27.462Z cpu12:16729808)CBT: 2214: Created device 18605b78-cbt for cbt driver with filehandle 408968056
2014-10-17T13:59:27.462Z cpu12:16729808)WARNING: CBT: 2039: Unsupported ioctl 60
2014-10-17T13:59:27.462Z cpu12:16729808)WARNING: CBT: 2039: Unsupported ioctl 59
2014-10-17T13:59:31.456Z cpu18:16729934)DLX: 4262: vol ‘Non-Production-A-Datastore-VMFS5-4′, lock at 71542784: [Req mode: 1] Not free:
2014-10-17T13:59:31.456Z cpu18:16729934)[type 10c00001 offset 71542784 v 37061, hb offset 3190784
gen 3, mode 1, owner 53e0181c-c8a6435e-55b0-0017a4770c24 mtime 28048957
num 0 gblnum 0 gblgen 0 gblbrk 0]

When crosschecking the lock @ address “71542784″ on volume ‘Non-Production-A-Datastore-VMFS5-4′ we see that the file in question is ‘vmserver0260-000002-ctk.vmdk’

Now we need to determine which ESX host is the owner of that lock that will not free. Please see KB 10051 for more information: http://kb.vmware.com/kb/10051

grep “00:17:a4:77:0c:24″ esx-esx0*/commands/nicinfo*
esx-esx0044.server.company.com-2014-10-21–17.31/commands/nicinfo.sh.txt:vmnic0 0000:002:00.0 elxnet Up 10000 Full 00:17:a4:77:0c:24 1500 Emulex Corporation HP NC553i Dual Port
FlexFabric 10Gb Converged Network Adapter

When we review the /var/log/vmkernel.log of host ‘esx0044.server.company.com’ we see a flood of lock holder checks on this host too:

2014-10-21T17:26:35.283Z cpu14:35211)DLX: 4262: vol ‘Non-Production-A-Datastore-VMFS5-17′, lock at 71235584: [Req mode: 1] Not free:
2014-10-21T17:26:35.283Z cpu14:35211)[type 10c00001 offset 71235584 v 301, hb offset 3907584
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 13817937
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-21T17:26:38.265Z cpu4:135822)DLX: 4262: vol ‘Non-Production-A-Datastore-VMFS5-15′, lock at 262238208: [Req mode: 1] Not free:
2014-10-21T17:26:38.265Z cpu4:135822)[type 10c00001 offset 262238208 v 9643, hb offset 3674112
gen 5, mode 1, owner 53e11584-d51063de-48a9-9c8e99227ee8 mtime 7918228
num 0 gblnum 0 gblgen 0 gblbrk 0]
2014-10-21T17:26:38.314Z cpu13:7072422)DLX: 4262: vol ‘Non-Production-A-Datastore-VMFS5-16′, lock at 130293760: [Req mode: 1] Not free:
2014-10-21T17:26:38.314Z cpu13:7072422)[type 10c00001 offset 130293760 v 10072, hb offset 3989504

2014-10-21T17:26:39.361Z cpu14:35211)DLX: 4262: vol 'Non-Production-A-Datastore-VMFS5-17', lock at 71241728: [Req mode: 1] Not free:
2014-10-21T17:26:39.361Z cpu14:35211)[type 10c00001 offset 71241728 v 363, hb offset 3907584
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 13817934
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-21T17:26:40.070Z cpu20:81812)World: 14296: VC opID hostd-4320 maps to vmkernel opID f2f9cb96
2014-10-21T17:26:42.283Z cpu4:135822)DLX: 4262: vol ‘Non-Production-A-Datastore-VMFS5-15′, lock at 262311936: [Req mode: 1] Not free:
2014-10-21T17:26:42.283Z cpu4:135822)[type 10c00001 offset 262311936 v 7749, hb offset 3674112
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 7917330
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-21T17:26:42.350Z cpu14:7072422)DLX: 4262: vol ‘Non-Production-A-Datastore-VMFS5-16′, lock at 130297856: [Req mode: 1] Not free:
2014-10-21T17:26:42.350Z cpu14:7072422)[type 10c00001 offset 130297856 v 10081, hb offset 3989504
gen 3, mode 1, owner 53e3b83d-2b1da026-14d6-0017a4770826 mtime 10085761
num 0 gblnum 0 gblgen 0 gblbrk 0]
2014-10-21T17:26:43.442Z cpu20:35211)DLX: 4262: vol ‘Non-Production-A-Datastore-VMFS5-17′, lock at 71247872: [Req mode: 1] Not free:
2014-10-21T17:26:43.442Z cpu20:35211)[type 10c00001 offset 71247872 v 330, hb offset 3190784
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 13817948
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-21T17:26:46.322Z cpu0:135822)DLX: 4262: vol ‘Non-Production-A-Datastore-VMFS5-15′, lock at 262320128: [Req mode: 1] Not free:
2014-10-21T17:26:46.322Z cpu0:135822)[type 10c00001 offset 262320128 v 7757, hb offset 3674112
gen 5, mode 2, owner 00000000-00000000-0000-000000000000 mtime 7917344
num 1 gblnum 0 gblgen 0 gblbrk 0]
2014-10-21T17:26:46.357Z cpu17:7072422)DLX: 4262: vol ‘Non-Production-A-Datastore-VMFS5-16′, lock at 129902592: [Req mode: 1] Not free:
2014-10-21T17:26:46.357Z cpu17:7072422)[type 10c00001 offset 129902592 v 10080, hb offset 3989504
gen 3, mode 1, owner 53e3b83d-2b1da026-14d6-0017a4770826 mtime 10085764
num 0 gblnum 0 gblgen 0 gblbrk 0]

Now we need to determine what process or ‘world’ on this host is requesting whether a lock is stale. When we check world ’35211′ we learn that it is process ‘vpxa-wroker’. Why is vpxa-worker trying to open files? What is vpxa-worker trying to do in general? Let’s take a look at the /var/log/vpxa.log file for more information:

2014-10-21T17:34:40.090Z [FFFD4B70 info 'commonvpxLro' opID=190a874-bf] [VpxLRO] — BEGIN task-internal-375725 — – vpxapi.VpxaService.searchDatastore — 04fe2fb8-71f9-c0a4-d42c-2812b96c7fb6
2014-10-21T17:34:40.090Z [FFFD4B70 verbose 'vpxavpxaMoService' opID=190a874-bf] SearchDatastore: ds:///vmfs/volumes/53f257d5-11293746-04b5-0017a477084e/ true [N3Vim4Host16DatastoreBrowser10SearchSpecE:0x1f3d72f8]
2014-10-21T17:34:40.090Z [FFFD4B70 verbose 'vpxavpxaDatastoreContext' opID=190a874-bf] [VpxaDatastoreContext] Resolved URL ds:///vmfs/volumes/53f257d5-11293746-04b5-0017a477084e/ to localPath /vmfs/volumes/53f257d5-11293746-04b5-0017a477084e/
2014-10-21T17:34:40.124Z [FFFD4B70 info 'vpxavpxaVmprov' opID=190a874-bf] [VpxaVmprovUtil::IsTopLevelObjectStorePath] path /vmfs/volumes/53f257d5-11293746-04b5-0017a477084e/ has fstype: 62768
2014-10-21T17:34:40.124Z [FFFD4B70 verbose 'vpxavpxaVmprovUtil' opID=190a874-bf] [VpxaVmprovUtil] UrlToDatastoreUrl conversion: ds:///vmfs/volumes/53f257d5-11293746-04b5-0017a477084e/ -> ds:///vmfs/volumes/53f257d5-11293746-04b5-0017a477084e/
2014-10-21T17:34:40.728Z [24983B70 info 'Libs' opID=1faf940d-66] OBJLIB-FILEBE : FileBEOpen: can’t open ‘/vmfs/volumes/53f25ab0-c16dcbc9-b38e-0017a477084e/fldcvisla0007/fldcvisla0007_1-flat.vmdk’ : Failed to lock the file (262146).
2014-10-21T17:34:40.728Z [24983B70 info 'DiskLib' opID=1faf940d-66] DISKLIB-DSCPTR: DescriptorOpenInt: failed to open ‘/vmfs/volumes/53f25ab0-c16dcbc9-b38e-0017a477084e/fldcvisla0007/fldcvisla0007_1-flat.vmdk’: Failed to lock the file (40002)
2014-10-21T17:34:40.728Z [24983B70 info 'DiskLib' opID=1faf940d-66] DISKLIB-LINK : “/vmfs/volumes/53f25ab0-c16dcbc9-b38e-0017a477084e/fldcvisla0007/fldcvisla0007_1-flat.vmdk” : failed to open (Failed to lock the file).
2014-10-21T17:34:40.731Z [24983B70 verbose 'Default' opID=1faf940d-66] [Search::GetInfo] Successfully opened disk: /vmfs/volumes/53f25ab0-c16dcbc9-b38e-0017a477084e/fldcvisla0007/fldcvisla0007_1.vmdk
2014-10-21T17:34:40.803Z [24983B70 info 'DiskLib' opID=1faf940d-66] DISKLIB-LINK : “/vmfs/volumes/53f25ab0-c16dcbc9-b38e-0017a477084e/fldcvisla0007/fldcvisla0007_1-ctk.vmdk” : failed to open (The file specified is not a virtual disk).

Why is the vpxa process kicking off ‘vpxapi.VpxaService.searchDatastore’ API requests? It is attempting to open a lot of different vmdk files which is failing because they are locked, likely because those virtual machines are running on other hosts. What is interesting it is attempting to open change block track files as well except it is trying to open them as virtual machine disks however these not actual virtual machine disks and merely ctk files. Yet again, very odd behavior. At this point I suspect that these API calls are likely coming from a 3rd party piece of software and not something native to our product. Let’s check the vCenter logs for more information:

2014-05-20T20:45:40.137-04:00 [08928 warning 'VpxProfiler' opID=1ea7d388] ClientAdapterBase::InvokeOnSoap: (esx130.server.company.com, vpxapi.VpxaService.searchDatastore) [SoapRpcTime] took 89590 ms
2014-05-20T20:45:40.137-04:00 [08928 info 'vpxdvpxdVmomi' opID=1ea7d388] [ClientAdapterBase::InvokeOnSoap] Invoke done (esx130.server.company.com, vpxapi.VpxaService.searchDatastore)
2014-05-20T20:45:44.583-04:00 [09416 warning 'VpxProfiler' opID=43475cf] ClientAdapterBase::InvokeOnSoap: (esx130.server.company.com, vpxapi.VpxaService.searchDatastore) [SoapRpcTime] took 163645 ms
2014-05-20T20:45:44.583-04:00 [09416 info 'vpxdvpxdVmomi' opID=43475cf] [ClientAdapterBase::InvokeOnSoap] Invoke done (esx130.server.company.com, vpxapi.VpxaService.searchDatastore)
2014-05-20T20:45:48.982-04:00 [09424 warning 'VpxProfiler' opID=eba32ae4] ClientAdapterBase::InvokeOnSoap: (esx098.server.company.com, vpxapi.VpxaService.searchDatastore) [SoapRpcTime] took 129044 ms
2014-05-20T20:45:48.982-04:00 [09424 info 'vpxdvpxdVmomi' opID=eba32ae4] [ClientAdapterBase::InvokeOnSoap] Invoke done (esx098.server.company.com, vpxapi.VpxaService.searchDatastore)
2014-05-20T20:46:12.958-04:00 [07708 warning 'VpxProfiler' opID=632083eb] ClientAdapterBase::InvokeOnSoap: (esx098.server.company.com, vpxapi.VpxaService.searchDatastore) [SoapRpcTime] took 182271 ms
2014-05-20T20:46:12.958-04:00 [07708 info 'vpxdvpxdVmomi' opID=632083eb] [ClientAdapterBase::InvokeOnSoap] Invoke done (esx098.server.company.com, vpxapi.VpxaService.searchDatastore)
2014-05-20T20:46:18.465-04:00 [09412 warning 'VpxProfiler' opID=6d6d6500] ClientAdapterBase::InvokeOnSoap: (esx098.server.company.com, vpxapi.VpxaService.searchDatastore) [SoapRpcTime] took 193924 ms
2014-05-20T20:46:18.465-04:00 [09412 info 'vpxdvpxdVmomi' opID=6d6d6500] [ClientAdapterBase::InvokeOnSoap] Invoke done (esx098.server.company.com, vpxapi.VpxaService.searchDatastore)
2014-05-20T20:47:41.128-04:00 [08808 warning 'VpxProfiler' opID=ecaec22f] ClientAdapterBase::InvokeOnSoap: (esx130.server.company.com, vpxapi.VpxaService.searchDatastore) [SoapRpcTime] took 252143 ms
2014-05-20T20:47:41.128-04:00 [08808 info 'vpxdvpxdVmomi' opID=ecaec22f] [ClientAdapterBase::InvokeOnSoap] Invoke done (esx130.server.company.com, vpxapi.VpxaService.searchDatastore)
2014-05-20T20:48:28.925-04:00 [04168 warning 'VpxProfiler' opID=a5dad99f] ClientAdapterBase::InvokeOnSoap: (esx098.server.company.com, vpxapi.VpxaService.searchDatastore) [SoapRpcTime] took 251114 ms

We can see the runtime of these API calls to be 90, 163, 129, 182, 193, 252, and 251 seconds respectively. This is a REALLY long time for a search and if this is holding vmdk or ctk files open this long then the retry time of the VMM process that runs the VM would expire and then VM would power off. Now we need to determine who is issuing these API calls.

Let’s review the vpxd-profiler logs on vCenter to figure out where these searches are originating from:

–> ThreadState/ThreadId/1668/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]52e5e352-3b0f-9f06-96b2-bc8a7d49d548::datastore-3262::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6
974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx098.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/3292/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]52b7e9ee-a68d-f05a-569b-469c8f782287::datastore-2840::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6
974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx130.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/3988/State/WAITING_VPX_MUTEX::EventManager::EventBatchAppender
–> ThreadState/ThreadId/5932/State/WAITING_VPX_MUTEX::QuickStatsResultQueue
–> ThreadState/ThreadId/7528/State/WAITING_VPX_MUTEX::QuickStatsResultQueue
–> ThreadState/ThreadId/7676/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]5213f5de-1ade-5f03-1dff-c052e1128069::datastore-2896::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx098.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/7712/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]52f10aba-19f4-effe-e45a-b01b7a46920a::datastore-2837::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx098.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/8296/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]521f2165-f9a1-5da3-3aee-602d3252451c::datastore-2883::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx098.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/8572/State/TASK::task-35026::::vim.DiagnosticManager.generateLogBundles::371e3640-395c-c5a7-595b-dc21b56ca1b7(52a30ca3-828e-2d13-9b67-46f2b645b194)
–> ThreadState/ThreadId/8588/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]529e290c-c0da-e02f-4c3c-73ecaa630531::datastore-2838::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx098.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/8680/State/WAITING_VPX_MUTEX::QuickStatsResultQueue
–> ThreadState/ThreadId/8688/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]526bfb1a-e489-050e-8b25-302accd06a9c::datastore-2897::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx130.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/8720/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]52289e72-a956-c1a3-24ac-c1e39193918e::datastore-2843::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx130.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/8760/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]52aebf6b-afda-4b80-e748-f2584b83c047::datastore-2839::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx130.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/8828/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]529e2bdf-686e-bf2e-5f38-abb50a9ffd6b::datastore-2841::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx130.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/8856/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]52cb5829-f64f-4a8e-4d22-202682b8e2ab::datastore-2844::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx130.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/9072/State/TASK::task-internal-2::::VpxdDrmMainLoop::/State/WAITING_VPX_MUTEX::VpxdDrmMainLoopLRO
–> ThreadState/ThreadId/9096/State/TASK::task-internal-1::::VpxdDrmMainLoop::/State/WAITING_VPX_MUTEX::VpxdDrmMainLoopLRO
–> ThreadState/ThreadId/9168/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]52987018-8a32-89de-8b86-44af61a2ab94::datastore-2842::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx130.server.company.com::vpxapi.VpxaService.searchDatastore
–> ThreadState/ThreadId/9204/State/WAITING_VPX_MUTEX::MapListLRU
–> ThreadState/ThreadId/9420/State/TASK::task-internal-622550::host-552::VpxdInvtHostSyncHostLRO.Synchronize::/State/WAITING_VPX_MUTEX::TaskInfoPublisherLock
–> ThreadState/ThreadId/9432/State/TASK::session[ca010e84-bd1f-0493-018c-65a5389452c8]52a3861b-23b2-4c92-0126-8faac627b359::datastore-2922::vim.host.DatastoreBrowser.searchSubFolders::ca010e84-bd1f-0493-018c-65a5389452c8(520b34e4-8a51-6974-c44b-a0c67f1913a8)/State/RPC::vpxapi.VpxaService:vpxa::esx098.server.company.com::vpxapi.VpxaService.searchDatastore

These searches are originating from ID “ca010e84-bd1f-0493-018c-65a5389452c8″

–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeFilterUpdatesTime/max 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeFilterUpdatesTime/mean 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeFilterUpdatesTime/min 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeFilterUpdatesTime/numSamples 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeFilterUpdatesTime/total 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeGUReqTime/max 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeGUReqTime/mean 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeGUReqTime/min 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeGUReqTime/numSamples 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeGUReqTime/total 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeProvidersTime/max 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeProvidersTime/mean 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeProvidersTime/min 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeProvidersTime/numSamples 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/ComputeProvidersTime/total 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/SetDoneTime/max 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/SetDoneTime/mean 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/SetDoneTime/min 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/SetDoneTime/numSamples 0
–> /SessionStats/SessionPool/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/PropertyCollector/SetDoneTime/total 0

–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/HttpSessionObject/Hidden/total 0
–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/PropertyCollector/FilterCount/total 0
–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/PropertyCollector/FullScans/total 0
–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/PropertyCollector/IncrementalScans/total 0
–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/PropertyCollector/LastVersionNum/total 0
–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/PropertyCollector/NullCollectorCount/total 0
–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/PropertyCollector/QueuedOpsCount/total 0
–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/PropertyCollector/ReadLocked/total 0
–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/PropertyCollector/TotalObjectCount/total 0
–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/PropertyCollector/TriggeredFiltersCount/total 0
–> /SessionStats/SessionPool/Session/Id=’ca010e84-bd1f-0493-018c-65a5389452c8′/Username=’WDW\f-hpsitescope’/ClientIP=’10.1.1.4′/PropertyCollector/TriggeredProcessGUReqs/total 0

These searches are originating from user ‘f-hpsitescope’ on IP 10.1.1.4 and are effectively hammering vCenter with constant vpxapi.VpxaService.searchDatastore API requests. The next step would be to locate the server with this IP address and determine what piece of software is generating so many requests. Based on the name of the user it suggests that HP SiteScope is causing these requests. This may not necessarily be a problem with that product but instead how that product is configured. A useful troubleshooting step would be to disable this product to see if the behavior stops.

I hope this demonstration shows you an end-to-end approach on how to investigate these kinds of problems on your own.

PCoIP issues with Horizon View Desktops

There are various reasons a user might experience a blank (black) screen when using the PCoIP protocol with Horizon View and our Support Engineers get calls on this every day. These include, but are not limited to:

  • Misconfiguration of connection server settings.
  • vRAM shortage on the View virtual machine.
  • Incorrect video driver version installed on the View virtual machine.

Note: Troubleshoot your PCoIP issues in the proper order

It is important that the steps outlined in KB article:
Troubleshooting a black screen when logging into a Horizon View virtual desktop using PCoIP (1028332) be followed in the order provided in order to quickly isolate and identify the proper resolution. They are also ordered in the most appropriate sequence to minimize data loss. The KB walks you through a serious of checks, verifying that various requirements are met and that your systems are configured properly. You will see many articles referenced as you work through each step. Do not skip steps. A slow, methodical approach works best here.

If you still see a problem after reading through the body of the KB article, there are also a number of related articles listed in the ‘See Also’ section. If you want to be notified when this article is updated there is an rss link you can subscribe to.

Generating and Troubleshooting SSL certificates in View

VMware View SecurityNext up in our series of VMware View topics, we’re going to talk about security. I spoke with a couple of our top support engineers about View security and they identified three Knowledgebase articles that solve more support requests than any others in the area of security, namely SSL certificates.  They recommend customers use:

In View 5.1 and later, you configure certificates for View by importing the certificates into the Windows local computer certificate store on the View server host. By default, clients are presented with this certificate when they visit a secure page such as View Administrator. You can use the default certificate for lab environments, and one could even make the argument that it is OK for fire-walled environments, but otherwise you should replace it with your own certificate from a trusted CA (Verisign, GoDaddy, others) as soon as possible. They also told me you should use an SSL certificate from a trusted CA when setting up a Security Server for your environment when the Security Server can be used from outside your firewall (Internet) to access View desktops inside your firewall.

My engineers stressed to me the importance of following each step in these KBs one at a time when you are filling out the forms on those sites to obtain your certificate. It is easy to make a mistake and you might not receive something that will work for you.

Note: The default certificate is not signed by a commercial Certificate Authority (CA). Use of noncertified certificates can allow untrusted parties to intercept traffic by masquerading as your server.

 

When Linked Clones Go Stale

One of the biggest call drivers within our VMware View support centers revolves around linked clone pools. Some of your users may be calling you to report that their desktop is not available. You begin to check your vCenter and View Administrator portal and discover some of the following symptoms:

  • You cannot provision or recompose a linked clone desktop pool
  • You see the error:
    Desktop Composer Fault: Virtual Machine with Input Specification already exists
  • Provisioning a linked clone desktop pool fails with the error:
    Virtual machine with Input Specification already exists
  • The Connection Server shows that linked clone virtual machines are stuck in a deleting state
  • You cannot delete a pool from the View Administrator page
  • You are unable to delete linked clone virtual machines
  • When viewing a pools Inventory tab, the status of one or more virtual machines may be shown as missing

There are a number of reasons this might happen, and KB: 2015112 Manually deleting linked clones or stale virtual desktop entries from the View Composer database in VMware View Manager and Horizon View covers resolving this topic comprehensively, but let’s discuss a bit of the background around these issues.

When a linked clone pool is created or modified, several backend databases are updated with configuration data. First there is the SQL database supporting vCenter Server, next there is the View Composer database, and thirdly the ADAM database. Let’s also throw in Active Directory for good measure. With all of these pieces each playing a vital role in the environment, it becomes apparent that should things go wrong, there may be an inconsistency created between these databases. These inconsistencies can present themselves with the above symptoms.

Recently a new Fling was created to address these inconsistencies. If you’re not acquainted with Flings, they’re tools our engineers build to help you explore and manipulate your systems. However, it’s important to remember they come with a disclaimer:

“I have read and agree to the Technical Preview Agreement. I also understand that Flings are experimental and should not be run on production systems.”

If you’re just in your lab environment though, they are an excellent way to learn and understand the workings of your systems at a deeper level. Here is the Fling: ViewDbChk. For production systems we recommend following the tried and true procedures documented in KB 2015112. The KB includes embedded videos to help walk you through the steps.

Installing async drivers in ESXi 5.x

One thing that catches a few customers up is the process of installing async drivers in their ESXi host … We have a KB article on the topic here, but there is more than one method to choose from and preparation steps involved. Since these steps might seem a little tricky, we decided a quick, live video explaining the topic might help many of you.

We called upon Kiwi Ssennyonjo to walk us through the salient points.

Again, the full KB article can be found here: Installing async drivers on ESXi 5.0/5.1/5.5 (2005205)

Would you like us to Podcast?

Today we ask you a simple question:


Troubleshooting Network Teaming Problems with IP Hash

Last week, I shed some light on the challenges having multiple Vmkernel ports in the same subnet can cause. Today, I’ll be shifting gears back to troubleshooting common network teaming problems – more specifically with IP hash.

IP Hash load balancing is really nothing new, but unfortunately, it is very often misunderstood. To be able to effectively troubleshoot IP hash and etherchannel problems, it’s important to first understand how IP hash works and its inherent limitations.

From the vSphere 5.1 Networking Guide definition of IP Hash load balancing:

“Choose an uplink based on a hash of the source and destination IP addresses of each packet. For non-IP packets, whatever is at those offsets is used to compute the hash”

This may seem like an overly concise definition, but it does indeed summarize what the host is doing in a network team utilizing IP hash load balancing. To expand on this a bit – the host will take the source and destination IP address in a HEX format, perform an Xor operation on them, and then run the result through another calculation based on the number of uplinks in the team. The final result of the calculation is a number between 0 and the number of uplinks, minus one. So if you had four uplinks in an IP hash team, the result of each calculation would be a number between 0 and 3 – four possible outcomes that are each associated with one NIC in the team. This end result of the calculation is commonly referred to as the interface index number.

You may also be wondering how non-IP traffic would be put through this calculation since there wouldn’t be an IP header and thus it wouldn’t have a 32-bit source and destination IP address for this calculation. As per the definition from the networking guide: “For non-IP packets, whatever is at those offsets is used to compute the hash”. This essentially means that two 32 bit binary values will be taken from the frame/packet from where the IP addresses would usually be located if it was an IP packet. It really doesn’t matter if these two 32-bit values are not actually IP addresses. So long as there is binary data in these locations, the calculation can still be applied to balance this traffic out across the adapters in the team.

This behavior is very different from the default ‘Route based on the originating virtual port ID’ load balancing method. Instead of having a one-to-one mapping of virtual NICs to physical adapters in the host, any single virtual machine could potentially use any of the NICs in the team depending on the source and destination IP address.

It is this fact that makes IP Hash so desirable from a performance standpoint. It is the only load balancing type that could (in theory) allow any single virtual machine to utilize the bandwidth available on all network adapters in the team. If a virtual machine operates in a client/server type of role with a large number of independent machines accessing it (think hundreds of Outlook clients accessing an Exchange VM for example) the IP hash algorithm would provide a very good spread across all NICs in the team.

On the flipside, however, if you have a small number of IP addresses (or only one) doing most of the talking, you’ll find that the majority of the traffic may be favoring only one network adapter in the team. An example of this would be a database server that is accessed by only one application server. Since there is only one source and destination address pair, the hash calculation will always work out to the same index value and the host will only select one network adapter in the team to use.

That’s how it works from the host’s perspective, but how does the return traffic know which adapter to take? As you probably expected – it’s not just the host that has some math to do, the physical switch also needs to run packets through the same algorithm to select the correct physical switch port.

For this load balancing type to work correctly, the physical switch ports must be configured as an etherchannel bond (also called a port channel, or a trunk in the HP world). This essentially allows the bonding of multiple network adapters and causes the switch to perform the same type of hash calculation to ensure that it’s behaving in the exact same way for all traffic heading in the other direction. If the physical switch is not configured for an etherchannel, it’ll start getting confused very quickly as it’ll see the same MAC address sending traffic out of multiple ports resulting in what’s referred to as ‘MAC flapping’. I won’t go into too much detail into this scenario, but needless to say, all sorts of undesirable things start to happen when this occurs.

IP Hash and Etherchannel Limitations

Now that we have covered how IP hash works, let’s cover off briefly on the limitations of this type of teaming setup. The potential performance benefits of IP hash may not always outweigh the flexibility that is lost, or the other limitations that will be imposed.

I’d definitely recommend reading KB article: ESX/ESXi host requirements for link aggregation (1001938), which discusses this in detail, but to summarize a few key limitations:

ESX/ESXi supports IP hash teaming on a single physical switch only: This one can be a real deal-breaker for some. Because etherchannel bonding is usually only supported on a single switch, it may not be possible to distribute the uplinks across multiple physical switches for redundancy. There are some exceptions to this rule as some ‘stacked’ switches, or modular switches with a common backplane support etherchannel across physical switches or modules. Cisco’s VPC (virtual port channel) technology can also address this on supported switches. Consult with your hardware vendor for your options.

ESX/ESXi supports only 802.3ad link aggregation in ‘Static’ mode: This is also referred to as ‘Mode On’ in the Cisco world. This means that LACP (link aggregation control protocol) cannot be used. The only exception is with a vNetwork Distributed Switch in vSphere 5.1, and with the Cisco Nexus 1000V. If you are using vNetwork Standard Switches, you must use a static etherchannel.

Beacon Probing is not supported with IP hash: Only link status can be used as a failure detection method with an IP hash team. This may not be desirable in some situations.

An Example

Let’s walk through another fictitious example of a network teaming problem. Below is the problem definition we’ll be working off of today:

“I’m seeing very odd behavior from one of my hosts! Each virtual machine can’t ping different sets of devices on the physical network. If I try to ping a device, it may work from some virtual machines, but not from others. Connectivity is all over the place. I can’t make heads or tails of this! Help!”

Well this certainly sounds very odd – why are some devices accessible while others are not? And to make matters even more confusing, things that don’t work from one VM work fine from another and vice versa.

Let’s have a quick look at the vSwitch configuration on the host having a problem:

We’ve got three physical adapters associated with a simple virtual machine port group. Let’s have a look at the teaming configuration to determine the load balancing type employed:

And sure enough, Route based on IP hash is being employed as the load balancing method. With this very limited amount of information we can determine quite a bit about how the environment should be configured. We know the following:

  1. All three physical switch ports associated with vmnic1, vmnic2 and vmnic3 should be configured identically and should be part of a static etherchannel bond. Since this is a vNetwork Standard Switch, LACP should not be used.
  2. No VLAN tag is defined for the port group, so this tells us that we’re not employing VST (virtual switch tagging) and that the switch should not be configured for 802.1q VLAN trunking on the etherchannel bond. It should be configured for ‘access’ mode.
  3. The five virtual machines in the vSwitch will be balancing their traffic across all three network adapters based on source and destination IP addresses. The host will perform a mathematical calculation to determine which adapter to use.

To start our troubleshooting, we’ll first try to determine what works and what doesn’t. We’ll use two of the virtual machines, ubuntu1 and ubuntu2 for our testing today. We obtained a list of IP addresses and their ping results from our fictitious customer for these two virtual machines. Below is the result:

For ubuntu1:

10.1.1.1 Physical Router, default gateway Success
10.1.1.22 Physical Server, SQL database Success
10.1.1.23 Physical Server, SQL database Success
10.1.1.24 File Server on another ESXi host Fail
10.1.3.27 Physical Server, Primary Domain Controller Fail
10.1.3.28 Secondary Domain Controller on other ESXi host Success
10.1.1.101-106 All other VMs in the same port group Success

 

For ubuntu2:

10.1.1.1 Physical Router, default gateway Success
10.1.1.22 Physical Server, SQL database Success
10.1.1.23 Physical Server, SQL database Fail
10.1.1.24 File Server on another ESXi host Success
10.1.3.27 Physical Server, Primary Domain Controller Success
10.1.3.28 Secondary Domain Controller on other ESXi host Success
10.1.1.101-106 All other VMs in the same port group Success

 

Well that certainly seems odd doesn’t it? It’s pretty hard to find a pattern here and things really do seem to be “all over the place” as our fictitious customer claims. Neither of the VMs is having difficulty getting to the default gateway, but ubuntu1 can’t hit one of the VMs on another host and can’t hit a physical domain controller. Ubuntu2 can’t hit one of the physical SQL servers, but didn’t have any trouble reaching the other five machines we tried.

We can pretty much rule out the virtual machines in this situation as they can communicate with each other within the vSwitch just fine, and can also communicate with most of the devices upstream on the physical network as well. At this point, you may be suspecting that there is some kind of a problem with the teaming configuration, a physical switch problem or possibly something with one of the physical NICs on the host. All of these would be good guesses and would be in the correct direction here.

As I discussed in my blog post relating to NIC team troubleshooting last week, the esxtop utility can be very useful. Let’s have a look at the network view to see if it can lend any clues:

If you recall from my previous post when using ‘Route based on originating virtual port ID’, you’ll have a one-to-one mapping of virtual machines to physical network adapters when each VM has only a single virtual NIC. Not so with IP Hash. Instead, each virtual machine lists ‘all’ and the number of physical adapters it could be utilizing based on its calculation of the source and destination IP hash.

Well, that stinks. But we’re not quite ready to crawl to our network administration team in shame asking them to “check the switch”. Let’s take this a step further, get a better understanding of the problem and perhaps even impress them a bit in the process!

We can quite easily conclude that what we are dealing with here is an IP hash or an etherchannel problem. How do we know this? Very classic symptoms. Some source/destination IP combinations work just fine, while others don’t. Forget VLANs, forget subnet masks, routing – none of this matters in this situation. The same situation could present itself if you were communicating with something in the same network, or something 15 hops away on the other side of the world. The pattern that we are looking for here is actually the complete LACK of a pattern across the VMs. What we know is that we’re experiencing consistent difficulty reaching certain IP destinations, and it’s different from each VM we try in the vSwitch.

Unraveling the Mystery of IP Hash

Okay, so now what? Let’s think back to how IP hash works – it’s just a mathematical calculation. If the host can figure out which uplink to use, why can’t we do the same? Unfortunately, esxtop can’t help us, but if we have the source and destination IP addresses as well as the number of physical uplink adapters that are link-up, we can determine that path it will be taking.

I don’t want to scare anyone away here, but this does require some math. I’ll be the first to admit that I’m not the greatest with math, but if I can do it with the help of a calculator, then so can you. VMware has a great KB on how to do this calculation – KB: Troubleshooting IP-Hash outbound NIC selection (1007371), and I’d recommend giving it a read as well. I’ll walk you through this process for one of the source/destination address pairs and then we can see if a pattern finally emerges.

Let’s start with ubuntu1 and its default gateway. We know communication across this pair of addresses is working fine:

Source IP address: 10.1.1.101

Destination IP address: 10.1.1.1

Number of physical uplinks: 3

Let’s get started. The first thing we’ll need to do is to convert the IP addresses into HEX values for the calculation. There are some converters available that can do this in one simple step, but I’ll take the slightly longer road for educational purposes. First, let’s convert each of these IP addresses into their binary equivalents. This will need to be done for each of the four octets of the IP address separately. If you aren’t sharp with IP subnetting, or don’t really know how to convert from decimal values to binary, not to worry. Simply use the Windows Calculator in Programmer Mode and it can do the conversion for you.

Our IP address 10.1.1.101 – broken into its four independent octets – converts to binary as follows:

10

1

1

101

00001010

00000001

00000001

01100101

 

Pro-Tip: Remember, each of the octets of an IP address is expressed as an 8 bit value. Even if a binary value is calculated as fewer than 8 bits, you’ll need to append the 0’s at the beginning to ensure it’s always 8 bits in length. So a binary value of 1 for example, should be expressed as 00000001 for the purposes of our calculations today. Only the first octet can be expressed with less than 8 bits for this purpose because any leading zeros won’t change the total value of the number.

Next, we need to combine all four binary octets into a single 32-bit binary number. To do this, we simply append all of these octets together into the following:

00001010000000010000000101100101

Or if we drop the leading zeros at the beginning of the 32-bit value, we have:

1010000000010000000101100101

This number equates to 167,838,053 when converted to decimal format, but we’ll need the HEX value. To convert this, you can simply enter the long 32-bit binary number into Calculator in ‘Programmer’ mode, and then click the ‘Hex’ radio button. If you did it correctly, you should get the value:

0xA010165

Great, now we’ll do the same thing for our destination IP address, which is 10.1.1.1. After converting this to binary and then to HEX, we get the following value:

0xA010101

Pro-Tip: From here on out, I’ll always express hexadecimal values with a 0x prefix. This is so that there is no confusion between regular decimal numbers and hexadecimal numbers. You can usually identify a HEX value if it has an A, B, C, D, E or an F in it, but it could just as easily be made up of only numbers between 0 and 9. Our hexadecimal value of A010165 could also be represented as 0xA010165 – simply ensure your calculator is in HEX mode and drop the 0x when doing the upcoming calculations.

Now we’ve got everything we need to run this through the IP Hash calculation:

Source HEX address: 0xA010165

Destination HEX address: 0xA010101

Number of physical uplinks: 3

From this information, we run it through the following formula outlined in KB article: 1007371

(SourceHEX Xor DestHEX) Mod UplinkCount = InterfaceIndex

Even if you have no idea what Xor or Mod is, don’t worry – any scientific or programmer calculator can make quick work of this. In the Windows Calculator, simply go into programmer mode and the Xor and Mod functions are available. Don’t forget to ensure you are in HEX mode before entering in the values. Plugging our values into this equation, we get the following:

(0xA010165 Xor 0xA010101) Mod 3 = InterfaceIndex

Thinking back to high school math class, let’s calculate what’s in the brackets first, and we are left with the following:

0×64 Mod 3 = InterfaceIndex

And then we simply use Mod 3 of that value to calculate the interface index. Remember, because we have only three uplink adapters, a valid answer will be anything between 0, 1 or 2.

InterfaceIndex = 1

And there you have it. That wasn’t so bad was it? From our calculation we were able to determine that communication between 10.1.1.101 and 10.1.1.1 will be using interface index 1, which is the second uplink in the team as this value starts at 0.

A New View of the Situation

I went ahead and calculated the remaining interface index values for the other source and destination IP address combinations for ubuntu1 and ubuntu2. Below is the result:

From ubuntu1:

Source IP Destination IP Ping Success? Interface Index
10.1.1.101 10.1.1.1 Success 1
10.1.1.101 10.1.1.22 Success 1
10.1.1.101 10.1.1.23 Success 0
10.1.1.101 10.1.1.24 Fail 2
10.1.1.101 10.1.3.27 Fail 2
10.1.1.101 10.1.3.28 Success 0

 

From ubuntu2:

Source IP Destination IP Ping Success? Interface Index
10.1.1.102 10.1.1.1 Success 1
10.1.1.102 10.1.1.22 Success 1
10.1.1.102 10.1.1.23 Fail 2
10.1.1.102 10.1.1.24 Success 0
10.1.1.102 10.1.3.27 Success 1
10.1.1.102 10.1.3.28 Success 1

 

Well now, I’d say we are now seeing a very distinct pattern here. The physical adapter or physical switch port associated with interface index 2 is no doubt having some kind of a problem here. At this point, we can now hold our heads up high, walk down the hall to our network administration team and let them know that we’ve clearly got an etherchannel problem here. They may even be impressed when you tell them that you’ve narrowed it down to one of the three NICs in the team based on your IP Hash calculations!

After a quick look at the physical switch configuration, the network team provides you with the configuration of the port-channel and the three interfaces in question:

interface Port-channel8
switchport
switchport access vlan 10
switchport mode access
!
interface GigabitEthernet1/11
switchport
switchport access vlan 10
switchport mode access
channel-group 8 mode on
!
interface GigabitEthernet1/12
switchport
switchport access vlan 10
switchport mode access
channel-group 8 mode on
!
Interface GigabitEthernet1/13
switchport
switchport trunk allowed vlan 99-110
switchport mode trunk
switchport trunk encapsulation dot1q
switchport trunk native vlan 99

 

And there you have it. On the physical switch, port-channel 8 is made up of only two interfaces – not three. The third NIC in the team is associated with port GigabitEthernet1/13, which is an independent VLAN trunk port. Not only is it not a part of the etherchannel, its VLAN configuration is way off. Remember – IP Hash requires a consistent configuration on the physical switch. Uplink adapters cannot be removed or added to the vSwitch without ensuring that the physical switch ports associated with them are added to the etherchannel bond.

I hope you enjoyed this write-up and found it educational. I’d recommend checking out the following KB articles for more information on some of the topics I’ve discussed today:

Challenges with Multiple VMkernel Ports in the Same Subnet

Last week I took a look at some common network teaming problems and how to apply logical troubleshooting methodology to zero in on the problem. I’m hoping to write some follow-ups to dig a bit more into other load balancing types, but for now, I’ll be shifting the focus to host routing.

When I talk about host routing, I’m referring to just that – the host. Virtual machines route based on their guest configuration and based on what they can access on the physical network by means of their vSwitch and the upstream network configuration. Running virtual machines is certainly the primary focus of the vSphere suite of products, but there are numerous services used by the host that will require network connectivity. These include but are not limited to:

  • Management Networking and vCenter connectivity
  • vMotion
  • Fault Tolerance
  • Host storage connectivity (iSCSI, NFS)

ESXi differs in many ways from ESX – namely in the absence of the bolt-on Service Console that was used for management purposes. I won’t be going to too much detail to describe the differences between ESX and ESXi, as this has been covered at great length in many blog posts and technical documents out there. Rather, I will focus on host routing, how it differs between ESX and ESXi and how to avoid common pitfalls.

I’m going to begin by walking through a problem I’ve seen on more than one occasion here in Tech Support at VMware Support. Here is a fictitious problem statement that we’ll be operating off of today:

I’ve been running ESX 4.1 without issue, and I just recently deployed a new ESXi 4.1 host. The vSwitch and physical network configuration is identical, but I can’t mount my NFS datastore on the new ESXi host. I get a “Permission Denied” failure. I’ve triple-checked my NFS filer permissions and everything is configured exactly as it should be. Help!

You may be wondering just what NFS permission problems have to do with host routing? More often than not, it really is just a simple permissions problem on the NFS filer. For the purposes of our example today though, we’ll be assuming that we’ve already verified that the permissions are indeed correct.

We’ll be working with two hosts – one ESX and one ESXi – that are both version 4.1 Update 1. Let’s start by taking a look at the ESX host that has been working just fine. First, we’ll check the NFS mount in question to determine how it’s been mounted and the relevant connection information. As you can see, this is a read-only NFS mount called ISOs. The NFS server’s IP address is 192.168.2.55. We’re able to browse the NFS datastore just fine, and if I remove the mount and mount it again, it connects back without issue on this ESX host.

Now let’s take a quick look at the vSwitch configuration on this same host:

As you can see above, the setup is very simple – vSwitch1 is being used for NFS purposes. We have a single VMkernel port for NFS with an IP address of 192.168.2.121. The Service Console port is utilizing vSwitch0, with a separate physical uplink adapter.

Everything may appear in order here, but the most important point we’ll want to make note of is that the Service Console port appears to be in the same IP subnet as the NFS VMkernel port. This is not according to best practices. Storage networking should always be in a dedicated subnet associated with a non-routable VLAN or a dedicated physical switch. Best practices aside, there should be no reason why this NFS share can’t be mounted so long as the host networking and upstream physical network are configured correctly.

Now let’s take a look at the ESXi host that is having difficulty. The vSwitch is configured as follows:

At first glance, the configuration certainly does seem consistent. The same physical uplink adapter configuration was maintained and the same IP subnet is being used for management and NFS connectivity. To begin our troubleshooting, let’s try to mount the NFS share and check the VMkernel logging see the exact error:

Pro-Tip: In ESXi 4.x, the VMkernel logging is written to the /var/log/messages file, along with logging from a slew of other chatty services, including hostd and vpxa. To filter only VMkernel messages in ESXi 4.x into the ‘less’ viewer, you can use the following command:

# grep vmkernel /var/log/messages | less

As you can see above, this is indeed specifically being reported as a ‘permission denied’ error. The ESXi host is receiving an error 13 back from the NFS filer. There really doesn’t appear to be an obvious networking problem as we receive back the error 13 after our mount attempt and can ping 192.168.2.55 all day long without a single dropped packet. We can also ping the host without issue from the NFS filer as well.

So what exactly is going on here?

Looking back to our ESX host, we can recall that the Service Console and NFS VMkernel port were both in the 192.168.2.0/24 network. Our ESXi host doesn’t have a Service Console port. Instead, it uses a VMkernel port for management networking. Again, these two VMkernel ports are in the same 192.168.2.0/24 network. But how does the ESXi host know which VMkernel port to use for NFS client purposes? Short answer – it doesn’t.

The host selects only one VMkernel port to use when there are more than one in any directly connected network. Generally speaking, this will be the lowest numbered or first created VMkernel port. So if we have vmk0 and vmk1 in the same subnet, the host will usually elect vmk0 for all communications within that network.

Let’s test our theory by checking the VMkernel routing table. We do this by running the following two commands:

# esxcfg-route –l
# esxcfg-route -n

The -l option provides a simple routing table, and the -n (for neighbor list) gives you what is essentially an ARP cache for various MAC addresses, along with the VMkernel interface currently being used to reach it. As you can see above, the host’s routing table doesn’t even include the NFS VMkernel port, vmk1. Only the management kernel port is listed for the directly connected 192.168.2.0/24 network. So to put it simply, the host is passing all traffic to 192.168.2.55 – the NFS server – through vmk0. We’re getting an access denied message because the NFS server is configured to allow vmk1’s IP address – not vmk0’s management IP address.

We can even confirm this by doing a packet capture on vmk1 using the tcpdump-uw utility in ESXi. We used the following command to check for traffic destined to 192.168.2.55 (the NFS server) on vmk1:

# tcpdump-uw -i vmk1 dst 192.168.2.55

Based on our testing, we received no tcpdump-uw output at all for vmk1 when trying to mount the NFS share. If we repeat this with vmk0, we get a flurry of outgoing traffic destined to 192.168.2.55.

The next logical question you may ask is why did this occur in ESXi but not in ESX? The answer is quite simple – The host’s NFS client must use a VMkernel port for communication and on the ESX host, we have only one VMkernel port in the 192.168.2.0 network. In short, it has no other choice. The Service Console has an independent routing table and even if its IP address happens to be in the same IP subnet, the Service Console and VMkernel will make independent forwarding decisions based on their own tables.

As you can see below, we can view the independent VMkernel and Service Console routing tables on the ESX host using the esxcfg-route -l and route -n commands respectively.

You may have also noticed that there are two ping commands in ESX – ping and vmkping. As you have probably guessed, ping is used when you want to send ICMP echo requests out of a Service Console interface, and vmkping for a VMkernel interface. In ESXi, both commands still exist, but they both are used for VMkernel interfaces only and can be used interchangeably.

What about vMotion, iSCSI?

You may be wondering about vMotion, Fault Tolerance and iSCSI traffic via VMkernel ports. Can’t you just check off the appropriate checkbox in the VMkernel port properties to ensure the correct one is used for each service?

And you would be correct in your assertion – you can indeed select which VMkernel port to use for these services. Even if there are other VMkernel ports in the same subnet, the host will respect the choices you make via these checkboxes:

Although this certainly helps, having multiple VMkernel ports in the same subnet can still cause confusion – even with these options checked off.

Take for example vMotion. If a host has a VMkernel port for vMotion and another for Management in the same subnet, the host will forward vMotion traffic based on the VMkernel port checked off for vMotion. That’s great and all, but now let’s suppose that a network administrator accidentally reconfigured the wrong physical port on the switch during some maintenance and the vmnic used for vMotion in now communicating in the wrong upstream VLAN. Suddenly, live migrations are failing to and from this host.

The first logical troubleshooting step you may wish to do is to login to this host via SSH, and to try to ping the vMotion interfaces on other hosts. Surprisingly, you may find that you are able to ping all of the other vMotion interfaces without issue. This is because the ‘ping’ utility is not respecting your choice of vMotion interfaces – it is simply forwarding traffic based on the host’s routing table.

There are similar challenges with iSCSI. You can bind VMkernel interfaces for use with the software iSCSI initiator, and the host will indeed respect this binding. Again, ICMP does not. Some iSCSI storage arrays use ICMP ping echo requests/replies as heartbeats to ensure the host interfaces are up. If these echo replies are not being received from the expected interfaces it can lead to all sorts of problems. I won’t get into any more detail on this situation, as this alone could be a full-length blog post. In a nutshell, it can cause unexpected behavior should an interface associated with active iSCSI paths go down on the host.

What’s New in ESXi 5.1?

Most of what we looked at was relating to ESX/ESXi 4.1, but it applies as well to ESXi 5.0. Things do change slightly in ESXi 5.1 as some changes were introduced to both the behavior of ICMP as well as ping or vmkping utility available in the busybox shell.

First, I’d recommend taking a look at KB 2042189 that discusses the ICMP ping response behavior change in ESXi 5.1. In summary, ICMP echo replies are now only sent back via the interface they were received on. The host will no longer refer to its routing table to make these forwarding decisions for ICMP traffic. If you think back to our iSCSI example earlier, you can see how this would be ideal to address the heartbeat challenges relating to ICMP echo requests being sent from the SAN.

Second, we can now select which VMkernel interface to ping out of using the ‘ping’ or ‘vmkping’ command in ESXi 5.1 using the -I option. Previously we could do this only for IPv6.  This can help greatly if you find yourself in a situation with multiple VMkernel ports per subnet – especially when dealing with iSCSI where you want to test connectivity across multiple independent paths via two or more VMkernel ports.

What should I do?

How can you ensure that your traffic is utilizing the intended VMkernel interface? Unfortunately, there isn’t a special command or advanced setting that can be used to intervene in the host’s forwarding decisions in all scenarios. The best advice that can be given is to simply adhere to best practices. The relevant best practices are as follows:

  1. Have only one VMkernel port per IP subnet (the only exception here is for iSCSI multi-pathing, or multi-NIC vMotion in vSphere 5.x).
  2. A dedicated non-routable VLAN or dedicated physical switch for vMotion purposes.
  3. A dedicated non-routable VLAN or dedicated physical switch for IP Storage purposes.
  4. A dedicated non-routable VLAN or dedicated physical switch for Fault Tolerance purposes.

Not only will this ensure better segmentation of the various traffic types, it will also prevent the oddities I described earlier. Unfortunately, implementing these best practices in an existing environment may be much easier said than done. Based on our original NFS example, the configuration changes on the host would actually be quite simple – just a few IP address changes, but the physical infrastructure may be a different story altogether. You’d need to ensure that a VLAN was created, physical switches configured, along with readdressing of the NFS filer itself. Your network and storage administrators may not be too happy with you after you make a request like this, which is why it’s so important to configure your environment correctly from the beginning. Remember – VLANs are your friend.

Now let’s have a look at a different ESXi host – this one is configured to have services spread across various subnets/VLANs:

  • Management: vmk0 in the 192.168.2.0/24 subnet.
  • NFS: vmk1 in the 192.168.3.0/24 subnet.
  • vMotion: vmk2 in the 192.168.4.0/24 subnet.

On the physical switch, NFS and vMotion are configured for dedicated non-routable VLANs. On this host, the vSwitch configuration looks as follows:

As you can see above, we now have one VMkernel port per IP subnet and a neat and tidy host routing table:

Now each kernel port is associated with a separate ‘Local Subnet’. Everything else routes via the default gateway associated with the management VMkernel port as it should.

And there you have it – if you don’t give the kernel any other choice – only one choice – it’ll always do what is expected.

Some topical reading for you from the VMware Knowledge Base:

Tech Talk video series

We've just started a new video series here on VMware KBTV that's going to cover new territory for us. So far, we've stuck to doing videos to complement specific VMware Knowledge Base articles. This has been a great success going by our viewer stats, but we know there's more we can offer you. We thought, why not leverage the trainers we have on staff at VMware? These guys have a gift at explaining things in ways that stick with you.

Here is our opener video (in two parts) where Scott Laforet covers some very basic concepts about virtualization and how VMware products can get you on the road to cloud computing. The first two videos discuss the basic evolution of VMware's products, and touches briefly on our Desktop and Datacenter offerings, including Fusion, Workstation, and vSphere (ESX, ESXi, and vCenter Server). We wanted to start at square one, because many customers are still unsure of what virtualization is, and which product has what features. No marketing here, this is about how our products work.

As this series gathers steam, expect the content to ramp up quickly to cover some pretty advanced material. All provided to you for free. Let us know what you think of the series and which topics you'd like covered in the comments are below!

Tech Talk – General Overview of VMware Technology – Episode 1 – Part 1

 

Tech Talk – General Overview of VMware Technology – Episode 1 – Part 2

Social Media at VMware

In this short video you’ll learn what social media activities are going on within the Global Services and Support group at VMware from Rick Blythe, Social Media Specialist. If you’re interested in following these Twitter accounts, follow:

Rick Blythe, Social Media Specialist at VMware