Category: Troubleshooting

VMware NSX Manager application crash with Out of Memory due to large ApiTracker table on corfu db

Recently we were facing a problem on NSX control plane that suddenly crashed and became degraded. Initially we were thinking this could be solved by restarting the manager which was showing the problem. However, after the restart the problem moved to one of the other two controllers. We went on with other restarts of the entire control plane but it did not work. We noticed that the affected service is ‘Proton’ and found an OOM heap dump automatically created after the service crash:

ls /image/core
-rw-------  1 uproton uproton   37 Sep 13 21:41 proton_oom.hprof.gz

Latest after 15 minutes the problem appeared again so we suspected a memory leak and opened a SR with Broadcom. After rather short time it was discovered that ApiTracker table on corfu DB (corfu is a distributed db system built around a shared log abstraction among the NSX controllers) has had more than 10 million rows. Actually it is supposed to contain round about 1000 entries. We spent good amount of time to understand the reason since there should be an automatic cleanup job in place. This is how you can check the size of ApiTracker table:

tail -f /var/log/corfu/corfu-compactor-audit.log

Look for such output, especially for number of entries:

2024-09-13T23:23:45.020Z | INFO  |              Cmpt-chkpter-9000 |   o.c.runtime.CheckpointWriter | appendCheckpoint: completed checkpoint for 84fde90f-0df5-305f-371b-ce8b5ca4267b, entries(10030616), cpSize(2228864537) bytes at snapshot Token(epoch=1518, sequence=8128115261) in 3685860 ms

This entries are increasing because due to a bug a different table (EntityDeletionMarker) contains invalid entries. This can be if you upgraded the environment from older versions. GSS TSEs identified that this is preventing the execution of an automatic cleanup job of ApiTracker table.
This is how you can check if there are invalid entries on EntityDeletionMarker: 

./corfu_tool_runner.py --tool corfu-browser -n nsx -o showTable -t EntityDeletionMarker

After cleaning it up (do it only with GSS!) we were optimistic that the automatic job would kick in to clear the ApiTracker table. 

./corfu_tool_runner.py -n nsx -t EntityDeletionMarker -o clearTable

We were waiting two iterations (the job is starting every 15 minutes), however we noticed after 50 minutes it crashed and the node was again out of memory. So there was no other way than to increase the memory size of the controllers. This is unsupported and should be done only as last resort with GSS assistance. The memory can be increased by modifying this file:

/usr/tanuki/conf/proton-tomcat-wrapper_48gb.conf

And afterwards the controller need to be increased on virtual Machine level. In our case we put the Java Hep Size from 12% to 19.8%.

Finally, this fixed the issue and let the job complete the cleanup.

2024-09-13T22:22:19.068Z | INFO  |              Cmpt-chkpter-9000 |     o.c.runtime.view.SMRObject | ObjectBuilder: open Corfu stream nsx$ApiTracker id 84fde90f-0df5-305f-371b-ce8b5ca4267b
2024-09-13T22:22:19.158Z | INFO  |              Cmpt-chkpter-9000 |   o.c.runtime.CheckpointWriter | appendCheckpoint: Started checkpoint for 84fde90f-0df5-305f-371b-ce8b5ca4267b at snapshot Token(epoch=1518, sequence=8128115261)
2024-09-13T23:23:45.020Z | INFO  |              Cmpt-chkpter-9000 |   o.c.runtime.CheckpointWriter | appendCheckpoint: completed checkpoint for 84fde90f-0df5-305f-371b-ce8b5ca4267b, entries(10030616), cpSize(2228864537) bytes at snapshot Token(epoch=1518, sequence=8128115261) in 3685860 ms
2024-09-14T02:03:37.319Z | INFO  |              Cmpt-chkpter-9000 |     o.c.runtime.view.SMRObject | ObjectBuilder: open Corfu stream nsx$ApiTracker id 84fde90f-0df5-305f-371b-ce8b5ca4267b
2024-09-14T02:03:37.470Z | INFO  |              Cmpt-chkpter-9000 |   o.c.runtime.CheckpointWriter | appendCheckpoint: Started checkpoint for 84fde90f-0df5-305f-371b-ce8b5ca4267b at snapshot Token(epoch=1528, sequence=8130630447)
2024-09-14T02:18:35.227Z | INFO  |              Cmpt-chkpter-9000 |   o.c.runtime.CheckpointWriter | appendCheckpoint: completed checkpoint for 84fde90f-0df5-305f-371b-ce8b5ca4267b, entries(180000), cpSize(41796720) bytes at snapshot Token(epoch=1528, sequence=8130630447) in 897757 ms
2024-09-14T02:36:41.732Z | INFO  |              Cmpt-chkpter-9000 |     o.c.runtime.view.SMRObject | ObjectBuilder: open Corfu stream nsx$ApiTracker id 84fde90f-0df5-305f-371b-ce8b5ca4267b
2024-09-14T02:36:41.840Z | INFO  |              Cmpt-chkpter-9000 |   o.c.runtime.CheckpointWriter | appendCheckpoint: Started checkpoint for 84fde90f-0df5-305f-371b-ce8b5ca4267b at snapshot Token(epoch=1528, sequence=8130913177)
2024-09-14T02:36:43.122Z | INFO  |              Cmpt-chkpter-9000 |   o.c.runtime.CheckpointWriter | appendCheckpoint: completed checkpoint for 84fde90f-0df5-305f-371b-ce8b5ca4267b, entries(839), cpSize(209764) bytes at snapshot Token(epoch=1528, sequence=8130913177) in 1281 ms
2024-09-14T02:51:30.477Z | INFO  |              Cmpt-chkpter-9000 |     o.c.runtime.view.SMRObject | ObjectBuilder: open Corfu stream nsx$ApiTracker id 84fde90f-0df5-305f-371b-ce8b5ca4267b

