VMware VIew - Customization operation timed out when we launch linked clone Recompose

[XaviGG]

Hello,

We have VMware Horizon View 5.2.0 infrastructure and we have created some different pools because we needed to migrate the previous production pools (from QuickPrep Guest Customization to Sysprep Guest Customization, due to a KMS host for Windows and Office licenses perfectly working).

Well...

Now we have an issue because when we launch a Recompose to any Linked Clone belonging to the new pools, we can be in three states:

1- Recompose is done perfectly.

2- Recompose stops with an state Customization operation timed out

3- Recompose shows an error "Customization operation timed out" but later continues and finishes the task.

We have modified the Register key "HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\services\vmware-viewcomposer-ga\ExecScriptTimeout REG_WORD" from the Windows 7 with SP1 template to increase timeout from 20000ms to 999999ms.

We have applied the Microsoft hotfix to the Windows 7 template because we have installaled VMXNET3 NIC.

"A fatal error occurred" error message when you run the Sysprep command on a VMware virtu...

So, we are suffering the same situations.

Anybody could help us? Any idea?

Many thanks

[XaviGG]

Nobody knows?

[Linjo]

Do you see exactly the error-messages that is listed in the MS KB-article?

// Linjo

[XaviGG]

No, just the VM stops with an error "Customization operation timed out". Sometimes continues succesfully, sometimes the task is stuck in that state.

[Linjo]

There should be some errors in the logs, could you post those?

[XaviGG]

Of course. I have launched one Recompose task minutes ago. It finished succesfully, but during some minutes, it showed an error state.

Here the View Composer log:

2013-11-26 09:54:49,229 | 34            | INFO  | ServiceCore.LockManager.LockManager - A lock is requested for VcConfigEntry with id: de76d4d9-5ef8-4035-83aa-6abda0bb06be

2013-11-26 09:54:49,370 | 34            | INFO  | CommonLib.Security.CertificateValidation - VC service certificate subject: "E=support@vmware.com, CN=VMware default certificate, OU="VMware, Inc.", O="VMware, Inc."", issuer name: "O=VMware Installer", valid from 11/11/2010 18:45:42 to 08/11/2020 18:45:42. Policy errors: RemoteCertificateNameMismatch, RemoteCertificateChainErrors.

2013-11-26 09:54:49,370 | 34            | INFO  | CommonLib.Security.CertificateValidation - Found the matched certificate thumbprint.

2013-11-26 09:54:49,822 | 34            | INFO  | CommonLib.Util.Util - Will retry after 0 seconds. The retry number is 1.

2013-11-26 09:54:49,822 | 34            | FATAL | CommonLib.VcSubsystem.VcUtil - VC connection exception. Will try to reconnect.

VMware.Sim.CommonLib.Exception.SimVcConnectionException: Error en la aplicación.

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.RetrieveProperties(PropertyFilterSpec[] specs)

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.VcMethod`1.Invoke()

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.VcExceptionHandler`1.Invoke(), Machine Name: viewc, Timestamp: 26/11/2013 8:54:49, App Domain Name: SviWebService.exe, Thread Identity: , Windows Identity: NT AUTHORITY\SYSTEM, OS Version: Microsoft Windows NT 6.1.7601 Service Pack 1, detail information: VC session timed-out during RetrieveProperties call, Configuration ID: de76d4d9-5ef8-4035-83aa-6abda0bb06be

2013-11-26 09:54:49,853 | 34            | INFO  | CommonLib.VcSubsystem.VimClientConnection - Unable either to logout from url: https://viewc.xxxxxx.net:443/sdk with username: xxxxxx\administrator or to dispose the connection.

System.Web.Services.Protocols.SoapException: The session is not authenticated.

   en System.Web.Services.Protocols.SoapHttpClientProtocol.ReadResponse(SoapClientMessage message, WebResponse response, Stream responseStream, Boolean asyncCall)

   en System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters)

   en VimApi.InternalVimService.Logout(ManagedObjectReference _this)

   en VMware.Sim.CommonLib.VcSubsystem.VimClientConnection.Disconnect()

2013-11-26 09:54:49,869 | 34            | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Unable to free up the vc connection.

System.Web.Services.Protocols.SoapException: The session is not authenticated.

   en System.Web.Services.Protocols.SoapHttpClientProtocol.ReadResponse(SoapClientMessage message, WebResponse response, Stream responseStream, Boolean asyncCall)

   en System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters)

   en VimApi.InternalVimService.Logout(ManagedObjectReference _this)

   en VMware.Sim.CommonLib.VcSubsystem.VimClientConnection.Disconnect()

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.Disconnect()

