VMware Horizon Community
Erossman
Enthusiast
Enthusiast

AppStack TimeOut 180 seconds

Hi Guys,

I have some troubles with AppVolumes (2.11 and 2.12.1 tested) and my instant clone pools.

We use Win7 x64 desktops. If a user have only one appstack assigned I can see the cvapps volume as a separate drive with a letter displayed under the computer settings.

It takes ca. 3 minutes after  it will disapared and the content of the appstack is loaded. It's only happened with a single appstack, not with multiple appstacks.

I can see in the svservice logs following information

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] OnStartShell: IMG\testuser (NameSamCompatible)

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] Found 1 SCSI adapter(s)

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] Found 2 disk(s)

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] Found 2 disk interface(s)

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] : GetDevicePathFromClass:SetupDiGetDeviceRegistryProperty [\Device\HarddiskVolume2]

[2017-05-02 12:22:05.363 UTC] [svservice:3908] IsFilePresentW: unable to open "\\?\GLOBALROOT\Device\HarddiskVolume2\snapvol.cfg" (error 1005)

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] [Volume.Dev0] Generic volume: \Device\HarddiskVolume2

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] : GetDevicePathFromClass:SetupDiGetDeviceRegistryProperty [\Device\HarddiskVolume3]

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] [Volume.Dev1] Generic volume: \Device\HarddiskVolume3

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] : GetDevicePathFromClass:SetupDiGetDeviceRegistryProperty [\Device\HarddiskVolume4]

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] [Volume.Dev2] Appvolume path: \Device\HarddiskVolume4

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] Checking for scripts on "\Device\HarddiskVolume4" (event shellstart)

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] Creating mount point at "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\"

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] "\\?\Volume{99c25326-2f27-11e7-a08a-0050568f61f0}\" mounted at "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\"

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] Creating mount point at "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\"

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] "\\?\Volume{99c25326-2f27-11e7-a08a-0050568f61f0}\" mounted at "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\"

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] RunScript: user script (event shellstart) on "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\" go process.

[2017-05-02 12:22:05.363 UTC] [svservice:P3896:T3908] RunExecutableAsUser: Path "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\shellstart.bat"

CreateProcessWithTokenAndEnvBlockW() standard user or UAC turned off, continue...

[2017-05-02 12:22:05.379 UTC] [svservice:P3896:T3908] Successfully launched (elevated privileges): \SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\shellstart.bat (wait -1 ms), pid=936 tid=2888

[2017-05-02 12:22:05.488 UTC] [svservice:P3896:T3908] Finished waiting for "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\shellstart.bat": CreationFlag 0x08000420, WaitStatus 0x00000000, ExitCode 0 (0x00)

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] Successfully launched: \SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\shellstart.bat (wait -1 ms)

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] Creating mount point at "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\"

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] "\\?\Volume{99c25326-2f27-11e7-a08a-0050568f61f0}\" mounted at "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\"

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] RunScript: user script (event windows_install_fonts) on "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\" go process.

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] Creating mount point at "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\"

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] "\\?\Volume{99c25326-2f27-11e7-a08a-0050568f61f0}\" mounted at "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\"

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] EnumAndLaunchRunKeyValues: No autorun values in \REGISTRY\MACHINE\SnapVolumes-{99c25326-2f27-11e7-a08a-0050568f61f0}\MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\Run

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] Creating mount point at "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\"

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] "\\?\Volume{99c25326-2f27-11e7-a08a-0050568f61f0}\" mounted at "\SnapVolumesTemp\MountPoints\{99c25326-2f27-11e7-a08a-0050568f61f0}\"

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] EnumAndLaunchRunKeyValues: No autorun values in \REGISTRY\MACHINE\SnapVolumes-{99c25326-2f27-11e7-a08a-0050568f61f0}\MACHINE\SOFTWARE\Wow6432Node\Microsoft\Windows\CurrentVersion\Run

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] Checking for svcapture on "\Device\HarddiskVolume4" (event svcapture)

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] RunScript: creating thread to check provisioning state

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] : GetDevicePathFromClass:SetupDiGetDeviceRegistryProperty [\Device\HarddiskVolume1]

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] [Volume.Dev3] Generic volume: \Device\HarddiskVolume1

