Delayed logon

[BertyB]

I've been assisting with diagnosing slow logon times in a new DEM VDI environment.  I started with looking at group policy logging and found delays of around 60 seconds for the VMWare Dynamic Environment Manager extension to complete.  I had logging enabled for DEM and found some gaps in the flexengine.log

2022-01-31 12:31:05.056 [INFO ] Starting FlexEngine v10.2.0.976 [IFP#181a52cf-3e7>>]
2022-01-31 12:31:05.057 [INFO ] Running as Group Policy client-side extension
2022-01-31 12:31:05.057 [INFO ] Performing path-based import
2022-01-31 12:31:05.163 [INFO ] Successfully redirected 'Desktop' folder to '\\fileserver\files\users\testuser\Desktop' ('Desktop Redirect.xml')
2022-01-31 12:31:05.218 [INFO ] Importing DEM settings 'FTA Delay and 20H2 Optimizations.zip' (\\ProfileStorage\UEMconfig\general\FlexRepository\Settings\Reg\FTA Delay and 20H2 Optimizations.zip)
2022-01-31 12:31:05.273 [INFO ] Successfully imported 'pre' phase settings ('FTA Delay and 20H2 Optimizations.xml')
2022-01-31 12:31:05.311 [INFO ] Skipping triggered task due to conditions ('NuancePowerMic.ps1.xml')
2022-01-31 12:31:05.326 [INFO ] Skipping triggered task due to conditions ('Paccess.ps1.xml')
2022-01-31 12:31:05.337 [INFO ] Skipping triggered task due to conditions ('Trace.ps1.xml')
2022-01-31 12:31:05.349 [INFO ] Skipping disabled config file '\\ProfileStorage\UEMconfig\general\Applications\7-Zip.ini'
2022-01-31 12:31:05.351 [INFO ] Skipping disabled config file '\\ProfileStorage\UEMconfig\general\Applications\Acrobat Reader.INI'
2022-01-31 12:31:26.379 [INFO ] Skipping disabled config file '\\ProfileStorage\UEMconfig\general\Applications\Adobe Acrobat.ini'
2022-01-31 12:31:51.730 [INFO ] Skipping disabled config file '\\ProfileStorage\UEMconfig\general\Applications\Adobe LiveCycle Designer.ini'
2022-01-31 12:32:04.620 [INFO ] Skipping disabled config file '\\ProfileStorage\UEMconfig\general\Applications\Calculator.INI'
2022-01-31 12:32:04.624 [INFO ] Skipping disabled config file '\\ProfileStorage\UEMconfig\general\Applications\CamStudio.ini'

The rest of the log doesn't show any delays and the end of the log shows it taking a minute long:

2022-01-31 12:32:05.318 [INFO ] Done (60262 ms) [<<IFP#181a52cf-3e7]

Here is the same time frame from the debug log:

2022-01-31T12:31:06.299-08:00 DEBUG (0AB0-0B24) <TimerService> [ws_perfmon] System CPU use: 9%
2022-01-31T12:31:06.299-08:00 DEBUG (0AB0-0B24) <TimerService> [ws_perfmon] Physical memory use: 13%
2022-01-31T12:31:09.471-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] NestedModeServerWin::SetClientAppSettingProc Will GetImpersonatedTokenAsLogonUser.
2022-01-31T12:31:09.471-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] GetImpersonatedTokenAsLogonUser: Unable to query user token of session 1 (err 1008).
2022-01-31T12:31:09.471-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] GetImpersonatedTokenAsLogonUser: No shell window to impersonate.
2022-01-31T12:31:09.471-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] NestedModeServerWin::SetClientAppSettingProc GetImpersonatedTokenAsLogonUser failed, will try again later.
2022-01-31T12:31:25.478-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] NestedModeServerWin::SetClientAppSettingProc Will GetImpersonatedTokenAsLogonUser.
2022-01-31T12:31:25.478-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] GetImpersonatedTokenAsLogonUser: Unable to query user token of session 1 (err 1008).
2022-01-31T12:31:25.478-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] GetImpersonatedTokenAsLogonUser: No shell window to impersonate.
2022-01-31T12:31:25.478-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] NestedModeServerWin::SetClientAppSettingProc GetImpersonatedTokenAsLogonUser failed, will try again later.
2022-01-31T12:31:36.322-08:00 DEBUG (0AB0-0B24) <TimerService> [ws_perfmon] System CPU use: 0%
2022-01-31T12:31:36.322-08:00 DEBUG (0AB0-0B24) <TimerService> [ws_perfmon] Physical memory use: 13%
2022-01-31T12:31:55.087-08:00 DEBUG (0AB0-0D80) <MessageFrameWorkDispatch> [ws_vhub] Can't get a valid sessionId within 60 seconds for channel 0x000001800525B470. Already closed?
2022-01-31T12:31:55.087-08:00 INFO (0AB0-0D80) <MessageFrameWorkDispatch> [ws_vhub] USB policy set to disallowed
2022-01-31T12:31:57.478-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] NestedModeServerWin::SetClientAppSettingProc Will GetImpersonatedTokenAsLogonUser.
2022-01-31T12:31:57.478-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] GetImpersonatedTokenAsLogonUser: Unable to query user token of session 1 (err 1008).
2022-01-31T12:31:57.478-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] GetImpersonatedTokenAsLogonUser: No shell window to impersonate.
2022-01-31T12:31:57.478-08:00 DEBUG (1098-0838) <2104> [ViewMMDevRedir] NestedModeServerWin::SetClientAppSettingProc GetImpersonatedTokenAsLogonUser failed, will try again later.
2022-01-31T12:32:06.337-08:00 DEBUG (0AB0-0B24) <TimerService> [ws_perfmon] System CPU use: 1%
2022-01-31T12:32:06.337-08:00 DEBUG (0AB0-0B24) <TimerService> [ws_perfmon] Physical memory use: 13%