2013-11-26 09:54:49,869 | 34            | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Reconnect called to create a new connection to VC https://viewc.xxxxxx.net:443/sdk and user xxxxxx\administrator.

2013-11-26 09:54:50,353 | 34            | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Successfuly connected to the VC server at: https://viewc.xxxxxx.net:443/sdk with user: xxxxxx\administrator

2013-11-26 09:54:50,493 | 34            | INFO  | ServiceCore.LockManager.LockManager - A release is requested for VcConfigEntry with id: de76d4d9-5ef8-4035-83aa-6abda0bb06be

2013-11-26 09:56:24,562 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - MoveSviClones called for 1 SVI clones with Ids: 8a827f0c-da82-4eba-9739-f5addaf40ec9.

2013-11-26 09:56:24,780 | 34            | INFO  | ServiceCore.LockManager.LockManager - A lock is requested for DeploymentGroup with id: b1377cc9-6908-4449-a099-c10ab94595b7

2013-11-26 09:56:24,780 | 34            | INFO  | ServiceCore.LockManager.LockManager - Multiple lock are required for SimClone with ids: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:24,780 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - Operation MoveSviClones locked clones.

RequestId: MoveSviClones-c7a15e4e-0bd8-4228-aa83-034ac6a1294f

CloneId[0]: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:24,827 | 34            | INFO  | ServiceCore.LockManager.LockManager - Multiple releases are required for SimClone with ids: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:24,827 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - Operation MoveSviClones released clones.

RequestId: MoveSviClones-c7a15e4e-0bd8-4228-aa83-034ac6a1294f

CloneId[0]: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:24,827 | 34            | INFO  | ServiceCore.LockManager.LockManager - A release is requested for DeploymentGroup with id: b1377cc9-6908-4449-a099-c10ab94595b7

2013-11-26 09:56:25,903 | 34            | INFO  | ServiceCore.LockManager.LockManager - A lock is requested for DeploymentGroup with id: b1377cc9-6908-4449-a099-c10ab94595b7

2013-11-26 09:56:25,981 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - ResyncSviClones called for deployment group b1377cc9-6908-4449-a099-c10ab94595b7, for 1 clones, with resync spec replication datastore MoID = , force resync = True. CloneIds: 8a827f0c-da82-4eba-9739-f5addaf40ec9. Filed as request id 81965110-6767-47c1-ab2b-581694602fa2.

2013-11-26 09:56:25,997 | 34            | INFO  | ServiceCore.LockManager.LockManager - A lock is requested for AdConfigEntry with id: c9cd0a16-929d-448b-9a13-50969821f6b7

2013-11-26 09:56:25,997 | 34            | INFO  | ServiceCore.LockManager.LockManager - A lock is requested for VcConfigEntry with id: de76d4d9-5ef8-4035-83aa-6abda0bb06be

2013-11-26 09:56:25,997 | 34            | INFO  | ServiceCore.LockManager.LockManager - Multiple lock are required for SimClone with ids: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:25,997 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - Operation ResyncSviClones locked clones.

RequestId: 81965110-6767-47c1-ab2b-581694602fa2

CloneId[0]: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:26,824 | 34            | INFO  | ServiceCore.Action.UfaInitializeDiskAction - Created an UfaInitializeDiskAction with total disks 1.

2013-11-26 09:56:26,870 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - Received a request to resync 1 clones for deployment group b1377cc9-6908-4449-a099-c10ab94595b7. Filed as request id 81965110-6767-47c1-ab2b-581694602fa2

2013-11-26 09:56:26,870 | WFE thread 1  | INFO  | ServiceCore.WorkflowEngine.SingleCloneTask - Task 52c15504-df3f-49fb-b6d9-6ce0e52aa270 is set with non-cancellable.

2013-11-26 09:56:27,198 | WFE thread 8  | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Long run task. Request ID: 81965110-6767-47c1-ab2b-581694602fa2. Task MOID: task-2852815.

2013-11-26 09:56:27,229 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks is signaled to poll.

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.Util.Util - Will retry after 0 seconds. The retry number is 1.

2013-11-26 09:56:27,245 | VC thread     | FATAL | CommonLib.VcSubsystem.VcUtil - ManagedObjectNotFoundFault fault was thrown by the VC server.

System.Web.Services.Protocols.SoapException: The object has already been deleted or has not been completely created

   en System.Web.Services.Protocols.SoapHttpClientProtocol.ReadResponse(SoapClientMessage message, WebResponse response, Stream responseStream, Boolean asyncCall)

   en System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters)

   en VimApi.InternalVimService.ModifyListView(ManagedObjectReference _this, ManagedObjectReference[] add, ManagedObjectReference[] remove)

   en VMware.Sim.CommonLib.VcSubsystem.PropertyCollectorUpdateTracker.<UpdateListView>b__5()

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.VcMethod`1.Invoke()

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.VcExceptionHandler`1.Invoke()

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Got SimVcSubsystemException ManagedObjectNotFoundFault fault was thrown by the VC server: https://viewc.xxxxxx.net:443/sdk..

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - ListViewRef: session[86f6c4ec-a2dd-86d1-b423-16d0a21e5c4d]52add3bb-6db3-de01-0d41-11ac6d76a33e

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Task in list: task-2852815

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Added task: task-2852815

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Session timed out. Need to create a new ListView.

2013-11-26 09:56:28,493 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Task Task:task-2852815 completed. Removing it from list. The number of tasks to be monitored is reduced to 0.

2013-11-26 09:56:28,493 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks waits for signaling to poll.

2013-11-26 09:56:29,616 | WFE thread 6  | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Long run task. Request ID: 81965110-6767-47c1-ab2b-581694602fa2. Task MOID: task-2852816.

2013-11-26 09:56:29,616 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks is signaled to poll.

2013-11-26 09:56:30,926 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Task Task:task-2852816 completed. Removing it from list. The number of tasks to be monitored is reduced to 0.

2013-11-26 09:56:30,926 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks waits for signaling to poll.

2013-11-26 09:56:31,238 | WFE thread 1  | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Long run task. Request ID: 81965110-6767-47c1-ab2b-581694602fa2. Task MOID: task-2852817.

2013-11-26 09:56:31,238 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks is signaled to poll.

2013-11-26 09:56:33,438 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Task Task:task-2852817 completed. Removing it from list. The number of tasks to be monitored is reduced to 0.

2013-11-26 09:56:33,438 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks waits for signaling to poll.

2013-11-26 09:56:33,641 | WFE thread 2  | INFO  | ServiceCore.ActiveDirectory.AdUtil - AD account vdi-xxx-xxx-1 under same ownership or using existing account will be moved.

2013-11-26 09:56:34,936 | UFA main thread 3 | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Getting NFC ticket for disk 2018 in vm vm-60533

2013-11-26 09:56:34,967 | UFA main thread 3 | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Recevied the NFC ticket for disk 2018 in vm vm-60533 from VC.

2013-11-26 09:56:34,967 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.UfaWorkItem - UFA: issuing disk connection request for disk: datastore: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk, host: hvdi2.xxxxxx.net, port: 902.

2013-11-26 09:56:36,121 | UFA main thread 3 | INFO  | CommonLib.Security.CertificateValidation - No certificate for local request. URL is https://localhost:50531/.

2013-11-26 09:56:37,104 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.GetDiskSignatureUfaWorkItem - UFA: finish getting disk signature for disk: datastore: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk, host: hvdi2.xxxxxx.net, port: 902 successfully.

2013-11-26 09:56:37,120 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.InitializeDiskSetUfaWorkItem - CompletionCallbackProxy: finished init disk: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk.

2013-11-26 09:56:37,120 | UFA main thread 3 | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Getting NFC ticket for disk 2018 in vm vm-60533

2013-11-26 09:56:37,135 | UFA main thread 3 | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Recevied the NFC ticket for disk 2018 in vm vm-60533 from VC.

2013-11-26 09:56:37,135 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.UfaWorkItem - UFA: issuing disk connection request for disk: datastore: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk, host: hvdi2.xxxxxx.net, port: 902.

2013-11-26 09:56:37,588 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.InitializeDiskUfaWorkItem - UFA: skip partition and format on the disk: datastore: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk, host: hvdi2.xxxxxx.net, port: 902.

2013-11-26 09:56:37,915 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.InitializeDiskUfaWorkItem - UFA: finish init disk operation for disk: datastore: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk, host: hvdi2.xxxxxx.net, port: 902 successfully.

2013-11-26 09:56:38,071 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.InitializeDiskSetUfaWorkItem - CompletionCallbackProxy: finished init disk: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk.

2013-11-26 09:56:38,118 | WFE thread 5  | INFO  | ServiceCore.LockManager.LockManager - Multiple releases are required for SimClone with ids: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:38,118 | WFE thread 5  | INFO  | Sim.ServiceCore.SimServiceApiImpl - Operation ResyncSviClones released clones.

RequestId: 81965110-6767-47c1-ab2b-581694602fa2

CloneId[0]: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:38,118 | WFE thread 5  | INFO  | ServiceCore.LockManager.LockManager - A release is requested for DeploymentGroup with id: b1377cc9-6908-4449-a099-c10ab94595b7

2013-11-26 09:56:38,118 | WFE thread 5  | INFO  | ServiceCore.LockManager.LockManager - A release is requested for AdConfigEntry with id: c9cd0a16-929d-448b-9a13-50969821f6b7

2013-11-26 09:56:38,118 | WFE thread 5  | INFO  | ServiceCore.LockManager.LockManager - A release is requested for VcConfigEntry with id: de76d4d9-5ef8-4035-83aa-6abda0bb06be

2013-11-26 09:54:49,229 | 34            | INFO  | ServiceCore.LockManager.LockManager - A lock is requested for VcConfigEntry with id: de76d4d9-5ef8-4035-83aa-6abda0bb06be

2013-11-26 09:54:49,370 | 34            | INFO  | CommonLib.Security.CertificateValidation - VC service certificate subject: "E=support@vmware.com, CN=VMware default certificate, OU="VMware, Inc.", O="VMware, Inc."", issuer name: "O=VMware Installer", valid from 11/11/2010 18:45:42 to 08/11/2020 18:45:42. Policy errors: RemoteCertificateNameMismatch, RemoteCertificateChainErrors.

2013-11-26 09:54:49,370 | 34            | INFO  | CommonLib.Security.CertificateValidation - Found the matched certificate thumbprint.

2013-11-26 09:54:49,822 | 34            | INFO  | CommonLib.Util.Util - Will retry after 0 seconds. The retry number is 1.

2013-11-26 09:54:49,822 | 34            | FATAL | CommonLib.VcSubsystem.VcUtil - VC connection exception. Will try to reconnect.

VMware.Sim.CommonLib.Exception.SimVcConnectionException: Error en la aplicación.

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.RetrieveProperties(PropertyFilterSpec[] specs)

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.VcMethod`1.Invoke()

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.VcExceptionHandler`1.Invoke(), Machine Name: viewc, Timestamp: 26/11/2013 8:54:49, App Domain Name: SviWebService.exe, Thread Identity: , Windows Identity: NT AUTHORITY\SYSTEM, OS Version: Microsoft Windows NT 6.1.7601 Service Pack 1, detail information: VC session timed-out during RetrieveProperties call, Configuration ID: de76d4d9-5ef8-4035-83aa-6abda0bb06be

2013-11-26 09:54:49,853 | 34            | INFO  | CommonLib.VcSubsystem.VimClientConnection - Unable either to logout from url: https://viewc.xxxxxx.net:443/sdk with username: xxxxxx\administrator or to dispose the connection.

System.Web.Services.Protocols.SoapException: The session is not authenticated.

   en System.Web.Services.Protocols.SoapHttpClientProtocol.ReadResponse(SoapClientMessage message, WebResponse response, Stream responseStream, Boolean asyncCall)

   en System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters)

   en VimApi.InternalVimService.Logout(ManagedObjectReference _this)

   en VMware.Sim.CommonLib.VcSubsystem.VimClientConnection.Disconnect()

2013-11-26 09:54:49,869 | 34            | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Unable to free up the vc connection.

System.Web.Services.Protocols.SoapException: The session is not authenticated.

   en System.Web.Services.Protocols.SoapHttpClientProtocol.ReadResponse(SoapClientMessage message, WebResponse response, Stream responseStream, Boolean asyncCall)

   en System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters)

   en VimApi.InternalVimService.Logout(ManagedObjectReference _this)

   en VMware.Sim.CommonLib.VcSubsystem.VimClientConnection.Disconnect()

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.Disconnect()

2013-11-26 09:54:49,869 | 34            | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Reconnect called to create a new connection to VC https://viewc.xxxxxx.net:443/sdk and user xxxxxx\administrator.

2013-11-26 09:54:50,353 | 34            | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Successfuly connected to the VC server at: https://viewc.xxxxxx.net:443/sdk with user: xxxxxx\administrator

2013-11-26 09:54:50,493 | 34            | INFO  | ServiceCore.LockManager.LockManager - A release is requested for VcConfigEntry with id: de76d4d9-5ef8-4035-83aa-6abda0bb06be

