procmon

User Profile Manager – Unavoidable Delays

2018-06-30
/ /
in Blog
/

I’ve been exploring optimizing logon times and noticed “User Profile Service” always showed up for 1-3 seconds.  I asked why and began my investigation.

The first thing I needed to do is separate the “User Profile Service” into it’s own process.  It’s originally configured to share the same process as other services which makes procmon’ing difficult.

Making this change is easy:

Now that the User Profile Service is running in it’s own process we can use Process Monitor to target that PID.

I logged onto the RDS server with a different account and started my procmon trace.  I then logged into server:

One of the beautiful things about a video like this is we can start to go through frame-by-frame if needed to observe the exact events that are occurring.  Process Monitor also gives us a good overview of what’s happening with the “Process Activity” view:

9,445 file events, 299,668 registry events.  Registry, by far, has the most events occurring on it.  And so we investigate:

  1. On new logins the registry hive is copied from Default User to your profile directory, the hive is mounted and than security permissions are set.

    Setting the initial permissions of the user hive began at 2:14:46.3208182 and finished at 2:14:46.4414112.  Spanning a total time of 121 milliseconds.  Pretty quick but to minimize logon duration it’s worth examining each key in the Default User hive and ensuring you do not have any unnecessary keys.  Each of these keys will have their permissions evaluated and modified.
  2. The Profile Notification system now kicks off.

    The user profile server now goes through each “ProfileNotification” and, if it’s applicable, executes whatever action the module is responsible for.  In my screenshot we can see the User Profile Service alerts the “WSE”.  Each key actually contains the friendly name, giving you a hint about its role:

    It also appears we can measure the duration of each module by the “RegOpenKey” and “RegCloseKey” events tied to that module.

    In my procmon log, the WSE took 512ms, the next module “WinBio” took 1ms, etc.  The big time munchers for my system were:
    WSE: 512ms
    SyncCenter: 260ms
    SHACCT: 14ms
    SettingProfileHandler: 4ms
    GPSvc: 59ms
    GamesUX: 60ms
    DefaultAssociationsProfileHandler: 4450ms (!)
  3. In the previous screenshot we can see the ProfileNotification has two events kicked off that it runs through it’s list of modules: Create and Load.  Load takes 153ms in total, so Create is what is triggering our event.
  4. DefaultAssociationsProfileHandler consumes the majority of the User Profile Service time.  What the heck is it doing?  It appears the Default Association Profile Handler is responsible for creating the associations between several different components and your ability to customize them.  It associates (that I can see):
    ApplicationToasts (eg, popup notifications)
    RegisteredApplications
    File Extensions
    DefaultPrograms
    UrlAssociations
    The GPO “Set Default Associations via XML file” is processed and the above is re-run with the XML file values.
  5. Do we need these associations?

    Honestly…   Maybe.

    However, does this need to be *blocking* the login process?  Probably not.  This could be an option to be run asynchronously with you, as the admin, gambling that any required associations will be set before the user gets the desktop/app…  Or if you have applications that are entirely single purpose that simply read and write to a database somewhere than this is superfluous.

  6. Can we disable it?

    Yes…

    But I’m on the fence if this is a good idea.  To disable it, I’ve found deleting the “DefaultAssociationsProfileHandler” does work, associations are skipped and we logon 1-4 seconds faster.  However, launching a file directly or shortcut with a url handler will prompt you to choose your default program (as should be expected).

I’m exploring this idea.  Deleting the key entirely and using SetUserFTA to set associations.

We have ~400 App-V applications that write/overwrite approximately 800 different registered applications and file extensions into our registry hive (we publish globally — this puts them there).  This is the reason why I started this investigation is some of our servers with lots of AppV applications were reporting longer UserProfileService times and tying it all together, this one module in the User Profile Service appears to be the culprit.  And with Spectre increasing the duration of registry operations 400% this became noticeable real quick in our testing.