[2017-05-02 12:22:05.504 UTC] [svservice:P3896:T3908] Found 4 volume(s)

[2017-05-02 12:22:05.519 UTC] [svservice:3908] Assertion failed at enumdev.c:475 in EnumerateDevices: InterfacesFound >= DevicesFound

[2017-05-02 12:22:05.519 UTC] [svservice:P3896:T3908] Found 2 volume interface(s)

[2017-05-02 12:22:05.519 UTC] [svservice:3908] HttpFileShareRequest WinHttp over SSL is disabled. Log collection to file share not supported.

[2017-05-02 12:22:05.519 UTC] [svservice:P3896:T3908] handleFileShareStr: File share info received from manager is empty.

[2017-05-02 12:22:05.519 UTC] [svservice:P3896:T3908] OnStartShell: Error Failed to Start DCT Logger

[2017-05-02 12:22:06.191 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 15 second(s) so far)

[2017-05-02 12:22:07.191 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 16 second(s) so far)

[2017-05-02 12:22:08.191 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 17 second(s) so far)

[2017-05-02 12:22:09.191 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 18 second(s) so far)

[2017-05-02 12:22:10.191 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 19 second(s) so far)

[2017-05-02 12:22:11.191 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 20 second(s) so far)

[2017-05-02 12:22:12.177 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 21 second(s) so far)

[2017-05-02 12:22:13.199 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 22 second(s) so far)

[2017-05-02 12:22:14.199 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 23 second(s) so far)

[2017-05-02 12:22:15.199 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 24 second(s) so far)

[2017-05-02 12:22:16.199 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 25 second(s) so far)

[2017-05-02 12:22:17.199 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 26 second(s) so far)

...

...

...

[2017-05-02 12:24:50.235 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 179 second(s) so far)

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] Waiting for 1 new volumes before resetting order (0 processed, waited 180 second(s) so far)

[2017-05-02 12:24:51.235 UTC] [svservice:3224] Gave up waiting for 1 remaining volume(s) to load after 180 second(s) (called by WaitVolumesLoadingWorker)

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] ResetVolumeReordering: resetting reorder counter (called by ResetVolumeReorderingTimeout)

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] ResetVolumeReordering: SvdResetReorderList success!

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] Message: "Timed out when loading assigned volumes, please retry or contact your administrator." (hToken FFFFFFFFFFFFFFFF)

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] RunExecutableAsUser: Path "C:\Program Files (x86)\CloudVolumes\Agent\svservice.exe"

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] RunExecutableAsUser: CommandLine svservice.exe message "Timed out when loading assigned volumes, please retry or contact your administrator."

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] RunExecutableAsUser: SessionId 1 of 3 -> CurrentSessionId 1 Name(Console) State(0) UserToken 00000000000003C8

CreateProcessWithTokenAndEnvBlockW() standard user or UAC turned off, continue...

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] Successfully launched (elevated privileges): svservice.exe message "Timed out when loading assigned volumes, please retry or contact your administrator." (wait 0 ms), pid=4100 tid=4756

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] Successfully launched: svservice.exe message "Timed out when loading assigned volumes, please retry or contact your administrator." (wait 0 ms)

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] Initializing HTTP connection

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] HttpInitializeConnection: Asynchronous volume mounting is: Disabled.

[2017-05-02 12:24:51.235 UTC] [svservice:P3896:T3224] Choosing a manager out of 1 configured manager(s)

This there something wrong with my golden master image?

I can see in the logs a HarddiskVolume2

If I take a look to HKLM\SYSTEM\CurrentControlSet\Control\hivelist I can see HarddiskVolume3. Is this ok?

