The Curious Case of the Slowly Populating Start Menu

The Problem

When a user was logging on to a Citrix XenApp 7.7 session it was taking up to two minutes for Receiver 4.4 to populate their start menu. Given that this was the primary way of delivering applications from that desktop, this was a showstopper.

The Troubleshooting

Frustratingly, the issue was intermittent in that occasionally all of the shortcuts would be present as soon as Explorer made the Start Menu available although more often it was at least twenty seconds before they showed up and sometimes even longer.

I tried all the usual things including:

  1. Opened the configured StoreFront URL for the store in a browser in the session for the user – no problems
  2. Disabling StoreFront load balancing (with a hosts file entry on XenApp)
  3. Disabling the mandatory profile (rename WFDontAppendUserNameToProfile and WFProfilePath values in HKLM\SOFTWARE\Policies\Microsoft\Windows NT\Terminal Services – no need for messing about with GPOs although watch for Group Policy background refreshes)
  4. Disabling customisations we were making to the Receiver settings
  5. Disabling “Check for Publisher’s certificate revocation” and “Check for server certificate revocation” in Internet Properties
  6. CDF Tracing (resulting in a csv trace with other 138,000 lines!)
  7. Various different command line options to selfservice.exe (the handy SysInternals Strings.exe utility revealed some undocumented ones like -fastConnectLogon) See http://support.citrix.com/article/CTX200337
  8. SysInternals Process Monitor (procmon)
  9. Renaming the files for some of the launched Citrix processes, like ceip.exe (Customer Experience Improvement Program) and Win7LookAndFeelStartupApp.exe that featured in the procmon trace, so they wouldn’t run

Process Monitor showed that it was only the AuthManSvr.exe process (one of the many that SelfService.exe and SSOnSvr.exe launch for the user) that communicated with the StoreFront server and yet the IIS logs on the StoreFront server showed that this particular XenApp server (via its IPv4 address in the log) wasn’t generating any requests until a good twenty seconds, or more, after SelfService.exe was launched.

So I then set about finding out how to enable logging for AuthManSvr and SelfService which didn’t take long with the help of Google – in HKLM\Software\Wow6432Node\Citrix\AuthManager, add a REG_SZ value “LoggingMode” set to “Verbose” and “TracingEnabled” set to “True”. For SelfService logging, see http://support.citrix.com/article/CTX123544 which was enabled by temporarily adding the required file to the local mandatory profile.

Looking first in the SelfService.txt log file, located in %LocalAppData%\Citrix\SelfService, I looked for large gaps in the time stamps and found the following:

10/16:56:45 authman D CtxsJobL: Created AuthManager connection
10/16:56:45 dservice ? CtxsJobL: Do HTTP Request
10/16:56:45 dservice > CtxsJobL: {
10/16:57:05 dservice ? CtxsJobL: }00:00:20.0422895

Where the “10/” is the date so we have a twenty second gap and this correlates with the “00:00:20.0422895” which is presumably the exact duration of the request.

I then cross referenced this time to the AuthManSvr.txt log file, located in %LocalAppData%\Citrix\AuthManager\Tracing, and found this section:

02/10/16 16:56:45 > T:00002FA0 . . . . . . Trying proxy auto-detect (WPAD)
02/10/16 16:56:45 > T:00002FA0 . . . . . . {
02/10/16 16:56:45 > T:00002FA0 . . . . . . . CWindowsNetworkServices::TryGetAutoProxyForUrl
02/10/16 16:56:45 > T:00002FA0 . . . . . . . {
02/10/16 16:57:03 *WRN* T:00001D90 . . . . . . . WinHttpGetProxyForUrl call failed; last error=12180
02/10/16 16:57:03 < T:00001D90 . . . . . . }
02/10/16 16:57:03 < T:00001D90 . . . . . }
02/10/16 16:57:03 T:00001D90 . . . . . Using manual proxy config.
02/10/16 16:57:03 T:00001D90 . . . . . The manual proxy info settings contains an empty proxy list string.
02/10/16 16:57:03 T:00001D90 . . . . . No proxy info found
02/10/16 16:57:03 < T:00001D90 . . . . }
02/10/16 16:57:05 *WRN* T:00002FA0 . . . . . . . . WinHttpGetProxyForUrl call failed; last error=12180
02/10/16 16:57:05 < T:00002FA0 . . . . . . . }
02/10/16 16:57:05 < T:00002FA0 . . . . . . }

Having troubleshot an issue only last month where the Receiver was stalling whilst making a connection to a  published application that turned out to be caused by “Automatically Detect Settings” in Internet Properties being ticked, I reckoned we were seeing a similar issue since WPAD is mentioned above which is the mechanism used for autodiscovery of proxy settings.

The Solution

I therefore set about proving this theory by getting the “Automatically Detect Settings” tickbox unticked at logon before AuthMgr.exe is launched. It’s not unfortunately straightforward as there isn’t a GPO setting for it and if you monitor the registry when you change the setting manually (using procmon with a filter set on “Operation” is “RegSetValue”) you’ll find it’s changing a single bit in a large REG_BINARY value. As I was using AppSense Environment Manager, I knocked up the following PowerShell in a custom action in a logon node (comments removed for brevity):

[string]$regKey = “HKCU:\Software\Microsoft\Windows\CurrentVersion\Internet Settings\Connections”
[string]$regValue = “DefaultConnectionSettings”

$current = Get-ItemProperty -Path $regKey -Name $regValue | Select -ExpandProperty $regValue

if( $current -ne $null -and $current.Count -gt 8 )
{
$old = $current[8]
$current[8] = $current[8] -band 0xF7

if( $current[8] -ne $old )
{
Set-ItemProperty -Path $regKey -Name $regValue -Value $current
}
}

And that folks was how I spent my day today! The joys of being a  consultant!

I hope it helps someone else solve this problem as I did find other reports of this issue in my searches on the web for a ready made solution (if only!).

Advertisements

Author: guyrleech

I wrote my first (Basic) program in 1980, was a Unix developer after graduation from Manchester University and then became a consultant, initially with Citrix WinFrame, in 1995 and later into Terminal Server/Services and more recently virtualisation, being awarded the VMware vExpert status in 2009 and 2010. I have also had various stints in Technical Pre-Sales, Support and R&D. I work as a Senior Technical Consultant for HCL, live in West Yorkshire, England; have a wife, three children and three dogs and am a keen competitive runner when not injured.

3 thoughts on “The Curious Case of the Slowly Populating Start Menu”

  1. Because the AuthMgrSrv process is launched very early in the logon process by ssonsvr.exe, for consistent results I found it was necessary to set the “DefaultConnectionSettings” value in the mandatory profile we were using in order for it to get set early enough for AuthMgrSrv.exe to pick it up.

  2. Many Thanks Guy! I was on the right way – but you gave me the confirmation.
    We’ve saw this behaivour on ThinClients after some days (About 80 days) and we did a workaround be disabling the writecache. But now, after the 3 time i spend some hours to troubleshoot this problem. And I think exactly your way did the trick. Thanks

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s