Lastly, time is still being consumed on RDS and server platforms by the infuriating garbage services like GamesUX (“Games Explorer”).  It just tweaks a nerve a little bit when I see time being consumed on wasteful processes.

Read More

AppV 5 – Raiser’s Edge 7.96 – Run-time error -2147024770 (800707e)

2017-12-15
/ /
in Blog
/

We are in the process of upgrading Blackbaud’s Raiser’s Edge to 7.96 and we encountered an error:

Run-time error ‘-2147024770 (8007007e)’:
Automation error
The specified module could not be found.

This error is giving us a few clues as to what might be happening.  The most obvious message is the “8007007e” which is a standard windows error hex code which translates to:

8007007E = FileNotFoundException

So RE7.exe is not finding a file it’s looking for.  With most AppV packages we can suss out the file it’s missing by using procmon and tracing for “FILE NOT FOUND” in the result field.  Unfortunately, my searching for this message did NOT result in finding a file that wasn’t resolved by another path.  In other words, all files were accounted for.  But the error message very clearly states that a file is missing.  So the next step is to install the application locally and compare the launch differences between the local install and the AppV install.  Again, process monitor makes this easy by using the “loaded modules” option.

The differences I found between a local install of this application and the AppV launch looked like so:

The launches were identical, until the highlighted points.  The local install, which works without issue, has an extra file that gets loaded.  bbcor7.dll.

It appears, somehow, this file is getting loaded and registered dynamically on a local install, but this is not happening with the AppV install.  I don’t see the file get searched for at all with the AppV install and tracing with procmon.  However, executing a regsvr32 /s “C:\Program Files (x86)\Blackbaud\The Raisers Edge 7\DLL\bbcor7.dll” during sequencing does do all the necessary work to register and allow RE7.exe to find and load the file in an AppV bubble.

So, long story short, execute:

While sequencing your AppV package and this should fix this issue.

Here is my entire sequencing script:

 

Read More

AppV5 – Microsoft Visual C++ Runtime Library – Error R6034

2017-05-05
/ /
in Blog
/

We packaged an application that was giving out an error message at a certain point in the program:

————————— Microsoft Visual C++ Runtime Library ————————— Runtime Error! Program: D:\AppVData\PackageInstallationRoot\7336984D-A43A-4EE3-A223-09E50C2E4A04\8B9E7007-D87F-4620-9B10-F06320BB1B… R6034 An application has made an attempt to load the C runtime library incorrectly. Please contact the application’s support team for more information. ————————— OK —————————

 

Fortunately, this was a nice repeatable error.

What happens is the program generates this message when it’s importing a word doc into its database.  This error message doesn’t stop the program from importing or causes a failure, and the process actually completes successfully.  Even stranger is after this message appears and you click OK it will not pop up again and you can repeat the process ad infinitum without this prompt…  Until you quit and relaunch the program.  Then it will prompt the first time but then never after.

But having this prompt even once is unacceptable to our users.  So how can we solve it?  Let’s examine the clues we’ve been given.  “An application has made an attempt to load the C runtime library incorrectly”.  So it’s crashing when loading a Visual C++ Runtime Library.  Which file?  Unfortunately, the path got truncated.  But Procmon will tell us!  I opened procmon, set it only look for ‘Load Image’ operations and then traced the process name.  This is where it crashed:

 

It crashed loading the MSVCR80.dll.  What’s curious is this DLL and the version and everything exist natively in the system.  I’m unsure why it was captured but the program is deferring to the AppV msvcr80.dll as opposed to the natively installed one.

Using Process Explorer I searched for this DLL and confirmed that it’s loaded in multiple places, with all programs except the AppV program using the natively installed one.

What I suspect is happening is that there is some form of DLL sharing occurring and Windows is telling the program that “your loading this file?!  I already have it loaded and used by all these other programs.  Use that instead you dummy!”

So can we force the program to use the natively installed DLL’s?

This program automatically installs some Visual C++ runtime libraries and these are captured by AppV automatically.  There is no way to remove them as they are not a separate installer or anything we can just hack out during an install.

However, we can just manually delete them.  If they don’t exist in the package AppV should automatically look for those files in the native file system.

I then went into the AppV Sequencer and ‘Edit’ on the package, selected ‘Package Files’ and deleted the ‘winsxs’ folder:

 

Did it work?

This is what procmon showed me for the new package without these folders:

The msvcm80.dll is now using the natively installed version and path!  And I did not get the error message any more and the operation worked successfully!  Another success story.

Read More

Lets Make PVS Target Device Booting Great Again (Part 2)

2017-01-05
/ /
in Blog
/

Continuing on from Part 1, we are looking to optimize the PVS boot process to be as fast as it possibly can be.  In Part 1 we implemented Jumbo Frames across both the PVS target device and the PVS server and discovered that Jumbo Frames only applies to the portion where BNIStack kicks in.

In this part we are going to examine the option “I/O burst size (KB)”  This policy is explained in the help file:

I/O burst size — The number of bytes that will be transmitted in a single read/write transaction before an ACK is sent from the server or device. The larger the IO burst, the faster the throughput to an individual device, but the more stress placed on the server and network infrastructure. Also, larger IO Bursts increase the likelihood of lost packets and costly retries. Smaller IO bursts reduce single client network throughput, but also reduce server load. Smaller IO bursts also reduce the likelihood of retries. IO Burst Size / MTU size must be <= 32, i.e. only 32 packets can be in a single IO burst before a ACK is needed.

What are these ACK’s and can we see them?  We can.  They are UDP packets sent back from the target device to the PVS server.  If you open Procmon on the PVS server and startup a target device an ACK looks like so:

These highlighted 48byte UDP Receive packets? They are the ACKS

And if we enable the disk view with the network view:

 

With each 32KB read of the hard disk we send out 24 packets, 23 at 1464 bytes and 1 at 440 bytes.  Add them all together and we get 34,112 Bytes of data.  This implies an overall overhead of 1344 bytes per sequence of reads or 56 bytes per packet.  I confirmed it’s a per-packet overhead by looking at a different read event at a different size:

If we look at the first read event (8,192) we can see there is 6 packets, 5 at 1464 and one at 1208, totaling 8528 bytes of traffic.  8528 – 8192 = 336 bytes of overhead / 6 packets = 56 bytes.

The same happens with the 16,384 byte read next in the list.  12 packets, 11 at 1464 and one at 952, totaling 17,056.  17056 – 16384 = 672 bytes of overhead / 12 packets = 56 bytes.

So it’s consistent.  For every packet at the standard 1506 MTU you are losing 3.8% to overhead.  But there is secretly more overhead than just that.  For every read there is a 48 byte ACK overhead on top.  Admittedly, it’s not much; but it’s present.

And how does this look with Jumbo Frames?

For a 32KB read we satisfied the request in 4 packets.  3 x 8972 bytes and 1 at 6076 bytes totalling 32,992 bytes of transmitted data.  Subtracting the transmitted data from what is really required 32,992-32,768 = 224 bytes of overhead or…  56 bytes per packet 🙂

This amounts to a measly 0.6% of overhead when using jumbo frames (an immediate 3% gain!).

But what about this 32KB value.  What happens if we adjust it longer (or shorter)?

Well, there is a limitation that handicaps us…  even if we use Jumbo Frames.  It is stated here:

IO Burst Size / MTU size must be <= 32, i.e. only 32 packets can be in a single IO burst before a ACK is needed

Because Jumbo Frames don’t occur until after the BNIStack kicks in, we are limited to working out this math at the 1506 MTU size.

