Move-VM The request channel timed out while waiting for a reply after 00:05:00

[Lug77]

I'm running a Move-VM command to move a VM from an NFS mount to a VSAN datastore and I'm getting this error.

Move-VM        The request channel timed out while waiting for a reply after

00:05:00. Increase the timeout value passed to the call to Request or increase the SendTimeout value on the Binding.

The time allotted to this operation may have been a portion of a longer timeout.

The task still continues and completes fine in vCenter, just PowerCLI times out.  Environment is PowerCLI 6.5 and PowerShell 5.0.  ESXi 6.5 GA. 

Anyone know how to increase this timeout?

BTW, Previously when I've ran this migration it worked fine with PowerCLI 5.5 and PowerShell 4.0.  Also, in that scenario I was migrating from an NFS mount to a regular VMFS datastore.

Here's the actual syntax of the command.

$DestDS =  get-vmhost "vmhostname" | Get-Datastore -Name "*vsan*"

$vmobj = get-vm "vmname"

$vmobj | Move-VM -Datastore $DestDS -ErrorAction:Stop

[LucD]

Did you already try to disable the timeout with the Set-PowerCLIConfiguration cmdlet and the WebOperationTimeoutSeconds parameter?

[Lug77]

I have not, but I will.  Thanks for the tip.  I will update with results but won't likely have any news until next month.

[LucD]

Take note of the Scope parameter when you use the cmdlet.

[Lug77]

I set the WebOperationTimeoutSeconds to -1 (so it would be an infinite timeout) and it broke Get-TagAssigment.  I returned it to the default value of 300 and Get-TagAssignment works again.  I'll do more testing with just larger timeouts rather than infinite.  Scope was set to AllUsers as the script will be ran by multiple users on the system.

[LucD]

Do a Get-PowerCLIConfiguration, just to check the scopes.

It takes session - user - allusers, in that order.

[Lug77]

Session and AllUsers both changed when I set it to -1 and when I reverted it to 300.

[Lug77 · Accepted solution]

I've set it to a 3600 sec for AllUsers and the process is working well now.  Get-TagAssignment also works.

[lorried82]

Hi LucD - I am getting this same error but in only 1 of my clusters. The command I am using is to create a new vm based

example

New-VM -Name $VMName -Template $SourceVMTemplate -ResourcePool $TargetCluster -OSCustomizationSpec $spec -Datastore $datastore -Description $notes

I tried changing the timeout but that did nothing - it is so strange it is just when I try to create a new-VM in a specific resourcePool, it works for all the other Resource Pools. Am I missing something?

appreciate any feedback!

Thanks

[LucD]

When it's not the timeout, there must be another cause.
Can you check the contents of the vpxd log at the time of the issue, to see if there are any pointers in there?

[lorried82]

The only think in the vpxa.log is below

When I run the same script in another cluster and tail that log I see logs like below

2018-04-10T12:29:05.279Z info vpxa[418E4B70] [Originator@6876 sub=vpxLro opID=3e23c0da-bf-9a] [VpxLRO] -- BEGIN task-internal-172037 -- vpxa -- vpxapi.VpxaService.reserveName -- 52be3915-9d2e-7326-94b9-7a5bd0de8b1d

2018-04-10T12:29:05.279Z verbose vpxa[418E4B70] [Originator@6876 sub=vpxaDatastoreContext opID=3e23c0da-bf-9a] [VpxaDatastoreContext] Resolved URL ds:///vmfs/volumes/55760251-82d6abd2-3909-00215ec43b80/ to localPath /vmfs/volumes/55760251-82d6abd2-3909-00215ec43b80/

vpax.log from host that is in cluster I can't create-vm

-10T12:29:23.935Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-75263aef] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:23.935Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-75263aef] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:25.774Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-20e75cff] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:25.774Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-20e75cff] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600365 to 7600366 (at 7600365)

2018-04-10T12:29:25.774Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdvm opID=WFU-20e75cff] [VpxaHalVmHostagent] 1756: GuestInfo changed 'guest.disk'

2018-04-10T12:29:25.774Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=halservices opID=WFU-20e75cff] [VpxaHalServices] VmGuestDiskChange Event for vm(1757) 1756

2018-04-10T12:29:25.774Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=vpxaInvtVm opID=WFU-20e75cff] [VpxaInvtVmChangeListener] Guest DiskInfo Changed

2018-04-10T12:29:25.774Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-20e75cff] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:25.774Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-20e75cff] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:25.777Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-358a7a39] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:25.777Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-358a7a39] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600366 to 7600367 (at 7600366)

