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

Category Archives: Tech Talk

Deep-dive technical explorations

Deploying a VMware Horizon View Environment

You are the head of the IT department in your company, and you have just finished a meeting discussing finances and IT budget. The message is clear – it’s time to cut costs. Easy to say, but what can you do, and how do you do it? A VMware View infrastructure can provide significant cost savings as well as simplifying your administration while freeing up IT assets and personnel for other projects. But how do you start?

“VMware Horizon™ 6 (with View) delivers virtualized and remote desktops and applications through a single platform and supports end users with access to all of their Windows and online resources through one unified workspace.”

Ok, that product description sounds good, but what does it actually mean?

Think of how a physical computer lab runs. The IT administrator is tasked with the job of managing the computers. The lab requests 10 computers, so on day 1 the administrator sets up 10 PCs. The lab hums along happily and meets all the company’s needs. But wait, there is a big project coming and we need to bring in 5 people for a few months. The administrator puts in a requisition and purchases 5 new PCs for the lab and sets them up too. 3 months later when the project is complete and the extra computers are no longer needed, the administrator packs them up and puts them in a store room.

This is wasteful. 5 computers are just sitting in a closet unused. This is where a virtual desktop infrastructure (VDI) with Horizon View comes in. A Horizon View implementation can reduce the cost and manpower associated with the physical lab.

Using our previous example, you have configured your lab to use Horizon View desktops. In the physical lab, you can use:

  • Old computers that are past their useful life due to hardware obsolescence
  • Low cost dumb terminals or embedded systemsNon-Windows clients
  • Non-Windows clients
  • BYOD user equipment

Now let’s investigate the same scenario with the Horizon View lab. New user accounts are created and we entitle the new users to the lab pool and that’s it. The pool can be configured to add desktops as required with no admin intervention. The lab requires a far smaller expenditure for workstations due to the low cost of client units, or perhaps the users can even use their own devices. The implementation costs are far less to expand to accommodate new users and there is significantly less labor required to administer.

In part 2, I will cover preparing your environment to deploy a Horizon View implementation.

What is a linked clone? Part II

In Part I, we covered the basics of what a linked clone is, the basic structure, and how a linked clone is provisioned. In this follow-up piece, we’ll look at the 3 major operations performed on a linked clone. Refresh, recompose, and re-balance.

Refresh

As mentioned in Part I, a checkpoint is created containing the individual customizations to the VM that differentiates it from the replica. This checkpoint contains things like the machine password, domain information, Windows name, etc. This checkpoint is a snapshot of the VM post customization. The refresh operation reverts the VM to this checkpoint snapshot.

View Connection Server changes the status of the VM to Maintenance to tag it as unusable, reverts to the previous checkpoint snapshot, and after start-up, the View Composer agent updates the machine account password if needed. View Connection Server then sets the machine back to Provisioned, or Available to meet the pool requirements.

The Desktop is now ready for use.

Recompose

A recompose lets you redeploy an existing View desktop while preserving any persistent or user data disks that may be attached to the VM.

When a recompose is performed with no configuration change (no new snapshot), no recompose will occur because Composer will detect that no changes will be made. The difference between using an existing template/snapshot and a new template/snapshot is a new replica is needed with a new snapshot. The new replica is cloned from the snapshot, and a new checkpoint and difference disk are created.

View changes the status of the desktop to Maintenance and creates the new snapshot if needed. Though the VM hardware is not replaced, this is a new VM and is customized using the same process as a newly provisioned desktop with a new checkpoint and difference disk. View then sets the machine back to Provisioned, or Available to meet the pool requirements.

The difference between using an existing template/snapshot and a new template/snapshot is a new replica is needed with a new snapshot. The new replica is cloned from the snapshot, and a new checkpoint and difference disk are created.

View Connection Server changes the status of the desktop to Maintenance and creates the new snapshot if needed. Though the VM hardware is not replaced, this is a new VM and is customized using the same process as a newly provisioned desktop with a new checkpoint and difference disk. View then sets the machine back to Provisioned, or Available to meet the pool requirements.

Re-balance

A re-balance serves 2 purposes-

  1. It will redistribute linked clones to use available free storage space.
  2. It is the only supported method to migrate linked clones between datastores. Storage vMotion will break a linked clone.