The SymLink for my OS Drive C:\ is showing to HarddiskVolume3

Regards,

VM-Master

14 Replies
alsmk2
Hot Shot
Hot Shot

In regard to the drive letters showing, I now implement the following on every appstack we create to avoid app volumes assigning drive letters.

Network drive letters are not mapped to VMware App Volumes AppStacks (2139351) | VMware KB

There is a specific registry key you can set on the svservice too, but it rarely works. The method linked stops drive letters being assigned full stop. You can add this to existing appstacks by manually attaching it to a machine with no AppVol agent installed, or simply updating the appstack the normal way.

In terms of the the delay, have you set the VolWaitTimeout key in your gold image? The following seems to work for most of our deployments:

HKLM\SYSTEM\CurrentControlSet\services\svservice\Parameters

DWORD: VolWaitTimeout - 5

Reply
0 Kudos
alsmk2
Hot Shot
Hot Shot

Another suggestion to check on your gold image is that it has never had an appstack directly attached to it. You can normally sort that out by deleting all entries, apart from the \DosDevicesC: & (Default) from the following location:

HKLM\SYSTEM\MoutedDevices

Clear it out and reboot the system - any additional devices that should have an entry will be recreated after reboot.

Reply
0 Kudos
Ray_handels
Virtuoso
Virtuoso

What alsmk2 says.

We saw the exact same happening if we had multiple appstacks attached to our VDI. What happens is that during logon Windows "grabs"  the appstack and assigns it a driveletter. Appvolumes tries to get the appstack backs but fails doing so.

Eventually, after 180 seconds it just forcebly takes the appstacks back processing them instantly after retaining control of them. Changing the attribute of the machine no NoDefaultDriveLetter=Yes solved the issue for us.

Reply
0 Kudos
mellicott
Enthusiast
Enthusiast

Thirded, and we updated our templates so it became the norm, but in the meantime I had many stacks to update, all you need  to do is run a CMD prompt while provisioning, then: -

diskpart

list volume

select volume 3 (probably)

attributes volume (if you want to see what the setting is, else just do the next line)

attributes volume set nodefaultdrivelatter

exit

Apologies if you already know the above sequence of commands.

Horizon Client 5.4.3 Appvol Manager 2.18 Appvol Client 2.18.6 UEM 9.10
Reply
0 Kudos
Erossman
Enthusiast
Enthusiast

Hi All,

in appvol 2.12.1 vmware changed the template so that an appstack will not get a drive letter anymore.

I also tried this, but it doesn't change the behavior that It takes 180s after reach a timeout.

In the meantime I saw that this issue only happened because we set the appvol manager adress via a batch skript in the horizon pool.

We do ths because we have only on master image but different AppVolumes Cluster (TEST, PRE-PROD, PROD)

It seems so that appvolumes need a clean reboot to initalize all the services and drivers.

You could see the same behavior if you do the following.

1. Boot a VM with AppVol Agent

2. Remove all the Manager Adresses in the Registry

3. Reboot the VM and Logon again with a local Admin User

4. Set again the Manager Adresse in the Registry

5. Now don't reboot! Restart the AppVol Services

6. LogOff and Logon with a Domain User and a single assigned AppStack

7. You will see an timeout message after 180 sec

Ray_handels
Virtuoso
Virtuoso

Allthough we have seen it working on test environments with just changing the reg key it would not be something I would suggest doing (just my 2 cents though).

I would do a full reinstall of the agent because it is really easy and quick to do this.

Reply
0 Kudos
Erossman
Enthusiast
Enthusiast

Hi Ray,

I have two enterprise customer which prefer this method. They don't want to manage extra golden master images only to set the appvol manager.

It's working great if a user have more than one appstack. Why should we do a full reinstall? What will this change?

Reply
0 Kudos
Ray_handels
Virtuoso
Virtuoso

Hey,

If it works it works Smiley Happy. But I believe that there is more to it than just changing that 1 registry key. I'm not 100% sure but i thought that there were a few keys that needed to be changed. It would be nice though to get a definitive answer from engineering if this is a supported method.

