vMotion failing for large VMs with "failed to get DVS state in the restore phase" error on VMs backed by NSX segments

Products

• VMware NSX

Issue/Introduction

vMotion failures occur when migrating large VMs backed by NSX segments, and expected to take several hours or longer to complete. The migration eventually failed with the error message: "failed to get DVS state in the restore phase."

 

From the destination ESXi host's vmkernel.log under /var/run/log reports unable to find dvport from the VDS. Please refer to the log snippet below.

 

YYYY-MM-DDTHH:MM:SS.SSSZ -INFO vmkernel - [esx@##13] cpu58:######86)VMotionUtil: ##20: #################78 D: Starting VMOTION_STREAM_PRECOPY. sendStart: FALSE
YYYY-MM-DDTHH:MM:SS.SSSZ -WARNING vmkwarning - [esx@##13] cpu115:######85) NetDVS: ##97: Failed to find dvport by ConnecteeKey ########-####-####-####-##########9a
YYYY-MM-DDTHH:MM:SS.SSSZ -WARNING vmkwarning - [esx@##13] cpu115:######85) NetDVS: ##39: Acquire dvs lock ## ## ## ## ## ## ## ##-## ## ## ## ## ## 65 50 failed, j = 0: Not found
YYYY-MM-DDTHH:MM:SS.SSSZ -WARNING vmkwarning - [esx@##13] cpu115:######85) VMotionSend: ##65: #################78 D: failed to get DVS state in the restore phase from the source host <IP address>
YYYY-MM-DDTHH:MM:SS.SSSZ -WARNING vmkwarning - [esx@##13] cpu115:23379485) VMotionSend: ##65: #################78 D: Failed handling message reply GET_DVS_STATE: Not found
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO vmkernel - [esx@##13] cpu115:######85)Migrate: 100: #################78 D: MigrateState: Failed

 

The nsx-syslog located at /var/run/log reports that while the destination DVS was found, it failed to locate the port with the associated VIF. Please refer to the log snippet below.

 

YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] Searching through vmx dir
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] Found DVS:[## ## ## ## ## ## ## ##-## ## ## ## ## ## b0 37]
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] Could not find port/vif
YYYY-MM-DDTHH:MM:SS.SSSZ -ERROR nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" errorCode="MPA42004" threadID="######77"] [DoVifPortOperation] Failed to find port with vif [########-####-####-####-##########9b] vmxPath [<path to vmx for the VM>]
YYYY-MM-DDTHH:MM:SS.SSSZ -WARNING nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] Error getting port status for port [########-####-####-####-##########dd] in dvs []
YYYY-MM-DDTHH:MM:SS.SSSZ -WARNING nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] Error getting port file info for port [########-####-####-####-##########dd] in dvs []
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] PortStatus portFilePathOnPort portFilePathRequest <path to vmx for the VM>
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [DoVifPortOperation] Clearing VIF [########-####-####-####-##########9b] from port [########-####-####-####-##########dd] even though MP did not return VIF
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] tzId:[########-####-####-####-##########80] dvsId:[## ## ## ## ## ## ## ##-## ## ## ## ## ## b0 37] lportId:[########-####-####-####-##########dd] vifId:[########-####-####-####-##########9b] forceFind:[1]
YYYY-MM-DDTHH:MM:SS.SSSZ -WARNING nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] Port [########-####-####-####-##########dd] state get failed, error code [bad0003], looking at all switches to clear VIF ########-####-####-####-##########9b
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [DoVifPortOperation] Successfully cleared external id from the port [########-####-####-####-##########dd]
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [removeVifFromCache] vif:[########-####-####-####-##########9b] cleared from vifsInProcess

 

Earlier log events shows the attach call on the destination host was created successfully during the migration process.

YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [DoVifPortOperation] request=[opId:[ms2qisac-#####58-auto-1xx9b-h5:########-##-##-##-##-##-####-51] op:[HOSTD_ATTACH_PORT(1)] vif:[{*}########-####-####-####-##########9b{*}] ls:[########-####-####-####-##########ea] vmx:[<path to vmx for the VM>] lp:[]]\n
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="mpa-client" threadID="#####82"] [SwitchingVertical] MpaClientHostService Received: Publish msg, type (com.vmware.nsx.switching.VifMsg) corelationId (########-####-####-####-##########54) trackingId (########-####-####-####-##########54) from APH (########-####-####-####-##########d1)
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] Set port backing type to nsx for VDS
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] Successfully created port [{*}########-####-####-####-##########dd{*}]
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] Adding [com.vmware.port.extraConfig.vnic.external.id] value [########-####-####-####-##########9b]
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] Successfully updated port [########-####-####-####-##########dd] with extraConfig [com.vmware.port.extraConfig.vnic.external.id]
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] Adding [com.vmware.port.extraConfig.opaqueNetwork.id] value [########-####-####-####-##########ea]
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsx-opsagent ######35 [nsx@4413 comp="nsx-esx" subcomp="opsagent" s2comp="nsxa" threadID="######77"] [PortOp] Successfully updated port [########-####-####-####-##########dd] with extraConfig [com.vmware.port.extraConfig.opaqueNetwork.id] 

 

The nsxaVim.log file under /var/run/log indicates that the re-sync process deleted the port '########-####-####-####-##########dd' before the migration was completed.

 

YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsxaVim - [esx@##13] [25368960]: INFO [resync] deleting 2 unused dvports on vds ## ## ## ## ## ## ## ##-## ## ## ## ## ## b0 37
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsxaVim - [esx@##13] [25368960]: INFO [resync] Resync result: port2delete=[2] port2detach=[0] vnic2attach=[0] stalePortFile2delete=[0]
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsxaVim - [esx@##13] [25368960]: INFO [resync] Following ports were deleted
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsxaVim - [esx@##13] [25368960]: INFO [resync] ########-####-####-####-##########f8
YYYY-MM-DDTHH:MM:SS.SSSZ -INFO nsxaVim - [esx@##13] [25368960]: INFO [resync] ########-####-####-####-##########dd

Environment

VMware NSX 9.1.0

Cause

This issue occurred because large VM can take a long time to complete the migration. Although the port was successfully created on the destination host, the resync process cleans up unused ports at regular intervals if it identifies ports that are not in use.

Resolution

To prevent ports from being cleaned up while the VM is being migrated, increase the cleanup task check frequency from 1 hour to 200 hours on the destination ESXi host by following these steps:

1. Edit the file nsxa.json:
   
   vi /etc/vmware/nsx-opsagent/nsxa.json
   
   Change
   
   "vmCheckFrequency" : 1,
   
   to
   
   "vmCheckFrequency" : 200,
   
   
2. Restart the agent:
   
   /etc/init.d/nsx-opsagent restart