2013-11-26 09:56:24,562 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - MoveSviClones called for 1 SVI clones with Ids: 8a827f0c-da82-4eba-9739-f5addaf40ec9.

2013-11-26 09:56:24,780 | 34            | INFO  | ServiceCore.LockManager.LockManager - A lock is requested for DeploymentGroup with id: b1377cc9-6908-4449-a099-c10ab94595b7

2013-11-26 09:56:24,780 | 34            | INFO  | ServiceCore.LockManager.LockManager - Multiple lock are required for SimClone with ids: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:24,780 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - Operation MoveSviClones locked clones.

RequestId: MoveSviClones-c7a15e4e-0bd8-4228-aa83-034ac6a1294f

CloneId[0]: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:24,827 | 34            | INFO  | ServiceCore.LockManager.LockManager - Multiple releases are required for SimClone with ids: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:24,827 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - Operation MoveSviClones released clones.

RequestId: MoveSviClones-c7a15e4e-0bd8-4228-aa83-034ac6a1294f

CloneId[0]: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:24,827 | 34            | INFO  | ServiceCore.LockManager.LockManager - A release is requested for DeploymentGroup with id: b1377cc9-6908-4449-a099-c10ab94595b7

2013-11-26 09:56:25,903 | 34            | INFO  | ServiceCore.LockManager.LockManager - A lock is requested for DeploymentGroup with id: b1377cc9-6908-4449-a099-c10ab94595b7

2013-11-26 09:56:25,981 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - ResyncSviClones called for deployment group b1377cc9-6908-4449-a099-c10ab94595b7, for 1 clones, with resync spec replication datastore MoID = , force resync = True. CloneIds: 8a827f0c-da82-4eba-9739-f5addaf40ec9. Filed as request id 81965110-6767-47c1-ab2b-581694602fa2.

2013-11-26 09:56:25,997 | 34            | INFO  | ServiceCore.LockManager.LockManager - A lock is requested for AdConfigEntry with id: c9cd0a16-929d-448b-9a13-50969821f6b7

2013-11-26 09:56:25,997 | 34            | INFO  | ServiceCore.LockManager.LockManager - A lock is requested for VcConfigEntry with id: de76d4d9-5ef8-4035-83aa-6abda0bb06be

2013-11-26 09:56:25,997 | 34            | INFO  | ServiceCore.LockManager.LockManager - Multiple lock are required for SimClone with ids: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:25,997 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - Operation ResyncSviClones locked clones.

RequestId: 81965110-6767-47c1-ab2b-581694602fa2

CloneId[0]: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:26,824 | 34            | INFO  | ServiceCore.Action.UfaInitializeDiskAction - Created an UfaInitializeDiskAction with total disks 1.

2013-11-26 09:56:26,870 | 34            | INFO  | Sim.ServiceCore.SimServiceApiImpl - Received a request to resync 1 clones for deployment group b1377cc9-6908-4449-a099-c10ab94595b7. Filed as request id 81965110-6767-47c1-ab2b-581694602fa2

2013-11-26 09:56:26,870 | WFE thread 1  | INFO  | ServiceCore.WorkflowEngine.SingleCloneTask - Task 52c15504-df3f-49fb-b6d9-6ce0e52aa270 is set with non-cancellable.

2013-11-26 09:56:27,198 | WFE thread 8  | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Long run task. Request ID: 81965110-6767-47c1-ab2b-581694602fa2. Task MOID: task-2852815.

2013-11-26 09:56:27,229 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks is signaled to poll.

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.Util.Util - Will retry after 0 seconds. The retry number is 1.

2013-11-26 09:56:27,245 | VC thread     | FATAL | CommonLib.VcSubsystem.VcUtil - ManagedObjectNotFoundFault fault was thrown by the VC server.

System.Web.Services.Protocols.SoapException: The object has already been deleted or has not been completely created

   en System.Web.Services.Protocols.SoapHttpClientProtocol.ReadResponse(SoapClientMessage message, WebResponse response, Stream responseStream, Boolean asyncCall)

   en System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters)

   en VimApi.InternalVimService.ModifyListView(ManagedObjectReference _this, ManagedObjectReference[] add, ManagedObjectReference[] remove)

   en VMware.Sim.CommonLib.VcSubsystem.PropertyCollectorUpdateTracker.<UpdateListView>b__5()

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.VcMethod`1.Invoke()

   en VMware.Sim.CommonLib.VcSubsystem.VcSubsystem25.VcExceptionHandler`1.Invoke()

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Got SimVcSubsystemException ManagedObjectNotFoundFault fault was thrown by the VC server: https://viewc.xxxxxx.net:443/sdk..

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - ListViewRef: session[86f6c4ec-a2dd-86d1-b423-16d0a21e5c4d]52add3bb-6db3-de01-0d41-11ac6d76a33e

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Task in list: task-2852815

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Added task: task-2852815