A re-balance will try to ensure all configured datastores are equally used based on the amount of available free space. I will not be discussing the algorithm used here because it is dependent on the version of View and the storage over commit settings. View will investigate each datastore the pool is configured to use, and determine which linked clones to migrate. It is possible during a re-balance that no desktops will be migrated. A refresh operation will also occur on all affected desktops.

When a re-balance occurs, the VM status is changed to Maintenance. View will then detach any persistent disks and move them and the VM to the new datastore. The persistent disks are attached to the VM at the new location. If a replica for the pool does not exist at the new location, Composer will request a new replica to be cloned by vCenter to be placed on that datastore. Composer will then attach the linked clone to the replica and customization occurs with a new checkpoint and difference disk. View will then set the machine back to Provisioned, or Available to meet the pool requirements.

A re-balance can also be used to vacate a datastore. Deselecting a datastore from a linked clone pool settings and then performing a re-balance on the pool will cause all associated linked clones from the pool to be migrating to another datastore (when possible). This is often used to migrate a linked clone pool from one datastore to another.
This covers the basics of what a linked clone is, and what maintenance and administrative options are available.

What is a linked clone?

In this 2 part article, we will be discussing linked clones, which are an integral part of VMware View. Part 1 will contain an overview of what a linked clone is. Part 2 will cover the operations that can be performed on a linked clone and how to maintain them.

So, what is a linked clone?

It’s the weekend and you’re out at a dinner party with several new friends. The conversation goes around the table from person to person and everyone talks about who they are and what they do for a living. The conversation gets around to you and you say, “I’m a VMware View Administrator”. If your friends are like mine, you will get blank, questioning stares in return. As a VMware View Administrator, what do you tell people what you do when they ask and how do you explain it?

I tell them I’m a tree tender.

To most people, the concept of virtualization is foreign, but a simple explanation is normally enough to understand what a virtual machine is and provide a basic idea of how it works. But what about a linked clone? This is where we use our tree analogy.

Simplifying things, if you were to describe a tree to someone, how would you do it?

A tree has a central core or trunk, several leaf-covered branches coming off at the top, and at the base in the ground it has roots. A linked clone can be thought of in a similar way.

The Tree Trunk

This can be known as the template, golden image, or base image. It is a virtual machine (VM) that is installed with all of the appropriate Windows updates, applications and patches that your users require. This is setup and configured to be a generic VM from which our linked clones will branch.

The Branches

This is the linked clone replica. This is a duplicate copy of the snapshot taken of the base image.  The replica is used as the “base” for all linked clones attached to it, for the terms of space saving and efficiency. Each linked clone pool will have at least one replica, one per snapshot in use.

The Leaves

Each linked clone VM within a pool is a leaf. Each leaf is attached to a branch which is attached to a trunk. The linked clone VM is not a standalone VM, but is a combination of the replica and a difference disk. The difference disk contains every disk write made after the replica is created.

The Roots

This is your vCenter. View Connection Server provides access, View Composer creates requests for cloning and customization, but your vCenter runs the whole show and makes things happen. Everything hooks into your vCenter.

How does it all work?

First, you need to create the template and prepare it for use. This includes installing VMware tools and the View Agent. Once you have all Operating System and application installed and updates complete, the template is ready, to be shut down and it’s snapshot is taken.

Within the View administrator, you will configure the pool to point at the specific base image and select the appropriate snapshot. Multiple pools can point to different images, the same image and snapshot, or the same image and different snapshots.

Once the pool is created, Composer will then request that vCenter clone a replica machine for use by the pool, and create the number of VMs needed to satisfy its pool requirements. This is where the linked clone machine is different than a standard VM. The replica contains everything that is needed to run Windows. It has all of the OS files, boot files and applications. The linked clone VM attaches to this so every linked clone shares the same Windows installation. A disk is created that contains the changes made for an individual VM. This checkpoint contains the domain and naming information and other basic information (the customization information) required to differentiate it from other linked clones attached to the same replica.

The linked clone can be customized in one of 2 ways. Sysprep (a Microsoft tool) uses a vCenter customization template that can be utilized to provide information on customizations to be performed. The second option is to use Quickprep which is Composer’s built in customization tool, and is generally recommended unless a Sysprep-specific customization is required.

At this point, the difference disk is created and all disk writes from that point on are saved to the difference disk. The replica is not modified, and the checkpoint contains all of the customization information that would be needed in the event the linked clone needs to be refreshed.

Watch this space for part 2 coming in about a week’s time. Thanks for reading!

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: