Brief "error" during customization, but then goes to Provisioned

[MrBeatnik]

Hi,

So I've recently been getting the following error for every linked clone, non-persistent, machine that is built using quickprep:

Provisioning error occurred for Machine someMachineName: Customization error due to no network communication between the View agent and Connection Server

This error appears only for a few minutes, and then goes back to normal (i.e. the machine is created, provisioned and available for use).

I checked the ga-new.log for the time/date of this error and cannot see anything particularly useful. It seems to happen just before a reboot from Windows activation (KMS). The reboot is called, but there is 37 second period where nothing happens before the reboot process is initiated. There also seems to be a three minute period where nothing is happening after the machine comes back up. This seems like a timeout issue?

• I already have the ExecScriptTimeout setting in the registry (Documentation Center for VMware Horizon 6.0 with View), and I can see this is working for my Customization Script (As the ga-new log file shows the correct timeout at a later point in the logfile), but the issue is happening before the customization script is invoked.
• We are using VMXNET3 on Windows 7, and have the appropriate KB hotfix installed.
• This only appeared to be happening after I uninstalled VMware Tools and Agent, and reinstalled (in that order).
• Agent 6.1.0
  

For example, Timeout error occurred reported by View Administrator at 3/24/2016 6:04:15 PM showing in red below.

2016-03-24 18:03:49,112 [392] INFO  CustomizationPersistentInfoReg  -  [CustomizationPersistentInfoReg.cpp, 98] Opened guest registry key for accessing customization info.

2016-03-24 18:03:49,124 [392] DEBUG CSvmGaService  -  [svmGaService.cpp, 323] In RunService

2016-03-24 18:03:49,125 [392] DEBUG SvmDisk  -  [SvmDisk.cpp, 55] Found signature file //?/Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}/simvol.dat at volume \\?\Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}\ with mount point * and usage 001

2016-03-24 18:03:49,125 [392] INFO  CSvmGaService  -  [svmGaService.cpp, 214] Found policy file on the volume: \\?\Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}\

2016-03-24 18:03:49,125 [392] INFO  CSvmGaService  -  [svmGaService.cpp, 252] Add logger on internal disk. //?/Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}

2016-03-24 18:03:49,125 [392] INFO  CSvmGaService  -  [svmGaService.cpp, 305] Successfully parsed the policy and disk signatures

2016-03-24 18:03:49,126 [392] INFO  CSvmGaService  -  [svmGaService.cpp, 359] Reset policy state.

2016-03-24 18:03:49,126 [392] INFO  CSvmGaService  -  [svmGaService.cpp, 375] Starting the state machine thread

2016-03-24 18:03:49,127 [392] DEBUG CSvmGaService  -  [svmGaService.cpp, 382] Started the state machine thread

2016-03-24 18:03:49,127 [392] DEBUG WaitableManagerWin32  -  [WaitableManagerWin32.cpp, 87] Updating callback for event SviServiceStopEvent (0000013C)

2016-03-24 18:03:49,127 [392] DEBUG WaitableManagerWin32  -  [WaitableManagerWin32.cpp, 90] adding callback for event SviServiceStopEvent (0000013C)

2016-03-24 18:03:49,127 [392] DEBUG WaitableManagerWin32  -  [WaitableManagerWin32.cpp, 179] Dispatching callback for event WaitableManagerInternal (00000134)

2016-03-24 18:03:49,128 [1600] INFO  SvmStateMachine  -  [SvmStateMachine.cpp, 66] C'tructed StateMachine

2016-03-24 18:03:49,128 [1600] INFO  RestoringCheckpoint  -  [RestoringCheckpoint.cpp, 61] In RestoringCheckpoint

2016-03-24 18:03:49,128 [1600] INFO  RestoringCheckpoint  -  [RestoringCheckpoint.cpp, 111] Checkpoint is enabled, not yet checkpointed.

2016-03-24 18:03:49,130 [1600] INFO  Customizing  -  [Customizing.cpp, 60] In Customizing

2016-03-24 18:03:49,130 [1600] INFO  KwikPrep  -  [KwikPrep.cpp, 66] In KwikPrep

2016-03-24 18:03:49,130 [1600] INFO  KwikPrep  -  [KwikPrep.cpp, 92] Setting computer name 0022B920

2016-03-24 18:03:49,381 [1600] INFO  KwikPrep  -  [KwikPrep.cpp, 115] Initiating license activation process.

2016-03-24 18:03:49,381 [1600] INFO  KwikPrep  -  [KwikPrep.cpp, 116] Executing license rearm command.

2016-03-24 18:03:52,003 [1600] INFO  Guest  -  [Guest.cpp, 532] Script cscript /Nologo "C:\Program Files\Common Files\VMware\View Composer Guest Agent/vmware-viewcomposer.vbs" -lt standard ouput: 1

2016-03-24 18:03:52,628 [1600] INFO  Guest  -  [Guest.cpp, 532] Script cscript \windows\system32\slmgr.vbs -rearm standard ouput: Microsoft (R) Windows Script Host Version 5.8

Copyright (C) Microsoft Corporation. All rights reserved.

Command completed successfully.

Please restart the system for the changes to take effect.

2016-03-24 18:03:52,628 [1600] INFO  KwikPrep  -  [KwikPrep.cpp, 137] License rearm process is completed.

2016-03-24 18:03:52,628 [1600] INFO  CSvmGaService  -  [svmGaService.cpp, 411] Service is in state: 5

2016-03-24 18:03:52,628 [1600] INFO  JustReboot  -  [RebootPolicy.cpp, 73] Rebooting the clone

2016-03-24 18:03:52,628 [1600] INFO  Guest  -  [Guest.cpp, 325] Initiating a reboot.

2016-03-24 18:04:25,644 [1764] INFO  CSvmGaService  -  [svmGaService.cpp, 467] Requested termination of the SVM state machine

2016-03-24 18:04:25,644 [392] DEBUG WaitableManagerWin32  -  [WaitableManagerWin32.cpp, 179] Dispatching callback for event SviServiceStopEvent (0000013C)

2016-03-24 18:04:25,644 [392] INFO  CSvmGaService  -  [svmGaService.cpp, 391] CSvmGaService::RunService: Stop requested.

2016-03-24 18:04:25,644 [392] INFO  CSvmGaService  -  [svmGaService.cpp, 482] Shutting down the service

2016-03-24 18:04:25,644 [392] INFO  CSvmGaService  -  [svmGaService.cpp, 484] Awaiting SVM state machine shutdown

2016-03-24 18:04:25,644 [1600] DEBUG Rebooting  -  [Rebooting.cpp, 82] Rebooting as per simple reboot policy.

2016-03-24 18:04:25,644 [392] INFO  CSvmGaService  -  [svmGaService.cpp, 487] Stopped the SVM state machine

2016-03-24 18:04:48,447 [1716] INFO  CSvmGaService  -  [svmGaService.cpp, 87] Initialized the Service

2016-03-24 18:04:48,448 [1716] INFO  CustomizationPersistentInfoReg  -  [CustomizationPersistentInfoReg.cpp, 98] Opened guest registry key for accessing customization info.

2016-03-24 18:04:48,451 [1716] DEBUG CSvmGaService  -  [svmGaService.cpp, 323] In RunService

2016-03-24 18:04:48,453 [1716] DEBUG SvmDisk  -  [SvmDisk.cpp, 55] Found signature file //?/Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}/simvol.dat at volume \\?\Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}\ with mount point * and usage 001

2016-03-24 18:04:48,453 [1716] INFO  CSvmGaService  -  [svmGaService.cpp, 214] Found policy file on the volume: \\?\Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}\

2016-03-24 18:04:48,453 [1716] INFO  CSvmGaService  -  [svmGaService.cpp, 252] Add logger on internal disk. //?/Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}

2016-03-24 18:04:48,454 [1716] INFO  CSvmGaService  -  [svmGaService.cpp, 305] Successfully parsed the policy and disk signatures

2016-03-24 18:04:48,455 [1716] INFO  CSvmGaService  -  [svmGaService.cpp, 359] Reset policy state.

2016-03-24 18:04:48,455 [1716] INFO  CSvmGaService  -  [svmGaService.cpp, 375] Starting the state machine thread

2016-03-24 18:04:48,456 [1716] DEBUG CSvmGaService  -  [svmGaService.cpp, 382] Started the state machine thread

2016-03-24 18:04:48,456 [1716] DEBUG WaitableManagerWin32  -  [WaitableManagerWin32.cpp, 87] Updating callback for event SviServiceStopEvent (0000013C)

2016-03-24 18:04:48,456 [1716] DEBUG WaitableManagerWin32  -  [WaitableManagerWin32.cpp, 90] adding callback for event SviServiceStopEvent (0000013C)

2016-03-24 18:04:48,456 [1716] DEBUG WaitableManagerWin32  -  [WaitableManagerWin32.cpp, 179] Dispatching callback for event WaitableManagerInternal (00000134)

2016-03-24 18:04:48,458 [1872] INFO  SvmStateMachine  -  [SvmStateMachine.cpp, 66] C'tructed StateMachine

2016-03-24 18:04:48,458 [1872] INFO  RestoringCheckpoint  -  [RestoringCheckpoint.cpp, 61] In RestoringCheckpoint

2016-03-24 18:04:48,458 [1872] INFO  RestoringCheckpoint  -  [RestoringCheckpoint.cpp, 111] Checkpoint is enabled, not yet checkpointed.

2016-03-24 18:04:48,458 [1872] INFO  Customizing  -  [Customizing.cpp, 60] In Customizing

2016-03-24 18:04:48,458 [1872] INFO  KwikPrep  -  [KwikPrep.cpp, 66] In KwikPrep

2016-03-24 18:04:48,458 [1872] INFO  KwikPrep  -  [KwikPrep.cpp, 98] Removing service dependencies

2016-03-24 18:04:48,460 [1872] INFO  CSvmGaService  -  [svmGaService.cpp, 411] Service is in state: 5

2016-03-24 18:04:48,461 [1872] INFO  Guest  -  [Guest.cpp, 885] Removing vmware-viewcomposer-ga dependency from BFE

2016-03-24 18:07:01,511 [1696] INFO  CSvmGaService  -  [svmGaService.cpp, 87] Initialized the Service

2016-03-24 18:07:01,512 [1696] INFO  CustomizationPersistentInfoReg  -  [CustomizationPersistentInfoReg.cpp, 98] Opened guest registry key for accessing customization info.

2016-03-24 18:07:01,522 [1696] DEBUG CSvmGaService  -  [svmGaService.cpp, 323] In RunService

2016-03-24 18:07:01,523 [1696] DEBUG SvmDisk  -  [SvmDisk.cpp, 55] Found signature file //?/Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}/simvol.dat at volume \\?\Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}\ with mount point * and usage 001

2016-03-24 18:07:01,523 [1696] INFO  CSvmGaService  -  [svmGaService.cpp, 214] Found policy file on the volume: \\?\Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}\

2016-03-24 18:07:01,523 [1696] INFO  CSvmGaService  -  [svmGaService.cpp, 252] Add logger on internal disk. //?/Volume{baeb9bfa-f1ea-11e5-804b-806e6f6e6963}

2016-03-24 18:07:01,525 [1696] INFO  CSvmGaService  -  [svmGaService.cpp, 305] Successfully parsed the policy and disk signatures

2016-03-24 18:07:01,525 [1696] INFO  CSvmGaService  -  [svmGaService.cpp, 359] Reset policy state.

2016-03-24 18:07:01,525 [1696] INFO  CSvmGaService  -  [svmGaService.cpp, 375] Starting the state machine thread

2016-03-24 18:07:01,525 [1696] DEBUG CSvmGaService  -  [svmGaService.cpp, 382] Started the state machine thread

2016-03-24 18:07:01,526 [1696] DEBUG WaitableManagerWin32  -  [WaitableManagerWin32.cpp, 87] Updating callback for event SviServiceStopEvent (00000140)

2016-03-24 18:07:01,526 [1696] DEBUG WaitableManagerWin32  -  [WaitableManagerWin32.cpp, 90] adding callback for event SviServiceStopEvent (00000140)

2016-03-24 18:07:01,526 [1696] DEBUG WaitableManagerWin32  -  [WaitableManagerWin32.cpp, 179] Dispatching callback for event WaitableManagerInternal (00000138)

2016-03-24 18:07:01,526 [1620] INFO  SvmStateMachine  -  [SvmStateMachine.cpp, 66] C'tructed StateMachine

2016-03-24 18:07:01,526 [1620] INFO  RestoringCheckpoint  -  [RestoringCheckpoint.cpp, 61] In RestoringCheckpoint

2016-03-24 18:07:01,526 [1620] INFO  RestoringCheckpoint  -  [RestoringCheckpoint.cpp, 111] Checkpoint is enabled, not yet checkpointed.

2016-03-24 18:07:01,526 [1620] INFO  Customizing  -  [Customizing.cpp, 60] In Customizing

2016-03-24 18:07:01,526 [1620] INFO  KwikPrep  -  [KwikPrep.cpp, 66] In KwikPrep

2016-03-24 18:07:01,526 [1620] INFO  KwikPrep  -  [KwikPrep.cpp, 98] Removing service dependencies

2016-03-24 18:07:01,529 [1620] INFO  CSvmGaService  -  [svmGaService.cpp, 411] Service is in state: 5