2013-11-26 09:56:27,245 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Session timed out. Need to create a new ListView.

2013-11-26 09:56:28,493 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Task Task:task-2852815 completed. Removing it from list. The number of tasks to be monitored is reduced to 0.

2013-11-26 09:56:28,493 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks waits for signaling to poll.

2013-11-26 09:56:29,616 | WFE thread 6  | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Long run task. Request ID: 81965110-6767-47c1-ab2b-581694602fa2. Task MOID: task-2852816.

2013-11-26 09:56:29,616 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks is signaled to poll.

2013-11-26 09:56:30,926 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Task Task:task-2852816 completed. Removing it from list. The number of tasks to be monitored is reduced to 0.

2013-11-26 09:56:30,926 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks waits for signaling to poll.

2013-11-26 09:56:31,238 | WFE thread 1  | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Long run task. Request ID: 81965110-6767-47c1-ab2b-581694602fa2. Task MOID: task-2852817.

2013-11-26 09:56:31,238 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks is signaled to poll.

2013-11-26 09:56:33,438 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - Task Task:task-2852817 completed. Removing it from list. The number of tasks to be monitored is reduced to 0.

2013-11-26 09:56:33,438 | VC thread     | INFO  | CommonLib.VcSubsystem.PropertyCollectorUpdateTracker - CheckTasks waits for signaling to poll.

2013-11-26 09:56:33,641 | WFE thread 2  | INFO  | ServiceCore.ActiveDirectory.AdUtil - AD account vdi-xxx-xxx-1 under same ownership or using existing account will be moved.

2013-11-26 09:56:34,936 | UFA main thread 3 | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Getting NFC ticket for disk 2018 in vm vm-60533

2013-11-26 09:56:34,967 | UFA main thread 3 | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Recevied the NFC ticket for disk 2018 in vm vm-60533 from VC.

2013-11-26 09:56:34,967 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.UfaWorkItem - UFA: issuing disk connection request for disk: datastore: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk, host: hvdi2.xxxxxx.net, port: 902.

2013-11-26 09:56:36,121 | UFA main thread 3 | INFO  | CommonLib.Security.CertificateValidation - No certificate for local request. URL is https://localhost:50531/.

2013-11-26 09:56:37,104 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.GetDiskSignatureUfaWorkItem - UFA: finish getting disk signature for disk: datastore: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk, host: hvdi2.xxxxxx.net, port: 902 successfully.

2013-11-26 09:56:37,120 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.InitializeDiskSetUfaWorkItem - CompletionCallbackProxy: finished init disk: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk.

2013-11-26 09:56:37,120 | UFA main thread 3 | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Getting NFC ticket for disk 2018 in vm vm-60533

2013-11-26 09:56:37,135 | UFA main thread 3 | INFO  | CommonLib.VcSubsystem.VcSubsystem25 - Recevied the NFC ticket for disk 2018 in vm vm-60533 from VC.

2013-11-26 09:56:37,135 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.UfaWorkItem - UFA: issuing disk connection request for disk: datastore: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk, host: hvdi2.xxxxxx.net, port: 902.

2013-11-26 09:56:37,588 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.InitializeDiskUfaWorkItem - UFA: skip partition and format on the disk: datastore: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk, host: hvdi2.xxxxxx.net, port: 902.

2013-11-26 09:56:37,915 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.InitializeDiskUfaWorkItem - UFA: finish init disk operation for disk: datastore: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk, host: hvdi2.xxxxxx.net, port: 902 successfully.

2013-11-26 09:56:38,071 | UFA main thread 3 | INFO  | CommonLib.UfaSubsystem.InitializeDiskSetUfaWorkItem - CompletionCallbackProxy: finished init disk: [XXX-DP001-0244-SAS] vdi-xxx-xxx-1/vdi-xxx-xxx-11-internal.vmdk.

2013-11-26 09:56:38,118 | WFE thread 5  | INFO  | ServiceCore.LockManager.LockManager - Multiple releases are required for SimClone with ids: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:38,118 | WFE thread 5  | INFO  | Sim.ServiceCore.SimServiceApiImpl - Operation ResyncSviClones released clones.