The caveat of this is the size isn’t actually the MTU size of 1506.  The math is based on the data that fits within, which is 1464 bytes.  Doing the math in reverse gives us 1464 x 32 = 45056 bytes.  This equals a clear 44K (45056 /1024) maximum size.  Setting IO/Burst to 44K and the target device still boots.  Counting the packets, there are 32 packets.

So if we up the IO/Burst by 1K to 45K (45*1024 = 46,080 bytes) will it still boot?

It does not boot.  This enforces a hard limit of 44K for I/O Burst until the 1st stage supports a larger MTU size.  I have only explored EFI booting, so I suppose it’s possible another boot method allows for larger MTU?

The reads themselves are split now, hitting the ‘version’ and the ‘base’ with the base being 25,600 + 20,480 for the version (46,080 bytes).  I believe this is normal for versioning though.

So what’s the recommendation here?

Good question.  Citrix defaults to 32K I/O Burst Size.  If we break the operation of the burst size we have 4 portions:

  1. Hard drive read time
  2. Packet send time
  3. Acknowledgement of receipt
  4. Turnaround time from receipt to next packet send

The times that I have for each portion at a 32K size appear to be (in milliseconds):

  1. 0.3
  2. 0.5
  3. 0.2
  4. 0.4

A total time of ~1.4ms per read transaction at 32K.

For 44K I have the following:

  1. 0.1
  2. 0.4
  3. 0.1
  4. 0.4

For a total time of ~1.0ms per read transaction at 44K.

I suspect the 0.4ms difference could be well within a margin of error of my hand based counting.  I took my numbers from a random sampling of 3 transactions, and averaged.  I cannot guarantee they were at the same spot of the boot process.

However, it appears the difference between them is close to negligible.  Question that must be posed is what’s the cost of a ‘retry’ or a missed or faulty UDP packet?  From the evidence I have it should be fairly small, but I haven’t figured out a way to test or detect what the turnaround time of a ‘retry’ is yet.

Citrix has a utility that gives you some information on what kind of gain you might get.  It’s called ‘Stream Console’ and it’s available in the Provisioning Services folder:

 

With 4K I/O burst it does not display any packets sent larger because they are limited to that size

 

8K I/O Burst Size. Notice how many 8K sectors are read over 4K?

 

16K I/O Burst Size

 

What I did to compare the differences in performance between all the I/O Burst Size options is I simply tried each size 3 times and took the results as posted by the StatusTray utility for boot time.  The unfortunate thing about the Status Tray is that it’s time/throughput calculations are rounded to the second.  This means that the Throughput isn’t entirely accurate as a second is a LARGE value when your talking about the difference between 8 to 9 seconds.  If you are just under or over whatever the rounding threshold is it’ll change your results when we start getting to these numbers.  But I’ll present my results anyways:

To me, the higher value of I/O Burst Size the better the performance.  

Again, caveats are that I do not know what the impact of a retry is, but if reading from the disk and resending the packet takes ~1ms then I imagine the ‘cost’ of a retry is very low, even with the larger sizes.  However, if your environment has longer disk reads, high latency, and a poor network with dropped or lost packets then it’s possible, I suppose, that higher I/O burst is not for you.

But I hope most PVS environments are something better designed and you actually don’t have to worry about it.  🙂

Read More

Windows Update – 0x80070308 ERROR_REQUEST_OUT_OF_SEQUENCE

2016-10-31
/ /
in Blog
/

We are getting this error when trying to install KB3172605, which was re-released in September of this year.  This patch was originally installed in August without issue but the re-release fails to install.  The WindowsUpdate.log reports:

Examining the CBS.LOG for more information has revealed the following:

The error starts here:

One of the nice things about Windows Update is it kicks up Windows Error Reporting immediately when it detects an error.  So if you run procmon.exe you can find when the error occurs and work backwards only a little bit to, usually, find why it crashed.

In this case I ran procmon while I tried installing this update, went to 11:25:10 and did a search for “Windows Error Reporting”

windowsupdatebug1

