process monitor – The knack

SysInternals has for a long time provided us with the valuable tool Process Monitor, which everyday presents new use cases.

While troubleshooting an installation that seemed to be running a specific CustomAction once a self-heal was initiated and in error set a few registry keys to an odd-value.

The registry-keys could not be located within the Registry-table and there was a ridiculus amount of CustomActions.

Registry key that was wrongfully set looked like this (when it was not correct);

Windows Registry Editor Version 5.00

[HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Taylor\Workbench\Installed Products]
"Proficy Machine Edition (TM)"="v5.50 Build 3655"
"View"="v5.50 Build 3655"
"Logic Developer - PLC "="v5.50 Build 3655"

Unfortunately, none of the CustomActions had very descriptive names as to which one would touch this key and there were a lot of them. A lot. Infact they started at 5750 and stopped at 6720 in the InstallExecuteSequence table.

How do you identify a CustomAction which sets a registry key ? Using timestamps in Process Monitor of course!

A fare warning before you start the steps; A lot of memory will be required due to the capture of Process Monitor

1. Fire up Process Monitor and let it monitor. No filter needs to be applied immediately.

2. Initiate the installation using verbose-logging. A sample command-line could look like this;

msiexec /i install.msi /qb TRANSFORMS=install.mst /l*v install.log

3. Once the installation is completed, stop the monitoring within Process Monitor.

4. Search for the registry key (or file if that is your case). As we are looking for when the registry key is updated, certain operations aren’t applicable. For example, RegOpenKey isn’t something that corresponds to the operation we are looking for. Therefore you can exclude this and avoid a lot of traversing through unnecessary finds.

As you can see, searching can take a bit of time;

The 3 million rows are quite heavy;

5. Once the applicable registry key is found and the RegSetValue is located the timestamp is located.

(click the image to see all of it)

6. Review the log-file generated during the installation and find the corresponding timestamp (12:04:11,972791 is the time in the screenshot).

The accuracy of Process Monitor has given us a very precise timestamp (972791 are the last digits) and we can easily see that during the time-slot of 12:04:11 there are 7 different CustomActions occuring, however only two occur within the reach of 12:04:11:97~.

As the FindfxViewVersion1 is actually executed after the timestamp, we can safely assume that it is the FindFrameWorXVersion that is setting the registry key in question.

7. Looking at the InstallExecuteSequence table the CustomAction is set to run at sequence # 6260, however no conditions are set for it.

The CustomAction will in error execute during any repair (and self-heal) and reset the registry keys due to the lack of conditions.

The following modification was done using InstEd to add a condition;

You could play around with different conditions that might suite your case and Symantec has provided a great overview of some commonly used scenarios!

The number one tool in troubleshooting applications has been and still is Process Monitor – providing great insight into everything that happens in the background of an application. However, when combining App-V and Process Monitor – there are some challenges to see the entire background activity – especially when it comes to registry activity. For quite some time there has been things that haven’t been properly shown when troubleshooting using Process Monitor and attempting to view the activity within the registry for a virtual application.

Process Monitor does present us with quite a few different ways of starting – lets explore the possibilites;

Obviously – we could just start it and see what it spits out. Looking through the possible start-up switches presents quite a few different ways of starting procmon. For our specific scenario – the /hookregistry looks mighty tempting, but it states that it only works on x86 Vista. The announcement for the feature were on the Softgrid-blog and was a first turning point after Microsoft acquired Softricity.

This is only whats documented and if looking around the internet – we can find one additional method of troubleshooting App-V. /externalcapture is a more commonly known startup switch, but its not documented (as you can see above) and apart from some presentations by Microsoft and unofficial blog-entries – there isn’t a whole lot formally written down about this gem.

Key question – whats the best method of using Process Monitor to troubleshoot App-V applications?

Well – lets find out;
A specific application is selected – mainly because its small, it does access the virtual registry when it starts and hopefully we can understand the difference between these behaviors. A filter is applied to only include the process in question (opwin.exe) and all the tests are preformed on a Windows 7 SP1 x86 machine.

Test 1
procmon.exe

Result is 265 items in total

Test 2
procmon.exe /hookregistry

Result is 265 items in total

Test 3
procmon.exe /externalcapture

Result is 322 items in total

So – we can clearly see that /externalcapture provides more registry output than the other possible options. What is the difference?

Procmon.exe /externalcapture shows us quite a few entries that are not at all visible from all the other options we used – especially the below are never shown at all when using the startup switches from the first two test cases.