RequestId: 81965110-6767-47c1-ab2b-581694602fa2

CloneId[0]: 8a827f0c-da82-4eba-9739-f5addaf40ec9

2013-11-26 09:56:38,118 | WFE thread 5  | INFO  | ServiceCore.LockManager.LockManager - A release is requested for DeploymentGroup with id: b1377cc9-6908-4449-a099-c10ab94595b7

2013-11-26 09:56:38,118 | WFE thread 5  | INFO  | ServiceCore.LockManager.LockManager - A release is requested for AdConfigEntry with id: c9cd0a16-929d-448b-9a13-50969821f6b7

2013-11-26 09:56:38,118 | WFE thread 5  | INFO  | ServiceCore.LockManager.LockManager - A release is requested for VcConfigEntry with id: de76d4d9-5ef8-4035-83aa-6abda0bb06be

[Linjo]

That looks ok, anything in the View Agent logs?

[XaviGG]

View Agent logs from the Linked Clone VM?

[Linjo]

Yes, if the customization times out is likely there that the errors will show up.

[XaviGG]

Here they are

[btkrausen]

I just ran into this same problem just recently. A few things that fixed my issue:

• Ensure you are using the VXMNET3 NIC (I had inadvertently installed the patch but not change the NIC type on this template )
• Use QuickPrep rather than SysPrep if your machines do not require a unique SID (most apps don't these days and it's faster)
  • You'll have to create a new pool to change this but you can move existing machines to a new pool.
• Ensure that your service account has the correct permissions within AD (there are six I believe).

[XaviGG]

• Ensure you are using the VXMNET3 NIC (I had inadvertently installed the patch but not change the NIC type on this template )   Ensured.
• Use QuickPrep rather than SysPrep if your machines do not require a unique SID (most apps don't these days and it's faster)  We need to use Sysprep, cause we are using KMS host for Windows and Office licenses-
  • You'll have to create a new pool to change this but you can move existing machines to a new pool.
• Ensure that your service account has the correct permissions within AD (there are six I believe). Ensured

We have migrated Quickprep to Sysprep pool due to KMS requirements.

[btkrausen]

According to this Microsoft KB, KMS does not require the SID to be changed, just the CMID. And this VMware documentation states that QuickPrep uses KMS to activate Win 7 desktops.

Let me know if you've found documentation that states otherwise as we just moved from sysprep to quickprep and my machines are activating just fine. I'm not any additional quickprep scripts either. Plus, we have another group running an almost 1000 desktop deployment using quickprep w/ KMS keys.

[btkrausen]

Found this in the View Administration Guide as well (sorry, this has sparked my interest now )

The View Composer QuickPrep tool implements the activation through these steps:

1 Invokes a script to remove the existing license status on the linked-clone virtual machine

2 Restarts the guest operating system

3 Invokes a script that uses KMS licensing to activate the operating system on the clone.

Each time QuickPrep runs on a linked clone, the activation takes place.

For KMS licensing, View Composer uses the KMS server that is configured to activate the parent virtual

machine. The KMS server treats an activated linked clone as a computer with a newly issued license

However, it sounds like your recompose if failing before it even gets to activation. When I spoke to VMware support earlier this week on a different issue, he stated that using sysprep was one of the main reasons he sees why recompose operations to fail. That plus the other two things I mentioned above. Hope that helps in some aspect and that you get it fixed soon

Have a Happy Thanksgiving.

[XaviGG]

When we had QuickPrep instead of SysPrep, KMS counter didn't increase.

We had to migrate all our pools from QuickPrep to SysPrep.

I would say that KMS needs SID to be changed.

VMware KB: Differences between QuickPrep and Sysprep

[DNieroda]

Ha!! Welcome to my world! I thought I was the only one.

With the latest ticket I submitted, the VMware tech insisted it was sysprep causing the recomposing issue, but when I asked him to provide proof of this, he was unable to deliver.

What I've found, is that sometimes if you let the error sit there.. and wait a bit..  (maybe 30min-1hour) the recomposing finishes and the Agent state goes to "Available" again.

However, this isn't always the case, and I usually end up with more "broken" vm's then working ones, and I have to recompose again and again until they've successfully recomposed.

This is annoying when I have 275+ vm's!

Sorry I can't provide any help with this.. just know that you're not the only one!

Have you resolved this yet by any chance?  

[tomaddox]

