When even Process Monitor isn’t enough

I was recently tasked to investigate why an App-V 5.1 application was giving a license error at launch on XenApp 7.8 (on Server 2008R2) when the same application installed locally worked fine. I therefore ran up the trusty Process Monitor (procmon) tool to get traces on the working and non-working systems so I could look for differences. As I knew what the licence file was called, I honed in quickly on this in the traces. In the working trace, you could see it open the licence file, via a CreateFile operation, and then read from the file. However, in the App-V version it wasn’t reading from the file (a ReadFile operation) but no CreateFile operation was failing so I couldn’t understand why it wasn’t even attempting to read from the file when it didn’t appear to be unable to access it. The same happened when running as an administrator so it didn’t look like a file permission issue.

Now whilst procmon is a simply awesome tool, such that life without it would be an unimaginably difficult place, it does unfortunately only tell you about a few of the myriad of Microsoft API calls. In order to understand even more of what a process is doing under the hood, you need to use an API monitor program that has the ability to hook any API call available. To this end I used WinAPIOverride (available here). What I wanted was to find the calls to CreateFile for the licence file and then see what happened after that, again comparing good and bad procmon traces.

WinAPIOverride can launch a process but it needs to be inside the App-V bubble for the app in order for it to be able to function correctly. We therefore run the following PowerShell to get a PowerShell prompt inside the bubble for our application which is called “Medallion”:

$app = Get-AppvClientPackage | ?{ $_.Name -eq 'Medallion' };
Start-AppvVirtualProcess -AppvClientObject $app powershell.exe

We can then launch WinAPIOverride64.exe in this new PowerShell prompt, tell it what executable to run and then run it:

winapioverride-launch

Note that you may not be able to browse to the executable name so you may have to type it in manually.

Once we tell it to run, it will allow us to specify what APIs we want to get details on by clicking on the “Monitoring Files Library” button before we click “Resume”.

api-monitor-hook

You need to know the module (dll) which contains the API that you want to monitor. In this case it is kernel32.dll which we can glean from the MSDN manual page for the CreateFile API call (see here).

api-monitor-kernel32

Whilst you can use the search facility to find the specific APIs that you want to monitor and just tick those, I decided initially to monitor everything in kernel32.dll, knowing that it would generate a lot of data but we can search for what we want if necessary.

So I resumed the process, saw the usual error about the licence file being corrupt, stopped the API monitor trace and set about finding the CreateFile API call for the licence file to see what it revealed. What I actually found was that CreateFile was not being called for the licence file but when I searched for the licence file in the trace, it revealed that it was being opened by a legacy API called OpenFile instead. Looking at the details for this API (here), it says the following:

you cannot use the OpenFile function to open a file with a path length that exceeds 128 characters

Guess how long the full path for our licence file is? 130 characters! So we’re doomed it would seem with this API call which we could see was failing in API monitor anyway:

medallion-open-file

I suspect that we don’t see this in procmon as the OpenFile call fails before it gets converted to a CreateFile call and thence hits the procmon filter driver.

The workaround, as we found that the installation wouldn’t work in any other folder than c:\Medallion so we couldn’t install it to say C:\M, was to shorten the package installation root by running the following as an admin:

Set-AppvClientConfiguration -PackageInstallationRoot '%SystemDrive\A'

This changes the folder where App-V packages are cached from “C:\ProgramData\App-V” to “C:\A” which saves us 18 characters. The C:\A folder needed to be created and given the same permissions and owner (system) as the original folder. I then unloaded and reloaded the App-V package so it got cached to the \A folder whereupon it all worked properly.

Advertisements

Exporting validated shortcuts to CSV file

In a recent Citrix XenApp 7.x consulting engagement, the customer wanted to have a user’s start menu on their XenApp desktop populated entirely via shortcuts created dynamically at logon by Citrix Receiver. Receiver has a mechanism whereby a central store can be configured to be used for shortcuts such that when the user logs on, the shortcuts they are allowed are copied from this central share to their start menu. For more information on this see https://www.citrix.com/blogs/2015/01/06/shortcut-creation-for-locally-installed-apps-via-citrix-receiver/

Before not too long there were in excess of 100 shortcuts in this central store so to check these individually by examining their properties in explorer was rather tedious to say the least so I looked to automate it via good old PowerShell. As I already had logon scripts that were manipulating shortcuts, it was easy to adapt this code to enumerate the shortcuts in a given folder and then write the details to a csv file so it could easily be filtered in Excel to find shortcuts whose target didn’t exist although it will also output the details of these during the running of the script.

I then realised that the script could have more uses than just this, for instance to check start menus on desktop machines so decided to share it with the wider community.