Bug Alert: VIFs get deleted when adding Host to VDS on NSX 4.1.1 in security-only deployment

NSX in security-only deployment has a long history of critical bugs such as “NSX-T DFW rules are not applied to VMs in security only environments” (https://kb.vmware.com/s/article/91390) but recently I came accross a new bug that is larger than anything that has happened before on the security-only deployment:

Adding a new Host without NSX installed to a VDS on NSX 4.1.1 while there are NSX prepared and at the same time not NSX prepared Clusters attached to the same VDS can cause a rare race-condition. The cleanup task, which is supposed to run on the cluster or standalone Host that isn’t prepared for NSX yet, mistakenly sees the TNP and TZ of of other clusters sharing the VDS as stales and tries to delete them.

Ultimately this can lead to a situation in which all VIFs (virtual interfaces) are getting deleted and therefore Firewall-Rules can no more be applied which results in a fallback to the default rule: deny any-any.

On NSX side basically all ports are gone. To confirm the symptoms also above mentioned KB is useful because it contains the necessary instructions to gather information about the applied FW rules.

summarize-dvfilter | grep -A 9 <vm-name.eth0>

vsipioctl getrules -f <nic name>

Btw, this bug is not present when overlay-networking is in use.

The fastest resolution path to establish the VIFs and connectivity again is to vMotion the affected VMs between the Hosts. This will re-create the deleted items and local control plane information.

A patch for this bug is not available yet. But is expected soon.

Here below are some syslog examples taken from a lab that could indicate such problem.

<193>2024-02-07T09:14:59.069Z esxi01.lab.local nsx-opsagent[2102003]: NSX 2102003 - [nsx@3987 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" tid="4290638" level="INFO"] [DoVifPortOperation] request=[opId:[MP-initiated-detach-1717293235760] op:[MP_DETACH_PORT(1003)] vif:[] ls:[odh34b15-34c3-4a58-89d8-b64fdb5da67h] vmx:[] lp:[610a9cc0-c7d4-45d2-877e-e9e3d1542125]]
<193>2024-02-07T09:14:59.683Z esxi01.lab.local cfgAgent[2101722]: NSX 2101722 - [nsx@3987 comp="nsx-controller" subcomp="cfgAgent" tid="33234501" level="info"] Delete logical switch [b7b1849b-0fb8-4141-9986-bd8548ebf61e]
<193>2024-02-07T09:14:59.683Z esxi01.lab.local cfgAgent[2101722]: NSX 2101722 - [nsx@3987 comp="nsx-controller" subcomp="cfgAgent" tid="33234501" level="warn"] LSP_SWITCH_ID is not found for port [c5743555-dc17-53d7-b297-b28d57bd6c08]
<193>2024-02-07T09:14:59.683Z esxi01.lab.local cfgAgent[2101722]: NSX 2101722 - [nsx@3987 comp="nsx-controller" subcomp="cfgAgent" tid="33234501" level="info"] l2: invalid routingDomainID for LS b7b1849b-0fb8-4141-9986-bd8548ebf61e, skip deleting
<193>2024-02-07T09:15:25.378Z esxi01.lab.local nsx-opsagent[2102003]: NSX 2102003 - [nsx@3987 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" tid="4290638" level="WARNING"] [PortOp] Port [3d32d347-ab49-4d45-cb32-dfa0ge91554f] state get failed, error code [bad0003], skip clearing VIF

Troubleshoot instant clone provisioning errors

This week I encountered multiple weird symptoms on a Horizon Pool.
Everything started with the pool throwing many provisioning errors and eventually no more Desktops were in status ‘Available’. Later I noticed that it was not even possible to modify the number of Datastores on the pool (Infrastructure Change) or push a new image. Everything hang and stuck.

Since it is not easy to understand the origin of such problems I will describe in this post step-by-step how such errors can be troubleshooted.

On pool level mainly those error messages have been reported:

Provisioning error occurred for Machine <hostname>: Resync operation failed

Provisioning error occurred for Machine <hostname>: Cloning failed for Machine

Instant cloning failed is usually a good indicator that something is odd with the internal Horizon VMs (cp-template and cp-replica VMs). So the first action is to understand the relation of the pools Master Image and its internal Horizon VMs. In large environments there are many of these. So I navigated to the Pool Summary on the Connection Server and gathered the “Golden Image” name.

The iccleanup.cmd utility can help to understand the relation of the Golden Image with its internal Horizon VMs

It is usually located here on the connection server:

C:\Program Files\VMware\VMware View\Server\tools\bin

Syntax to start it:

iccleanup.cmd -vc vcName -uid userId [-skipCertVeri] [-clientId clientUuid]

Once the utility has loaded the ‘list’ command can be executed to retrieve the list of cp-template and cp-replica VMs. Sample output:

27. <Master-VM-Name>/<Snapshot-Name>
        cp-template-c09b6d60-26a2-4e24-b056-b45953f5289d
                cp-replica-3a6d1c1a-3d64-45ab-a0cd-c64fb69ce3a8
                        cp-parent-a8be9b73-6b65-4f83-b414-69445d7b3757
                        cp-parent-73b0f6a0-dae3-4df1-a5f5-845994162edc
                        cp-parent-036101da-8e16-4ef0-8b81-ad2129b3e0a9
                cp-replica-d90ac860-47d3-46eb-bde5-dccf16025e27
                        cp-parent-a66fc46d-d403-41a8-848b-88203aec299b
                        cp-parent-46bce3fe-63f8-41fc-a5f7-409d360c4b97
                cp-replica-24705be4-3104-4419-b906-d7b72aee9da7
                        cp-parent-320ff1de-23e2-476e-a735-4997a95e5368
                        cp-parent-4bs00f66-3888-4ffc-9e97-48485dd4ce2c

I copied the list and run through each cp-parent VM and its Tasks & Events to understand more about the cloning failed problem. But oddly none of the cp-parent VMs contained a recent cloning action (not even a failure that I expected). I have noticed two of the cp-parent VMs were offline and there was not a snapshot on it which is also strange. So apparently the cloning is not even starting..

I wanted to understand if the pool is able to handle other actions such as Infrastructure Change (triggered by changes of datastores mapped to the pool) or push image process. Also I wanted to isolate the issue a little further, so I edited the Pool and removed all datastores apart from 3. This triggered the infra change which is usually a quick activity when it is only about removal. (In the backend it will attempt to remove cp-replica VMs from Datastores that are no more in use). In my case it was everything but not quick. I went to our syslog solution to understand what the task is doing.

My first search was:

<Pool Name> publish* image

With this I retrieved the PendingOperation task:

PendingOperation-vm-1822770:snapshot-1822951-InfrastructureChange

This task stuck at 0% and eventually failed and restarted itself… and guess what: failed again:

2024-02-08T15:10:04.091+01:00 ERROR (1B88-3394) [NgvcHelper] Unprime of pool <Pool Name> has failed. Timed out waiting for operation to complete. Total time waited 30 mins

So I went through the logs of this PendingOperation and noticed some events in which the instanceUUID of the Master VM was posted, so I went on and searched for it to see if there are some related events:

2024-02-08T14:09:43.813+01:00 DEBUG (1B88-3394) [VcCache] Getting virtual machine object for instanceUUID 5009cba1-bfb4-97f4-c957-3b5c7a760b65

And finally I found what I was hoping for, a task that was blocking everything:

2024-02-08T14:49:28.391+01:00 DEBUG (1B88-2F34) [LockManager] Task: ede1be65-08c6-4f41-8088-63681343ded3 is being BLOCKED because the needed lock combination: InternalVmLookupTask:Combination [lockGuid=ImageLinks-master.uuid=5009cba1-bfb4-97f4-c957-3b5c7a760b65&ss.id=1, type=READ] is currently owned by task: 37b6b3d1-8068-4247-83fc-4d7c827299be

I was able to link this task to a vCenter action “DisableDrsHaAction” which was a hanging operation on the Cluster that stuck at 0% greyed out…

So, finally the vCenter was restarted to kill this task. After the restart everything went on in the normal way.

I want to point out that this is not the only reason/trigger for such behaiovur within a Horizon environment. I saw situations in which a internal horizon VM got unprotected (usually they are protected and you cannot modify it) and moved by DRS to other datastores which caused the cloning operations to fail also. Or other situations in which the underlying storage system failed and internal horizon VMs got invalid. I hope this post can give you and idea how to start the troubleshooting when hitting such mess. The key is to have syslogs stored externally and to have debug log information enabled on Horizon side.