Wednesday, March 30, 2016

AppV5 - Package {GUID} version {GUID} failed configuration in folder '%packageinstallationroot% with error 0x4C40310C-0x12

We experienced this error on a package on one of our Citrix servers in the AppV\Client\Admin event logs.  Attempting to procmon this error didn't reveal anything substantial for what could be causing this issue.  I then tried my last post to enable AppV debug logs to see if we can see what's going on.

Because this server was being used by other users the log generated a lot of noise.  I stopped the log as soon as I got the error message though, which meant the error should be at the end of the generated log.  Fortunately, you can search for the error message:

[2]06B0.2DE4::‎2016‎-‎03‎-‎30 09:41:30.817 [Microsoft-AppV-Client]Package {499ed340-c809-47dc-a533-2cdeab537e93} version {3589c28b-edb7-41d6-865d-e01c4fdd4318} failed configuration in folder 'D:\AppVData\PackageInstallationRoot\' with error 0x4C40310C-0x12. 

I suspect the first bit of hexadecimal code (06B0.2DE4) are probably an identifier for a thread or some such so I suspect if I search for just this code I can be shown all events that lead up to this error:

Looks like it.

The log up to the error:

With the error time code, I can compare what Procmon says is going on.  And procmon reports back the following (at exactly 09:41:30.815):

Procmon has the AppVClient.exe doing the following action "QuerySecurityFile" and it's looking for "Information:Owner".  So what is this the value of this property?

Hmmm...  This does not look correct to me.  From my experience, I think the current owner ends up being 'SYSTEM' because that's the account the AppVClient.exe runs under when it creates this folder.  As a hunch, I looked at a system that is operating correctly and compared it's Owner attribute:

Sure enough, on a working system the Owner is SYSTEM.  So I'll attempt to modify the non-working system and retry adding the package:

Success!  So it appears this error "0x4C40310C-0x12" is DIRECTLY related to the ownership attribute on your PackageInstallationRoot folder.  If it is anything but SYSTEM it looks like it fails.  I do not know why that attribute changed, but changing it back to SYSTEM resolves this error code.

Thursday, March 24, 2016

AppV5 - The trouble with AppV5 logs (and a solution!)

AppV5 introduced to us a slew of logs that made troubleshooting more difficult than it should have been.

For instance, say you get an error message:

How do you start debugging this?  Well, you could start by trying to decipher the error message AppV has generated to a decimal value that you can then look at the first two digits to determine which 'part' of AppV generated the error and you can examine that specific log.  Sounds kind of ridiculous when you spell it out.

Another thing you could do is you could enable all logs just to be sure, but then you have to sift through the logs to find the time stamp that corresponds closest to the event that generated the message.  Sometimes it would be too far or close together or the debug logs generate so much information that your event viewer is just one big blob of 'the exact same time'.

One of these could be the cause of my issue.  Going through them all is extremely cumbersome.

Of course this isn't true that all these events are the same time, but it's all event viewer can display.  If you view the XML of the event you can see there is more precise time stamps, but regardless, trying to compare each event with other logs is cumbersome and very difficult.

Is there a better way?

Yes!  There is!  And Microsoft has actually documented it here:

This is a powershell script that generates a ETL file on your desktop then converts it to a text format.  The script is:

What does the output look like?

First thing to notice is that it's sorted chronologically, so if you can get a narrow time range to examine the error occurring it should be easier to spot.  Second thing is all event logs are added, and events themselves are included as they are generated.  So it should be easier to finding that specific component that causes the error.

If you are encountering AppV5 errors, this may be easier to help track down the error then trying to sift through the debug logs in event viewer.

Thursday, March 17, 2016

AppV5 - Package fails to load with error 0x79100E100-0xC (Starring Procmon)

We were having an issue with a AppV5 package loading and we received the following error message:
Event ID 1008
Package {b8b01729-ed31-4d77-a859-dbd8b82a3372} version {e1d21ac7-84f0-4ab7-998f-e3258be91298} failed configuration in folder 'D:\AppVData\PackageInstallationRoot\B8B01729-ED31-4D77-A859-DBD8B82A3372\E1D21AC7-84F0-4AB7-998F-E3258BE91298' with error 0x79100E10-0xC.