Does anyone see anything obvious here or what my next steps should be?  The "Unable to query user token of session 1" dont look good to me, but I'm not exactly sure what they mean.  Any help would be great!

[EmilianW1]

Hi @BertyB ,

Try using ControlUp:

https://www.controlup.com/resources/blog/entry/controlup-vmware-expand-their-partnership-with-new-pr...

You can use Script called Analyze Logon Duration. It might give you better overview at the logon process.

[chriskoch99]

All ControlUp ALD is likely to show you here is that your DEM CSE is taking a lot of seconds to process.  @BertyB  did you have any luck figuring this out?  We're fighting something similar, and my current concerns focus on NAS antivirus scanning interfering with file access.  Or maybe SMB cache timeouts, but we've already set all DirectoryCacheLifetime et al to 0.

[EmilianW1]

@BertyB ,

Please double check you initial DEM GPO config:

https://techzone.vmware.com/resource/quick-start-tutorial-vmware-dynamic-environment-manager#initial...

[Schmad7]

That setting was deprecated on version 2111. It's part of the GPO clean-up process. 

[BertyB]

@EmilianW1 

I found certain events in VMWare logs that were similar to the symptoms mentioned in this article:  https://kb.vmware.com/s/article/78014

The recommendation in the article is to implement a shutdown script via GPO that restarts Windows SMB file sharing service to cleanly disconnect communication to the server where profile data and such resides. We implemented this script and it resolved our issue.

Hope this helps!

[kvmw2130]

Hello,

Could you please elevate the DEM logging level to DEBUG it will give you more detailed information if any of the archives taking a longer time. 

To elevate logs adjust the GPO setting per screenshot: 

[chriskoch99]

@BertyB that solution sounds like an entirely plausible explanation for what we're seeing.  I'm excited to try this out.   Thanks for the follow-up!