Random logon delay when using UEM

[SummaCollege]

We are running floating desktops of Windows 10 v1703 and v1607 on VMware Horizon 7 and UEM 9.2.0.

What we are experiencing is that after enabling UEM, a random delay of about 1,5 - 2 min is added during logon. This is only happening when we immediately logon after initiating a shutdown of another machine. If we wait for about 15min after shutdown, the logon delay is not present.

We enabled verbose status messaging during logon and notice that the delay is not happening on the same part of the logon process every time. Its randomly waiting on Flexengine policy or User profile service to be applied (or any other part of logon it seems). During this delay we also noticed that the UEM console freezes and we are unable to operate the console! When the lock is gone, the logon process continues. During this delay we checked and there seems to be no lock on the UEM profile files or config files.

After logon, all seems to operate just fine.

We enabled debug logging mode for UEM and no errors or warning present.

Does anyone have a clue what could cause this?

[SummaCollege]

UEMdev​

I am in the process of redesigning our development structure in AD so i have more options in troubleshooting this issue. After that i'll try to rule out more parts of the process and i'll also try what would happen if i remove the UEM software.

I'll report back when i have more info...

[SummaCollege]

UEMdev​

One step further researching this issue.

During testing i disabled all user policies and started logging in several times. The first 4 logins were very fast, about 8 seconds!! The 5th login again was very slow.

The user vmlm logfile summary showed me the following result:

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Logon Time: 71.20 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Logon Start To Hive Loaded Time: 64.53 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Logon Start To Classes Hive Loaded Time: 64.64 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Profile Sync Time: 0.00 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Windows Folder Redirection Apply Time: 0.00 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Shell Load Time: 5.25 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Total Logon Script Time: 0.00 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] User Policy Apply Time: 0 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Machine Policy Apply Time: 0 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Group Policy Software Install Time: 0.00 seconds

2017-12-05T14:51:56.479 INFO (0f00-0340) [LogonMonitor::LogSummary] Free Disk Space Available To User: 26 GB

When searching throughout the log i found this delay:

2017-12-05T14:50:45.415 TRACE (0f00-0844) [LogonMonitor::StartShellLoadMonitor] Shell Load Monitor Started. Session: 1

2017-12-05T14:50:45.415 INFO (0f00-0844) [LogonMonitor::Logon] LOGON: User: SUMMACOLLEGE\icttestprsalg02, Session: 1

2017-12-05T14:50:46.227 TRACE (0f00-0dc8) [LogonMonitor::ProcessLogonEvent] Event Id: 1, Session: 1

2017-12-05T14:50:46.227 TRACE (0f00-0dc8) [LogonMonitor::ProcessLogonEvent] Profile Started. Session: 1

2017-12-05T14:51:50.603 INFO (0f00-0dc8) [LogonMonitor::MatchUserPolicyEvent] Assigned User Policy ActivityID {3BCBE29B-1AD0-4C2D-B5EF-2B185931C007} to Session 1

2017-12-05T14:51:50.603 TRACE (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 4001, ActivityID: {3BCBE29B-1AD0-4C2D-B5EF-2B185931C007}, Account: SUMMACOLLEGE\icttestprsalg02, Session: 1

2017-12-05T14:51:50.603 TRACE (0f00-0de8) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 5314, ActivityID: {3BCBE29B-1AD0-4C2D-B5EF-2B185931C007}, Account: , Session: 1

2017-12-05T14:51:50.603 INFO (0f00-0de8) [LogonMonitor::ProcessGroupPolicyEvent] Network Bandwidth: 40154 kbps, Slow link Threshold: 500 kbps, Slow Link: False

2017-12-05T14:51:50.603 TRACE (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 5327, ActivityID: {3BCBE29B-1AD0-4C2D-B5EF-2B185931C007}, Account: , Session: 1

2017-12-05T14:51:50.603 INFO (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Network Bandwidth On One Connection: 5019309 kbps

2017-12-05T14:51:50.603 TRACE (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Event Id: 5326, ActivityID: {3BCBE29B-1AD0-4C2D-B5EF-2B185931C007}, Account: , Session: 1

2017-12-05T14:51:50.603 INFO (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Domain Controller Discovery Time: 0.22 seconds, Error Code: 0

2017-12-05T14:51:50.650 TRACE (0f00-0dc8) [LogonMonitor::ProcessLogonEvent] Event Id: 5, Session: 1

2017-12-05T14:51:50.650 INFO (0f00-0dc8) [LogonMonitor::GetLogonStartTimeToHiveLoadedTime] Logon Start To Hive Loaded Time: 64.53 seconds. Session: 1

Don't know exactly what is happening when this delay occurs, but to me it looks like it happens before it is searching/waiting/retreiving assigned user policies. Am i right?

I have attached the logfiles from this session, including vmlm.txt

What i do find strange and i can't figure out what it means or determine if its related to the slow logins, is the fact there are a lot of the following messages throughout the whole logfile:

2017-12-05T14:51:50.603 TRACE (0f00-0dc8) [LogonMonitor::ProcessGroupPolicyEvent] Failed to find Session for User PolicyEvent Id: 5314, ActivityID: {2CF6B09C-6762-4ABD-9468-84A4DC9A87B2}, Account:

[DEMdev]

Hi SummaCollege​,

I think the [LogonMonitor::MatchUserPolicyEvent] Assigned User Policy ActivityID ... bit is logged when the user policy starts to be applied. It's strange that that is more than a minute after the logon starts, so I think that's the explanation of the delay. If only the root cause of that were known...

The Failed to find Session for User PolicyEvent Id: xyz messages occur if a Windows event log message for that particular ID is logged before the user policy has started to be applied. It seems that some of those messages even occur before the session is created, which does not make any sense to me. Also, some of those messages are for Group Policy-based software installations – are you using that?

Anyway, I really think this needs to be picked up in a Horizon forum where people hopefully know more about VMLM 🙂

[SummaCollege]

Thx again UEMdev​

I'v created a new thread in the Horizon forum: Random logon delay up to approx 120sec

Lets try and see if some experts over there might have any clue...

[SummaCollege · Accepted solution]

UEMdev Looks like we fixed the issue here. There were 2 things that needed fixing.

1) There were inconsistencies in PERC driver versions across different ESX hosts. I guess this was the main culprit. Also impacted VDI user experience during recompose actions.

2) One of the required printer drivers were missing from the Golden Image and thus was installed during login.

After fixing both of the above, logintimes of our floating desktop averages between 25 - 30 sec. Not that bad...

Now lets hope the issue is indeed permanently fixed.

[DEMdev]

That's great news, SummaCollege, thank you for letting us know! Good to have that PERC driver data point, thanks.