The actual Windows Error Reporting kicked in at the check to see if it is disabled (DisableWerReporting).  The last key it read before it crashed was:

“HKLM\COMPONENTS\DerivedData\Components\amd64_0e471cf709070f76ea5797942bb36096_31bf3856ad364e35_6.1.7601.23455_none_9b9ebc8fa6659c8e”

If I open that key in Regedit here is what it looks like:

windowsupdatebug2

And what another key in that same list looks like:

windowsupdatebug3

 

It appears the key that is in error is missing some information.  In order to fix this I’m going to another system and try to grab they values needed for identity and S256H.  I don’t know how these keys are generated but I’m hoping they are generated by the file it’s referring to which *should* mean that a same or similar level patched system should have the same files and thus the same generated hash’s.

I went to another system and exported the values.  In order to find the proper key, we find it is referenced by the previous key in the procmon trace:
“amd64_microsoft-windows-b..environment-windows_31bf3856ad364e35_6.1.7601.23455_none_c7bdc8a2bca7…”

The key path was present in both systems because they were at the same patch level but the look of the key is different because of GUIDs are generated:

windowsupdatebug10

Working system – Notice the highlight is different

By tracing back in the working system I exported the key that “c!” is referencing.

Working System has S256H, identity keys

Working System has S256H, identity keys

I exported out the key from the working system and had to edit it so the GUID matched the broken key’s values.  I took the ‘working’ registry:

And the broken key:

I added the S256H and identity values to the ‘broken’ key:

And then added the last “c!” line by following these next steps:

  1. copied the line out:
    “c!c4ebacc5355..93c10e6175a_31bf3856ad364e35_6.1.7601.23455_8459b72d1e2f2700″=hex:
  2. Pasted the value from the registry “key” underneath with the “broken” value:
  3. Starting at the ellipse, counted the number of characters from the “55..” to “93′ underneath and created the value:
  4. Lastly, removed the ‘_none” from the string:
  5. I could then add “c!” in front and added it to my ‘broken’ registry file:

    I then tried to install the patch:

    windowsupdatebug9

And it worked!

Read More

Windows Update – Errors 80070057, 800736B3, 8024400E

2016-10-19
/ /
in Blog
/

We started the new patching Microsoft has put forward (cumulative updates) and one of our Citrix vDisks had an issue with it. Windows Update would say that there were no updates available:

windowsupdatebug

But we very obviously have updates to deploy to it.

When I checked the ‘WindowsUpdate.log’ I saw the following:

0x80070057 = E_INVALIDARG

The ‘CBS’ (Component Based Servicing) is reporting an Invalid Argument.  Microsoft keeps a more verbose log of the component based servicing here: C:\Windows\Logs\CBS

This log reported the following:

An error appeared to occur at this point (there were a few):

Failed to get component version: 6.1.7601.22653
Failed to enumerate store versions on component: x86_microsoft-windows-c..ityclient.resources_31bf3856ad364e35_6.1.7601.22843_da-dk_c1126f6226996014
Failed to enumerate related component versions on component: x86_microsoft-windows-c..ityclient.resources_31bf3856ad364e35_6.1.7601.22843_da-dk_c1126f6226996014

 

The standard MS method of troubleshooting Windows Update is to run the ‘CheckSUR’ utility.  This was the result of running that tool:

windowsupdatebug2

No errors detected.  Awesome.  So I have a problem but this tool reports everything is peachy.

So when I looked at Windows Update I saw numerous ‘failed’ updates.

windowsupdatebug3

I took one that was failed and downloaded it (KB3177467) and attempted to manually install it.

This time I got a different error:

0x800736B3 – ERROR_SXS_ASSEMBLY_NOT_FOUND

Looking at the CBS.LOG showed me the following:

Ok, so now we can see the error but it still doesn’t give us much information.  If I run ProcMon I can find *when* the error occurs somewhat easily because Windows Error Reporting kicks in as soon as the error occurs:

windowsupdatebug4

My apologies for such an ugly screenshot.  The ‘Dark Blue’ highlight is when Windows Error Reporting kicked in.  So the error must have occurred immediately preceding it.  The only line that had a ‘NAME NOT FOUND’ without being a subkey search is the line that ends in v!6.1.7601.18766.  If I browse to that location in the registry, here’s what I find:

windowsupdatebug5

 

So we are definitely missing that key.  I have a bit of an advantage with the patches here as I have a duplicate of this server in another vDisk that was made around a year ago.  Both are supposed to be at the same patch level, but it allows me to look through it’s COMPONENTS registry hive and see if it has that key…

And I see a vastly different set of keys:

windowsupdatebug6

So I import that key and try running the update again…

windowsupdatebug7

 

Manually, it successfully updated.  So now I tried running Windows Update again:

windowsupdatebug8

Code 8024400E.  Which means…  I just need to rerun ‘Try again’ about 6 times.  Once I do:

windowsupdatebug9

Ok, we have updates.  As a test I’m going to do just one:

windowsupdatebug10

 

Success!

windowsupdatebug11

So I’ll try the rest:

windowsupdatebug12

 

Success!

windowsupdatebug13

 

It appears we can install patches again.  I’m concerned the COMPONENTS hives were so different but without a solid understanding of how that hive comes to be (I wish you could rebuild it) I think I may be stuck with assuming that a failed update or maybe a corrupt registry key is at fault for that missing key breaking updates.  I guess we’ll see what happens next month to see if we can patch Windows :/

Read More

AppV5 – Applications being published to “C:\App-V Packages” instead of %PACKAGEINSTALLATIONROOT%

2016-09-21
/ /
in Blog
/

The last little while we’ve had an issue with some applications seemingly being published to “C:\App-V Packages” instead of our defined path “D:\AppVData\PackageInstallationRoot”.

AppV-Packages

Notice the timestamps? Packages published during the same ‘publishing refresh’

 

Video of the issue in action that I was able to setup a repro:

So what’s going on here that would cause this to happen?

I turned to the event viewer to find the time when this package “8FE4C99E…” was published and just looked to see if there was anything surrounding it.

Highlighted is the package publish event

This is the event showing the package being published to “C:\App-V Packages”.  There is an odd thing different about this publish event compared to the rest (that you can see above).  Between ‘Configure Package’ and when the ‘Streaming’ starts there is a ‘Publishing Refresh’ event.

Publishing refresh

Why is there a Publishing Refresh event?  It turns out, it can be triggered by a group policy refresh.

GP Refresh

Notice the time stamps?

So, is there something that occurs during Group Policy refresh that could cause this?

To test this I used procmon to monitor for PackageInstallationRoot registry key and ran a Group Policy Refresh:

screen-shot-2016-09-21-at-8-27-01-am

Procmon_PackageInstallationRoot

The key is deleted then recreated and inbetween the AppV service is trying to read it.

So what is happening here?

At our organization we prefer to set Group Policies using Group Policies Preferences – Registry because of the power and flexibility of Item Level Targetting.  We prefer to only apply registry keys/policies to specific systems in certain groups rather than having a complicated OU structure.  Since I know we have a policy that configures our AppV5 values I went and looked into how this value was being configured:

GroupPolicyManagement

The ‘Action’ is ‘Replace’

screen-shot-2016-09-21-at-8-44-18-am

We have this value set to ‘Replace‘.  What does replace do?

Replace Delete and recreate a registry value or key for computers or users. If the target is a registry value, the net result of the Replace action is to overwrite all existing settings associated with the registry value. If the target is a registry key, the net result is to delete all values and subkeys in the key, leaving only a default value name with no data. If the registry value or key does not exist, then the Replace action creates a new registry value or key.