The get-help cmdlet can be used to see all the options but in its simplest form, just specify a -folder argument to tell it where the parent folder for the shortcuts is and a -csv with the name of the csv file you want it to write (it will overwrite any existing file of that name so be careful).

It can also check that the shortcut’s target exists on a remote machine. For instance, you can run the script on a Citrix Delivery Controller but have it check the targets on a XenApp server, via its administrative shares, by using the -computername option.

If you run it on a XenApp server with the “PreferTemplateDirectory” registry value set, use the -registry option instead of -folder and it will read this value from the registry and use that folder.

If you’re running it on a desktop to check that there are no bad shortcuts in the user’s own start menu, whether it is redirected or not, or in the all users start menu then specify the options -startmenu or -allusers respectively.

Finally, it can email the resultant csv file via an SMTP mail server using the -mailserver and -recipients options.

The script is available for download here.

Getting the PVS RAM cache usage as a percentage

Citrix Provisioning Services has long been one of my favourite products (or Ardence as it originally was before being purchased by Citrix and that name still appears in many places in the product). It has steadily improved over time and the cache to RAM with overflow to disk feature is great but how do you know how much of the RAM cache has been used? We care about this because if our overflow disk isn’t on SSD storage then using the overflow file could cause us performance degradation.

The PVS status tray program doesn’t tell us this as it just displays the sum of the free disk space available where the overflow disk resides (vdiskdif.vhdx) plus the RAM cache size and the usage of the overflow disk, not the RAM cache usage.

PVS cache

There are a number of articles out there that show you either how to get the non-paged pool usage, which gives a rough indication, or to use the free Microsoft Poolmon utility to retrieve the non-paged pool usage for the device driver that implements the cache. There’s a great article here on how to do this. Poolmon is also very useful for finding what drivers are causing memory leaks although now that most servers are 64 bit, there isn’t the problem there used to be where non-paged pool memory could become exhausted and cause BSoDs.

However, once we have learnt what the RAM cache usage is, how do we get that as a percentage of the RAM cache configured for this particular vdisk ? I looked at the C:\personality.ini file on a PVS booted VM (where the same information is also available in “HKLM\System\CurrentControlSet\services\bnistack\PVSAgent”) but it doesn’t have anything that correctly tells us the cache size. There is a “WriteCacheSize” value but this doesn’t seem to bear any relation to the actual cache size so I don’t use it.

With the release of PVS 7.7 came a full object based PowerShell interface so it is now very easy to interrogate PVS to find (and change!) all sorts of information including the properties of a vdisk such as its RAM cache size (if it is set for Cache to RAM, overflow to disk which is type 9 if you look at the $WriteCacheType entry in personality.ini). So in a health reporting script that I’m running for all XenApp servers (modified from the script available here) I run the following to build a hash table of the RAM cache sizes for all vdisks:

[string]$PVSServer = 'Your_PVS_Server_name'
[string]$PVSSiteName = 'Your_PVS_Site_name'
[hashtable]$diskCaches = ${}
Invoke-Command -ComputerName $PVSServer { Add-PSSnapin Citrix.PVS.SnapIn ; `
	Get-PvsDiskInfo -SiteName $Using:PVSSiteName } | %{ `
    if( $_.WriteCacheType -eq 9 ) ## cache in RAM, overflow to disk
    {
        $diskCaches.Add( $_.Name , $_.WriteCacheSize )
    }
}

Note that this requires PowerShell 3.0 or higher because of the “$using:” syntax.

Later on when I am processing each XenApp server I can run poolmon.exe on that server remotely and then calculate the percentage of RAM cache used by retrieving the cache size from the hash table I’ve built by using the vdisk for the XenApp server as the key into the table.

## $vdisk is the vdisk name for this particular XenApp server
## $server is the XenApp server we are processing
$thisCache = $diskCaches.Get_Item( $vdisk ) ## get cache size from our hash table
[string]$poolmonLogfile = 'D:\poolmon.log'
$results = Invoke-Command -ComputerName $server -ScriptBlock `
	{ Remove-Item $using:poolmonLogfile -Force -EA SilentlyContinue ; `
	C:\tools\poolmon.exe -n $using:poolmonLogfile ; `
	Get-Content $using:poolmonLogfile -EA SilentlyContinue | `
		?{ $_ -like '*VhdR*' } }

if( ! [string]::IsNullOrEmpty( $results ) )
{           
        $PVSCacheUsedActual = [math]::Round( ($results -split "\s+")[6] / 1MB  )
        $PVSCacheUsed = [math]::Round( ( $PVSCacheUsedActual / $thisCache ) * 100 )
        ## Now do what you want with $PVSCacheUsed
}