I'm also having this issue. The vmware-viewcomposer-ga-new.log file contains the following events:

014-04-28 15:51:45,433 [1276] INFO  CheckPointing  -  [CheckPointing.cpp, 124] Ready for shutdown and checkpoint

2014-04-28 15:51:45,434 [1276] INFO  LegacyRebootPolicy  -  [RebootPolicy.cpp, 51] Awaiting shutdown for checkpointing

The VM seems never to reboot on its own. After a manual reboot, the following entries appear in the log file:

2014-04-28 16:10:21,424 [1276] FATAL ExceptionTranslator  -  [SvmStateMachine.h, 227] Failed to write valueError 19 (0x13): The media is write protected.

StackTrace:

----Backtrace using dbghelp.dll----

Module path: C:\Program Files (x86)\Common Files\VMware\View Composer Guest Agent\vmware-svi-ga.exe

Module directory: C:\Program Files (x86)\Common Files\VMware\View Composer Guest Agent\

SymInitialize() failed

2014-04-28 16:10:21,424 [1276] FATAL ExceptionTranslator  -  [SvmStateMachine.h, 228] Caught an unexpected exception.

2014-04-28 16:10:21,424 [1276] FATAL ExceptionTranslator  -  [SvmStateMachine.h, 231] Stacktrace:

----Backtrace using dbghelp.dll----

Module path: C:\Program Files (x86)\Common Files\VMware\View Composer Guest Agent\vmware-svi-ga.exe

Module directory: C:\Program Files (x86)\Common Files\VMware\View Composer Guest Agent\

SymInitialize() failed

2014-04-28 16:10:21,424 [1276] FATAL Customizing  -  [Customizing.cpp, 70] Customization failed with: 6

2014-04-28 16:10:21,424 [1276] INFO  LibStub  -  [libstubs.cpp, 31] ----Win32 exception detected, exceptionCode 0xe06d7363 ----

2014-04-28 16:10:21,424 [1276] INFO  LibStub  -  [libstubs.cpp, 31] eip 0x74b5c41f eflags 0x00000212 rwFlags 0x19930520 badAddr 0x01c4f16c

2014-04-28 16:10:21,424 [1276] INFO  LibStub  -  [libstubs.cpp, 31] eax 0x01c4f064 ebx 0x01c4fd34 ecx 0x00000003 edx 0000000000

2014-04-28 16:10:21,424 [1276] INFO  LibStub  -  [libstubs.cpp, 31] esi 0x7c3a0f2c edi 0x01c4f0f4 ebp 0x01c4f0b4 esp 0x01c4f064

2014-04-28 16:10:21,424 [1276] INFO  LibStub  -  [libstubs.cpp, 31] ----Backtrace using dbghelp.dll----

2014-04-28 16:10:21,424 [1276] INFO  LibStub  -  [libstubs.cpp, 31] Module path: C:\Windows\syswow64\KERNELBASE.dll

2014-04-28 16:10:21,424 [1276] INFO  LibStub  -  [libstubs.cpp, 31] Module directory: C:\Windows\syswow64\

2014-04-28 16:10:21,424 [1276] INFO  LibStub  -  [libstubs.cpp, 31] SymInitialize() failed

2014-04-28 16:10:21,424 [1276] INFO  LibStub  -  [libstubs.cpp, 31] CoreDump: unable to determine app data path

One thing I did notice was that the VMware Horizon View Agent service was set to Disabled in the Services control panel. When I reenabled and restarted the service, the VM rebooted almost immediately and customization completed successfully. It appears that something is disabling the VMware View Agent service during the customization process and then never reenabling it, so Composer can't restart the VM. We just upgraded to 5.31, so I'm wondering if this is the issue. I'm going to perform some additional troubleshooting and will follow up once I've done so.

[Gaurav_Baghla]

panther log File ????????

http://support.microsoft.com/kb/927521

[TechMassey]

I have seen that issue before and in my experience it has been a networking issue. The error can occur because view did not receive a response from the agent at various points during the customization. In my case, it was DNS resolution. I would verify that you can ping that VM the whole time once it obtains an IP. I would also login to the console and verify it doesn't have a private IP and can ping view infrastructure components.

[tomaddox]

The DNS issue could be part of it. We use a spectacularly crappy DNS/DHCP product whose name I will not mention, and it handles dynamic updates very poorly. I did verify that fundamental IP connectivity is alive and correct, and this is a relatively new issue, so I don't think that DNS is the root cause, but it could be contributing.