2018-04-10T12:29:25.777Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-358a7a39] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:25.777Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-358a7a39] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:27.395Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1512 (vpxa VM id), 26096 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.396Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1559 (vpxa VM id), 25957 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.397Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1672 (vpxa VM id), 26106 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.399Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1689 (vpxa VM id), 29520 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.400Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1728 (vpxa VM id), 1612 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.401Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1738 (vpxa VM id), 37463 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.402Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1747 (vpxa VM id), 27815 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.403Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1757 (vpxa VM id), 1802 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.405Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1763 (vpxa VM id), 184526 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.406Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1770 (vpxa VM id), 16201 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.407Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1772 (vpxa VM id), 26101 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.408Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1774 (vpxa VM id), 26515 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.409Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1775 (vpxa VM id), 1331 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.411Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1776 (vpxa VM id), 1322 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.412Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1777 (vpxa VM id), 28615 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:27.413Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1778 (vpxa VM id), 1313 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:28.001Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-165e4fa5] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:28.001Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-165e4fa5] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600367 to 7600368 (at 7600367)

2018-04-10T12:29:28.001Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-165e4fa5] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:28.002Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-165e4fa5] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:32.284Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-9bee51c] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:32.284Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-9bee51c] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600368 to 7600369 (at 7600368)

2018-04-10T12:29:32.284Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdvm opID=WFU-9bee51c] [VpxaHalVmHostagent] 1769: GuestInfo changed 'guest.disk'

2018-04-10T12:29:32.284Z verbose vpxa[34DCEB70] [Originator@6876 sub=halservices opID=WFU-9bee51c] [VpxaHalServices] VmGuestDiskChange Event for vm(1770) 1769

2018-04-10T12:29:32.284Z verbose vpxa[34DCEB70] [Originator@6876 sub=vpxaInvtVm opID=WFU-9bee51c] [VpxaInvtVmChangeListener] Guest DiskInfo Changed

2018-04-10T12:29:32.284Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-9bee51c] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:32.284Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-9bee51c] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:33.420Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-53b39643] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:33.420Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-53b39643] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600369 to 7600370 (at 7600369)

2018-04-10T12:29:33.420Z verbose vpxa[34DADB70] [Originator@6876 sub=hostdvm opID=WFU-53b39643] [VpxaHalVmHostagent] 1688: GuestInfo changed 'guest.disk'

2018-04-10T12:29:33.420Z verbose vpxa[34DADB70] [Originator@6876 sub=halservices opID=WFU-53b39643] [VpxaHalServices] VmGuestDiskChange Event for vm(1689) 1688

2018-04-10T12:29:33.420Z verbose vpxa[34DADB70] [Originator@6876 sub=vpxaInvtVm opID=WFU-53b39643] [VpxaInvtVmChangeListener] Guest DiskInfo Changed

2018-04-10T12:29:33.420Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-53b39643] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:33.420Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-53b39643] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:33.423Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-334e33a3] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:33.423Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-334e33a3] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600370 to 7600371 (at 7600370)

2018-04-10T12:29:33.423Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-334e33a3] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:33.423Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-334e33a3] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:35.208Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-53202ca5] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:35.208Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-53202ca5] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600371 to 7600372 (at 7600371)

2018-04-10T12:29:35.208Z verbose vpxa[34DCEB70] [Originator@6876 sub=hostdvm opID=WFU-53202ca5] [VpxaHalVmHostagent] 1762: GuestInfo changed 'guest.disk'

2018-04-10T12:29:35.208Z verbose vpxa[34DCEB70] [Originator@6876 sub=halservices opID=WFU-53202ca5] [VpxaHalServices] VmGuestDiskChange Event for vm(1763) 1762

2018-04-10T12:29:35.208Z verbose vpxa[34DCEB70] [Originator@6876 sub=vpxaInvtVm opID=WFU-53202ca5] [VpxaInvtVmChangeListener] Guest DiskInfo Changed

2018-04-10T12:29:35.208Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-53202ca5] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:35.208Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-53202ca5] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:35.210Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-65532f45] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:35.210Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-65532f45] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600372 to 7600373 (at 7600372)

2018-04-10T12:29:35.210Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-65532f45] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:35.211Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-65532f45] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:42.048Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-38448efb] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:42.048Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-38448efb] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600373 to 7600374 (at 7600373)

2018-04-10T12:29:42.048Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-38448efb] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:42.048Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-38448efb] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:43.438Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-1d071d99] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:43.438Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-1d071d99] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600374 to 7600375 (at 7600374)

2018-04-10T12:29:43.438Z verbose vpxa[34DADB70] [Originator@6876 sub=hostdvm opID=WFU-1d071d99] [VpxaHalVmHostagent] 1727: GuestInfo changed 'guest.disk'

2018-04-10T12:29:43.438Z verbose vpxa[34DADB70] [Originator@6876 sub=halservices opID=WFU-1d071d99] [VpxaHalServices] VmGuestDiskChange Event for vm(1728) 1727

2018-04-10T12:29:43.438Z verbose vpxa[34DADB70] [Originator@6876 sub=vpxaInvtVm opID=WFU-1d071d99] [VpxaInvtVmChangeListener] Guest DiskInfo Changed

2018-04-10T12:29:43.438Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-1d071d99] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:43.438Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-1d071d99] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:43.443Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-3e2836b2] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:43.443Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-3e2836b2] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600375 to 7600376 (at 7600375)

2018-04-10T12:29:43.443Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-3e2836b2] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:43.443Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-3e2836b2] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:45.355Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-421effff] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:45.355Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-421effff] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600376 to 7600377 (at 7600376)