Well, process monitor is showing EXACTLY that scenario.  Replace is deleting the key and recreating it.  In between that time ‘AppVClient.exe’ is trying to read that value.  If PackageInstallationRoot doesn’t exist, then AppV defaults to ‘C:\App-V Packages” as the PackageInstallationRoot.

screen-shot-2016-09-21-at-10-01-23-am

No “PackageInstallationRoot” key -> “C:\App-V Packages” folder is where packages go.

 

It appears we have a race condition between group policy being applied and when our AppVClient is refreshing.  It is less than 600ms but that’s enough time for a package or two to start their refresh and get caught in ‘default folder’ purgatory.

How can we fix this?

The easiest solution and the one we are going to implement:

We’re going to change the action to “Update”.  When I initially tried to change the action was greyed out.  When “Remove this item when it is no longer applied” is checked, it forces the action to “Replace”.
screen-shot-2016-09-21-at-8-44-27-am

I had to ‘uncheck’ that value

screen-shot-2016-09-21-at-8-44-34-am

And then I could select ‘Update’.

screen-shot-2016-09-21-at-8-44-43-am

After updating the GPO and refreshing policies on the affected system, I ran procmon to verify that it does not delete the value anymore:

GPP_Update

It does not delete the value, it now ‘Sets’ the value to the same string we had before.  I don’t know if the individual ‘Set’ action will cause an issue; I suspect not since the value will always exist and is technically the same value throughout the entire set of actions that this issue is now ‘resolved’ for us.

Read More

Citrix XenApp – Graphical Artifacts

2016-07-22
/ /
in Blog
/

In our Citrix XenApp 6.5 environment we started having a couple applications encounter an issue where they would experience some serious graphical artifacts.  What was supposed to look like this:

1

Would look like this:

2

 

Here’s a short video demonstrating this issue:

Or sometimes it would show the windows *behind* the artifacted image.  That is, instead of the ‘White’ you see in my image, the application behind it shows through.

When investigating this we found there was a couple symptoms that we were going to experience these artifacts.

  1. The window would become ‘frosted’ or ‘ghosted’ (as seen in Spy++ or AutoIt Window Info)
    4
  2. The application would switch to ‘Not Responding’
    3
  3. If you completed the task ‘Edit’ quickly there would be no artifacting (time was important)
  4. When ‘timing’ the switch from ‘normal’ to frosted or ghosted window it would be around 5-7 seconds.

So what’s going on here?

For this particular instance, the application is launching MSPaint with some modified properties.  It sets Paint to ‘Always On Top’, which in itself isn’t an issue, but then it purposefully locks the UI so you must complete the drawing and close paint before continuing.  This is how the vendor designed this application to operate with this workflow.

And what’s Windows doing?  It turns out, Windows is trying to alert you that your program is non-responsive!  Windows has a built in feature to ‘Frost/Ghost’ the window of a non-responsive UI to prevent you from entering input that won’t be received.  The ghosting effect is time sensitive!  So that explains why if we opened and closed our document quickly their would be no artifacting but if we manipulated it for some time the artifacts would appear.  The time limit for monitoring unresponsiveness is 5 seconds.  DWM.exe is the process responsible for creating the ‘Frost’ window and when responsive returns, it appears it does a poor job telling the application to repaint all affected Windows.

Microsoft recommends a couple ‘fixes’ which is really a programmatic way to ‘disable’ the ghosting feature.  The two methods Microsoft suggests is to create a NoGhost application compatibility fix or have the programmer use ‘DisableProcessWindowsGhosting’.  But there is a 3rd method.

The 5 second time limit is programmable.  If we extend the timeout we don’t need to configure ‘NoGhost’ compatibility fixes for each app or go back to the vendor.  The timer is global and affects every application and window.  Unfortunately, I know of no way to permanently disable it, but we can set a high enough value to prevent it from appearing.

So what do we have to do to ‘resolve’ this?