This message is preceeded by this message:
Event ID 4009
machine script for event AddPackage with command line: 'cmd.exe' exited with failure error code: Incorrect function.. Because Rollback is set to true in the script definition, the current AppV Client operation was rolled back.

I started investigating.  The first thing I did was open a powershell window and tried to load the package via the command line:

I then looked at our DynamicDeployment XML file and examined the script it is trying to launch:

The script it's trying to launch looks like this:

Since this is a Machine Script, I started a process monitor capture, executed my command, stopped the capture then used the "Process Tree"

and clicked on AppVClient.exe and clicked "Include Subtree".

 and used the "show process and thread activity".  I filtered on 'Detail' 'Begins with' and set it for both Parent and Exit so I can look at the process path and exit codes:

The 'exit code' is '1' (Exit Status: 1) which means an error occurred that caused the script to fail.  So now we dive into that script and see why it's failing:

From looking at the script, it's trying to create a new 'mklink' path.  If I try and run this command manually, I get the following:

So this is where the errorlevel (also exit code) is being set.  The last error level is 1 which becomes the exit code once the script runs 'EXIT.

So, there are two methods I can think of to solve this problem.

1) I can set EXIT /B 0 to always set EXIT to report and error code of '0'.
2) Check to see if the path already exists and then EXIT

I chose to modify the script to exit if the path exists.  I changed it like so:

I cleared procmon, set it to trace again and attempted to run the add-appvclientpackage command again.

I selected 'AppVClient.exe' and clicked 'Include Subtree'

This time we can see that the 'AHS-ATOP.cmd' script has an 'Exit Status: 0' which means it completed successfully.  But, the next script, 'AHS-SoftWorksGroup-ScreenTestIII.cmd' with the parameter 'INSTALL' fails with 'Exit Status: 1'.  Again, we look into the script...

We can see it has the same flaw.  I then modified the script to add the same IF EXISTS check.  I then cleared procmon and reattempted to add the package.


Hurray!  The package loaded and the scripts ran correctly.

 An alternative to all of this is I could have changed the 'rollback' to 'false' in the DeploymentConfig.xml file, but I would rather the package *not* load if the 'INSTALL' script fails for whatever reason.  This ensures an error is generated that needs to be dealt with rather than potentially having a half-working package.  These INSTALL scripts were simple enough that a simple directory check would suffice to ensure it's working and that's what I've done.

Monday, March 14, 2016

WSUS clients fail with WARNING: Exceeded max server round trips: 0x80244010

J C Hornbeck/Joe Tindale touched on this topic on a Microsoft blog post here.

In that post he touches on what's actually happening:

Cause: The error, 0x80244010, means WU_E_PT_EXCEEDED_MAX_SERVER_TRIPS and happens when a client has exceeded the number of trips allowed to a WSUS server.  We have defined the maximum number of trips as 200 within code and it cannot reconfigured.  A “trip” to the server consist of the client going to the server and saying give me all updates within a certain scope.  The server will give the client a certain number of updates within this trip based on the size of the update metadata.  The server can send 200k worth of update metadata in a single trip so it’s possible that 10 small updates will fit in that single trip.  Other larger updates may require a single trip for each update if they exceed the 200k limit.  Due to the way Office updates are published you are more likely to see this error if you’re syncing Office updates since their metadata is typically larger in size.
I've bolded the more important information.  This is hardcoded and cannot be reconfigured.  This, to me, is a bit ridiculous that it can't be reconfigured.  

I have a WSUS client where we 'reset' the Windows Update client.  After resetting the client we were getting an error "WARNING: Exceeded max server round trips: 0x80244010".  We would try multiple times but this error wouldn't go away and prevented us from running Windows Update on this system.  So I started to investigate.  The first thing I did was finish reading that blog entry.  Hornbeck continues:

The client takes these new updates as they trickle down and inserts them into a small database to cache them for future use.  So during the first client synchronization with WSUS the client may get 75% of the available updates, put them into the database, and then fail at some point due to the number of max trips being exceeded.  The good news is the second synchronization cycle will not need to start from the beginning since the client has already cached 75% of the updates into its database.  The second cycle will pick up where it left off and most likely finish getting all the updates from the server.  There have been a few rare cases where a third scan cycle is needed but more often than not two is sufficient.

Again, I have bolded and underlined the important parts.  

I started my investigation by trying to replicate the problem.  I started up Windows Update and 'checked for updates'.

Ok, no problem.  So I checked again.

Well, Hornbeck/Tindale did say it may take a couple passes.  Let's try again.

I'm getting worried now...  Let's try a fourth time.

Hmmm...   At this point I wanted to better understand what Windows Update was doing.  I originally installed Wireshark to trace the conversation but it was difficult and time consuming to try and count the traffic back and forth to the WSUS server.  So I reverted my system and installed Fiddler2 on it.

From the video you can actually see the traffic from the WSUS server.  The request for the 'Updates' starts at item 3 and completes at 203.  Exactly 200 round trips.

Since my previous Windows Update attempts at the WSUS server failed after a few tries I thought I would trace the traffic with Fiddler for the multiple attempts.  My logic was I wanted to know if the traffic was 'looping'; repeating itself and getting to the limit preventing updates.  Or, would each send/receive be unique and thus, simply, more is needed?

The first bit of the first run.  If the second run as identical or near identical traffic 'packet sizes' I would be concerned it's looping...

I reset Fiddler and started the second run.  Completely different!
When I started the second run I was happy to see it was a completely different result.  I cleared Fiddler for a 3rd time ran the 'Check for Updates' until it timed out again, and cleared Fiddler again.  I then thought to just let Fiddler capture everything.  There really is no need to clear it each time.  I monitored the Fiddler output looking for loops or patterns.  The update check timed out a forth time (as before).  There was no looping I could see.

Finally, on the fifth run:

Updates!  We have updates!

In the end, when the Microsoft blog post was written (2008) there probably was only enough updates that two or three passes would go through all of them.  As time as gone on and more and more updates have been deployed to systems this hardcoded maximum is doing a huge disservice.  Our Windows 2008R2 SP1 systems require FIVE passes of clicking/waiting/clicking/waiting/etc.

A natural solution to this is to expose the "max server round trips" variable and allow it to be programmed by the organization according to their needs.  The present state of this issue is unnecessarily confusing and arbitrarily limited.

Friday, March 11, 2016

AppV5 - Sequencing Logibec eClinibase

I was given a new application to sequence:
Logibec's eClinibase.

This application has some restrictions:
1) It has an updater that will pull down .exe's
2) It won't launch from a script in the bubble.  Example:
cd /d C:\Logibec\eClinibase\ilgi11

Will crash.

I'm going to address point 2) first because it's weird and interesting.

Why does it crash?  Because, somehow, it breaks out of the bubble.  The reason it crashes is it looking for some registry keys that don't exist outside the bubble and it explodes.  The keys it looks for are:

On a local install if I delete the environment keys that matchup to the folder we're launching eClinibase from, I get the same error.  Since those keys don't exist outside the bubble, we get the same error...  Which means it's trying to look outside the bubble for some reason.  Powershell, however, works correctly but only if the exe is called directly:

However, we CAN get it to stay 'in the bubble' if we launch the eClinibase.exe with the /appvve: switch.

This is the first time I've ever encountered this where launching the application from a command prompt inside the AppV bubble fails, but it will work if you launch the exe with the /appvve: switch.

So that's weird that we need to launch it specifically that way, but it appears to work so I guess that's a limitation we have to roll with.

So how do we address point 1)?

I've used this technique before and it works here.  We will create a directory symlink to a network file share where the users will have full permission to update the application.  Since these updates occur 'as needed' the different environments may update at different times, this keeps them in sync across all of our Citrix servers since they will all point to the same location.

I add the mklink command the DynamicDeploymentConfig.xml:

And we are good to go!