Finding out the usage of the overflow to disk file is just a matter of getting the size of the vdiskdif.vhdx file which is achieved in PowerShell using the Get-ChildItem cmdlet and then accessing the “Length” attribute.

(Get-ChildItem "\\$server\d$\vdiskdif.vhdx" -Force).Length

We can then get the free space figure for the drive containing the overflow file using the following:

Get-WmiObject Win32_LogicalDisk -ComputerName $Server 
	-Filter "DeviceID='D:'" | Select-Object -ExpandProperty FreeSpace

So now I’ve got a script I can run as a scheduled task to email a report of the status of all XenApp servers including their PVS cache usage.

citrix health

First Experiences with XenApp 7.8 & App-V 5.1

Background

I’m currently working on a new XenApp rollout for a customer where we’ve been eagerly awaiting the 7.8 release to have a look at the App-V integration given that it promised to remove the need for separate App-V server infrastructure.

I’m not going to go into details here of how you make App-V applications available natively in XenApp/XenDesktop as that is covered elsewhere such as here. That article also covers troubleshooting and how to enable logging.

How it appears to work

When the Citrix Desktop Service (BrokerAgent) starts on your XenApp server, it communicates with a Delivery Controller and writes the details to the “ApplicationStartDetails” REG_MULTI_SZ value in “HKLM\SOFTWARE\Policies\Citrix\AppLibrary”. Now why it writes to the policies key when we’re not actually setting anything to do with App-V in policies I don’t know but a key is a key (unless it’s a value!). A typical line in this value looks like this:

56c1d895-e3d8-4dcc-a303-b0162a97c87b;\\ourappvserver\appvshare\thisapp\thisapp.appv;de0a5cd1-3264-4418-82dd-4bdf5959a29d;957c71c9-a732-401b-b354-17c493decac8;This App

Where the fields are semicolon delimited thus:

App-V App  GUID;Package UNC;App-V Package GUID;Published App Name

The BrokerAgent then downloads all .appv packages that you’ve added to your delivery groups to the “%SystemRoot%\Temp\CitrixAppVPkgCache” folder. This is regardless of whether App-V has been configured with a Shared Content Store. As this happens at boot, the packages should be locally cached by the time users logon who might want to run one of the published App-V applications so you’re trading system drive disk space with speed of launch. I’ve yet to see how this impacts on PVS cache in RAM so we may look at whether we can pre-populate the cache in the PVS master image so we don’t lose write cache when .appv packages are downloaded when the image is booted into shared mode.

There is a gotcha here though in that because Citrix use PowerShell to integrate with App-V so that if your PowerShell execution policy does not allow local scripts to be run, such as being set to “Restricted” which is the default, then the App-V integration will not work which can be seen in the above cache folder not populating and apps erroring when launched. To get around this, we set the execution policy to “RemoteSigned” in the base PVS image so we didn’t have to rely on group policy getting applied before the BrokerAgent starts.

We’re giving users all of their applications via Receiver generated shortcuts which is where the next small issue arises in that the shortcuts that Receiver (actually SelfService.exe) generates for App-V run SelfService.exe so effectively a new logon session is created, which can be seen by running quser.exe, to host the App-V application. Ultimately, Citrix call their own launcher process, CtxAppVLauncher.exe, which sits in the VDA folder and is installed with the VDA by default. This then uses PowerShell to launch the  App-V application from the %AllUsersProfile%\App-V folder (using sparse files so disk space is efficiently managed). You do still need to have the Microsoft App-V client installed though, since that’s what runs the App-V package, as you’d kind of expect.

This second logon all takes time though so we decided to cut out the middle man, selfservice.exe, and make the shortcut run CtxAppvLauncher.exe directly which takes the App-V app GUID as its single argument. This we do with a PowerShell script, run at logon (actually via AppSense Environment Manager), that was initially designed to check that pinned Receiver shortcuts were still valid and to update their icons as these are dynamically created, and named, at each logon (we’re using mandatory profiles). This was extended to find shortcuts for App-V apps, by matching the application name in the shortcut target with the data found in the “ApplicationStartDetails” registry value, and then changing them to run CtxAppVLauncher.exe, instead of SelfService.exe, with the App-V app GUID found in this registry value.

It does seem slightly strange though that we’ve had to go to these lengths to create locally launched App-V apps although the results are quite impressive in that the apps launch almost instantly due to the caching.

There may be further posts on the App-V integration depending on what else we unearth. Looking at FTAs (File Type Associations) is definitely on the agenda.

 

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!).