My preferred choice was to use Group Policy Preferences (Registry) and set a new value for HKCU\Control Panel\Desktop /v HungAppTimeout /t REG_SZ /d 120000

This sets the timeout to 2 minutes as opposed to 5 seconds.  Now when our program is used we get this result:

No More Artifacts.

When I was investigating this I found I could get the artifacting to occur in both ICA and RDP but not when on the console.  The frustrating thing about this issue is that it was not consistent.  Because of the 5 second default time limit, the program(s) we had that would ‘artifact’ would sometimes complete their UI locking job faster than 5 seconds, but sometimes not.  This lead to reports of artifacting occurring more often ‘during the peak work hours’ when the application/server/user load was the most.  This makes sense as the higher load undoubtedly lead to everything being slower, the database, server, etc. leading to the application waiting longer and thus exceeding the timeout.  I did find through the course of troubleshooting this issue that it seemed to ‘go away’ when I was trying to replicate after hours, which is frustrating to only have a slice of time to try and resolve this during peak hours.

Fortunately, after implementing the HungAppTimeout registry key the artifacts for several application ‘went away’.

Lastly, contrary to this article you do NOT need to restart for this value to take effect.  WinLogon.exe reads the HungAppTimeout value and then configures DWM accordingly when your profile loads.  So for this value to take effect you only need to log on with this value already residing in your user’s registry hive.

5

Read More

Microsoft Office – Your mailbox is currently being optimized as part of upgrading to Outlook 2010

2016-06-15
/ /
in Blog
/

I was using our Office 2010 through Citrix and started noticing I was getting this message:

1

“Your mailbox is currently being optimized as part of upgrading to Outlook 2010.  This one time process may take over 15 minutes and performance may be affected while optimization is in progress.”

“Upgrade Outlook Connector”

“You must upgrade to the latest version of Outlook Hotmail Connector to continue using this e-mail account.”

In addition, all of the options under ‘Account Settings’ do nothing.  This is in addition to my Home/Inbox being empty and my calendar blank.  Attempting to create a calendar event results in:
2

I then tried to open the ‘Mail’ control panel and found it was missing.  I manually opened it by launching it from:
“C:\Program Files (x86)\Microsoft Office\Office14\MLCFG32.CPL”

3

From here, clicking any of the buttons resulted in nothing happening.  Email Accounts… Data Files… did nothing.  Clicking ‘Show Profiles’ did work, though.  So what the heck is going on?  I opened up Process Monitor to try and find out.  I opened up the ‘Mail’ control panel via the command line, since this is a ‘Rundll32.exe’ I set the procmon filter to ‘Command Line’ ‘contains’ ‘MLCFG’ and clicked one of the non-functioning buttons.  My result:

4 5

PATH NOT FOUND.  Why isn’t the path found?  I opened a command prompt and followed the path doing a dir /x to show shortnames:

6

Well, there is the issue.  It’s showing as ‘MICROS~4’ when it’s searching for ‘MICROS~2’.  Doing a repair on office will cause re-registration to occur and this does resolve the issue, but I wanted to change my shortname instead of doing a repair.  Since these are PVS servers I created a new version, mounted the vDisk and changed the shortnames via fsutil:

7

In the screenshot, you can clearly see ‘Microsoft Office’ is now ‘MICROS~2’.  I unmounted the vDisk, set a target device and booted it up.  I opened the command prompt and…

8

What the heck?  For some reason mounting my vDisk offline and I can’t change the shortname.  I get access denied trying to change the shortname when the server is online so I was hoping offline would work.  Unfortunately, it does not appear to be so.

So what is the solution?  I guess repair office to force registration and it will point to the new paths because it will re-register all components. 🙁

Read More

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

2016-03-30
/ /
in Blog
/

We experienced this error on a package on one of our Citrix servers in the AppVClientAdmin 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:AppVDataPackageInstallationRoot’ 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.

Read More
Page 1 of 212