Reply
0 Kudos
Ray_handels
Virtuoso
Virtuoso

Man oh man.

So we had it working, recreated some appstacks because we unintentially added all kinds or registry settings in our appstacks due to policies (which didn't hurt us on 2.9.1 but still) recreated those appstacks on a cleaned machine, set all appstacks with the NoDefaultDriveLetter setting and I thought we were good to go.

Unfortenately we now see the exact same issue as you are seeing with the 180 seconds timeout and the hideous error stating virtualization failed allthough eventually the machine is build up nicely. We already had an open ticket so we will try and see if we can fix it this time around.. Will keep you guys posted. If anyone finds anything just let me know..

Reply
0 Kudos
Ray_handels
Virtuoso
Virtuoso

Erossman​ did you get any further with this?

For now we ended up using the VolWaitTimeOut setting to enforce logon to proceed.

because we would end up with the non saying error message we also decided to try and use the HidePopups setting to disable popups from the svservice. This way users aren't bugged with an error message.

Would love to hear your progressions. Still working on it though. Will keep you guys posted.

Erossman
Enthusiast
Enthusiast

Hi Ray,

I also have opened an ticket but haven't found to do a remote session yet.

It's always frustrating to be the first, who have an issue. 

There are some other bugs in AppVol 2.12.1 were I try to find a fix.....

Reply
0 Kudos
Ray_handels
Virtuoso
Virtuoso

Just wanted to ask you 2 things regarding the 180 seconds.

Do you happen to have an error in your svservice.log file that says "..METADATA\_meta.yml" was not opened.."??

I received a message that we had one appstack where the meta.yml was unpresent and thus it did not work. After recreating at first sight it seems to have fixed the issue (not 100% sure though).

Also, we have applocker policies in place. It seems as if Appvolumes has some issues with it.

Can you check and see what value the following reg key has in your VDI after login with appstacks?

HKLM\System\CurrentControlSet\Control\Srp\GP\RuleCount

Reply
0 Kudos
Erossman
Enthusiast
Enthusiast

I can't find nothing in the appvol agent log regarding "Metadata".

Again the issue only occur if I set the appvol manager address with the post-synchronization script of the instant clone pool.

This one contains the following batch input.......

net stop svservice

regedit.exe /s C:\Install\AppVolSwitch\AppVolMgmt.reg

net start svservice

The AppVolMgmt.reg contains.......

Windows Registry Editor Version 5.00

[HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\services\svservice\Parameters]

"Manager1"="AppVolMgmt01.mydomain.local:443"

The mentioned registry key "RuleCount" from you does not exist in my environment. I can see the Key "GP" but there is no content below.

We also don't use applocker. I hope this info will help you?

Reply
0 Kudos
Ray_handels
Virtuoso
Virtuoso

Hey Erosmann,

We eventually fixed the issue.

It seemed that one of our appstacks missed the meta.xml file in it's root and that's why Appvolumes couldn't reorder the appstacks because it could not "reach" the info on the appstack to do the reorder. This behaviour seems to be exactly the same as the issue with the appstacks having a drive letter. Because Windows claims the disk and gives it a drive letter Appvolumes cannot "reach" it and thus cannot reorder it.

So for us it means that we need to change all appstacks with the Nodefaultdriveletter setting and also check to see if the appstacks are not corrupt.

That being said, we have only changed the server using that registry setting once and it was in our test enviornment. As said, I normally always reinstall the application because it doesn't take that long. I have no idea why it shows this behaviour but my guess is that it is best to just reinstall the agent on the golden image.

You could also try to force Appvolumes to continue the proces of executing the appstacks by setting the VolWaitTimeOut=x (i would suggest going for 10 decimal if you have writables) and it will force execution of appstacks. Also make sure to use the HidePopups setting as well. Otherwise you end up with an error message for some users.

Reply
0 Kudos