2018-04-10T12:29:45.355Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-421effff] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:45.356Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-421effff] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:47.166Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-138e043] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:47.166Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-138e043] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600377 to 7600378 (at 7600377)

2018-04-10T12:29:47.166Z verbose vpxa[34DADB70] [Originator@6876 sub=hostdvm opID=WFU-138e043] [VpxaHalVmHostagent] 1774: GuestInfo changed 'guest.disk'

2018-04-10T12:29:47.166Z verbose vpxa[34DADB70] [Originator@6876 sub=halservices opID=WFU-138e043] [VpxaHalServices] VmGuestDiskChange Event for vm(1775) 1774

2018-04-10T12:29:47.166Z verbose vpxa[34DADB70] [Originator@6876 sub=vpxaInvtVm opID=WFU-138e043] [VpxaInvtVmChangeListener] Guest DiskInfo Changed

2018-04-10T12:29:47.166Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-138e043] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:47.166Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-138e043] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:47.171Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-3d0b4f55] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:47.171Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-3d0b4f55] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600378 to 7600379 (at 7600378)

2018-04-10T12:29:47.171Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-3d0b4f55] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:47.171Z verbose vpxa[34DCEB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-3d0b4f55] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:47.401Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1512 (vpxa VM id), 26096 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.402Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1559 (vpxa VM id), 25957 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.404Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1672 (vpxa VM id), 26106 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.405Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1689 (vpxa VM id), 29520 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.406Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1728 (vpxa VM id), 1612 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.407Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1738 (vpxa VM id), 37463 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.408Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1747 (vpxa VM id), 27815 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.410Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1757 (vpxa VM id), 1802 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.411Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1763 (vpxa VM id), 184526 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.412Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1770 (vpxa VM id), 16201 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.413Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1772 (vpxa VM id), 26101 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.414Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1774 (vpxa VM id), 26515 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.415Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1775 (vpxa VM id), 1331 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.416Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1776 (vpxa VM id), 1322 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.418Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1777 (vpxa VM id), 28615 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:47.419Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=hostdstats] Set internal stats for VM: 1778 (vpxa VM id), 1313 (vpxd VM id). Is FT primary? false

2018-04-10T12:29:48.177Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-318574c2] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:48.177Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-318574c2] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600379 to 7600380 (at 7600379)

2018-04-10T12:29:48.177Z verbose vpxa[34DADB70] [Originator@6876 sub=hostdvm opID=WFU-318574c2] [VpxaHalVmHostagent] 1737: GuestInfo changed 'guest.disk'

2018-04-10T12:29:48.177Z verbose vpxa[34DADB70] [Originator@6876 sub=halservices opID=WFU-318574c2] [VpxaHalServices] VmGuestDiskChange Event for vm(1738) 1737

2018-04-10T12:29:48.177Z verbose vpxa[34DADB70] [Originator@6876 sub=vpxaInvtVm opID=WFU-318574c2] [VpxaInvtVmChangeListener] Guest DiskInfo Changed

2018-04-10T12:29:48.177Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-318574c2] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:48.177Z verbose vpxa[34DADB70] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-318574c2] [WaitForUpdatesDone] Completed callback

2018-04-10T12:29:49.137Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-30b485f4] [WaitForUpdatesDone] Received callback

2018-04-10T12:29:49.137Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-30b485f4] [VpxaHalCnxHostagent::ProcessUpdate] Applying updates from 7600380 to 7600381 (at 7600380)

2018-04-10T12:29:49.137Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-30b485f4] [WaitForUpdatesDone] Starting next WaitForUpdates() call to hostd

2018-04-10T12:29:49.137Z verbose vpxa[FFDEAAE0] [Originator@6876 sub=VpxaHalCnxHostagent opID=WFU-30b485f4] [WaitForUpdatesDone] Completed callback

[LucD]

There doesn't seem to be any information on the createion fo a new VM in that log extract.

When you create the VM (from a Template) from the Web Client, does it work in that case?

[lorried82]

No that doesn't work either - via the Web Client or the Fat Client - it reads LOADING when it is on the last step - Ready to Complete

Look like the fat client finally error'd out - Call "StorageResourceManager.RecommendDatastores" for object "StorageResourceManager" on vCenter Server "<redacted>" failed.

When I try and look at events/task for the Datastore_cluster I get the message below

Call "TaskManager.CreateCollector" for object "TaskManager" on vCenter Server "<redacted>" failed.

[LucD]

That looks more like another issue.

Some things you might try:

• remove & add the ESXi nodes from/to the cluster
• restart your VCSA (if possible)
• create a new cluster, and move all the ESXi nodes to that new cluster

Ultimately you could open a SR for this.

[lorried82]

ok thanks LucD

[lorried82]

we restarted vCenter and this issue is now resolved. I am going to be opening up an SR for this since I don't understand why this would only be an issue at the cluster level.

Thanks again for all your help!

[hanxiao33]

Pls supply the whole step, 3ks