Comparing a Working and Non-Working MSI Installer Log

*This post originally appeared on the AppSense blog prior to the rebrand in January 2017, when AppSense, LANDESK, Shavlik, Wavelink, and HEAT Software merged under the new name Ivanti.

I had an incident recently where using the log parsing technique of removing unique fields such as date/time from a MSIExec log and then using a compare application helped find the issue.  I tend to find this a useful technique when reading through large log files from other vendors, where actions mostly run sequentially.  It tends to be more difficult to use if multiple actions are running in parallel and it’s not possible to isolate individual actions or threads within a log file.

If you’re already familiar with Regular Expressions then this blog probably doesn’t contain anything of addition use but if you’re an AppSense Administrator and haven’t tried comparing working and non-working logs using RegEx, this might provide a pointer for further investigation.

A Bit of Back Story

A customer had found that when the Add/Remove Programs Component was elevated using Application Manager, they were not able to Add/Remove components from Microsoft Office 2010 (http://www.appsense.com/kb/160204070232733 - Login Required).  A few other applications tested appeared to be unaffected.  The interesting aspect of the symptoms was MS Office was reporting back that the configuration had completed successfully but there were no obvious changes to the MS Office install.  This suggested that whatever Application Manager was doing, was allowing the Office Installer or child process to return a success code.  As a result, chances are the logs would not show an error but a change in behaviour.

Microsoft Office Logs

The Microsoft Office Setup saves logs to %temp% when using Add/Remove Programs to change installed components.  A review of the setup log confirmed that setup.exe was launching multiple MSIExec and these were returning a success result back to setup.exe.  Of the multiple MSIExec log entries within the setup.exe log, the following is of most interest and demonstrates the success result:

01/29/2016 13:57:36 Configuring chained package: OfficeMUI.en-us

Catalyst Package Configuration...

Package: OfficeMUI.en-us

File: C:\Program Files (x86)\Common Files\Microsoft Shared\OFFICE14\Office Setup Controller\Office.en-us\OfficeMUI.MSI

Command Line:  ADDLOCAL=MetricConverterIntl_1033, AlwaysInstalledIntl_1033, MSTagPluginStockFilesIntl_1033, WebDiscussFilesIntl_1033, GraphicsFiltersPNGFilesIntl_1033, EquationEditorFilesIntl_1033, GraphicsFiltersEPSFilesIntl_1033 ,MSTagPluginNamesFilesIntl_1033, TCWP5FilesIntl_1033, CAGOffice10Intl_1033, OISFilesIntl_1033, WxpFilesIntl_1033, XDOCSEditorFilesIntl_1033, USERNAME="Timothy Banner" ACCEPTEDEULA="1" WATSONSQM="AUTOREPORT" BRANDING_XML="C:\Users\TBANNE~1\AppData\Local\Temp\Setup00000d00\BRANDING.XML" COMPANYNAME="Appsense" SETUPEXEINSTALLUICULTURE="en-US" INSTALLLOCATION="C:\Program Files (x86)\Microsoft Office" REBOOT=ReallySuppress LAUNCHEDBYSETUPEXE=1 MSIRESTARTMANAGERCONTROL="Disable" SETUPEXEINSTALLUILANGUAGE=1033 SETUPINTLDLLDIRECTORY="C:\Users\TBANNE~1\AppData\Local\Temp\Setup00000d00\"

Successfully configured package: OfficeMUI.en-us product code:{90140000-006E-0409-0000-0000000FF1CE}

I didn’t find a logging option (at least one that I got working) to enable MSI Logging for these child processes of the Office setup.exe.  Fortunately the Windows Installer service does support generic logging for all msiexec installs (https://support.microsoft.com/en-us/kb/2545723).  Once enabled I was able to gather a set of working and non-working MS Office MSI Logs.

Setup.exe launches a number of child msiexec processes and a few minutes using Microsoft/SysInternals Process Explorer (http://www.microsoft.com/sysinternals) confirmed which MSIExec process was responsible for writing to disk the component in question.  As expected this was by far the largest MSI log at 10MB for the working and 7MB for the non-working.

Microsoft does provide the Wilogutl.exe (https://msdn.microsoft.com/en-us/library/windows/desktop/aa372811%28v=vs.85%29.aspx?f=255&MSPPError=-2147217396) for reviewing MSI logs using a GUI reading or generating a report.

Both logs contained the same number of error messages and after iterating through them all, they were all benign.  This was expected, as the MSI is returning a success exit code.  This meant going through the MSI logs and determining at which point they deviate and hoping that would provide a clue to progress further.

Running a Compare against MSILogs

I’ve got a couple of favourite tools for performing compares of text files, Notepad++ with the Compare plugin and WinMerge.  Both are free tools and both support Find/Replace using Regular Expressions.

The problem with performing an initial compare is every line is different due to date/time fields.  Equally there are going to be other unique fields such as GUIDs, thread IDs etc. Standard Find/Replace isn’t ideal for replacing these entries but RegEx can help.

If you’re not familiar with RegEx it’s a powerful language for parsing text.  There is plenty of online resources to provide an introduction and numerous webpages and tools for generating and translating regular expressions.  Microsoft have a Quick Reference (https://msdn.microsoft.com/en-us/library/az24scfc%28v=vs.110%29.aspx?f=255&MSPPError=-2147217396 ) but there are plenty of other quick reference and detailed tutorials.

As for GUIs, I quite like the Expresso GUI (https://ultrapico.com/Expresso.htm), it’s easy to build regular expressions (at least at my level) and more importantly to translate well written RegEx from forums and reference websites.

First thing to remember is that we’re not looking to produce the perfect RegEx…  Actually we’re not trying to even produce acceptable RegEx…  This is going to be just a quick dirty hack to clear up a text file and it’s not likely that the RegEx will be used again.  It’s also worth pointing out that there is a wealth of well written RegEx on the Internet for pretty much most common use cases.

Looking at the screenshot below we can see a few potential areas that maybe unique in the logs.  There is the (Process:Thread) entry that will be unique for each log, a Time entry and also a numerical thread entry.  We can also see that GUIDs will be in the logs but these may or may not be unique.

Let’s strip the “MSI (c) (process:thread) [time]: “ entries.  I appreciate that knowing the thread and time is really useful.  The thread is usually useful to follow the actions performed by an individual thread when several threads are writing to the log file at the same time and performing unrelated actions.  Removing time doesn’t help for determining timings issues and long pauses.  But we’re just trying to find when the logs start to deviate, once we get to this point we reopen the original log and have an initial entry point for review.  Typically with particular attention to the thread that is affected.

The following RegEx will do the job.  Probably worth reiterating that this isn’t a RegEx tutorial, just an introduction on how it could be useful in this context:

• ^MSI.*:\d\d\d\]:\s

Where:

• ^ = Start of line
• MSI = find literal MSI
• . = Any character
• * = Repeat the last character multiple times e.g. find “.” any character multiple times
• \d = a numerical value from 0-9
• \] = ] is a special character in RegEx for matching groups
• : = a literal colon
• \s = Single space character, I could also have used a “ “ but it wouldn’t have been easy to spot.

To sum it up, find everything from lines starting with “MSI up to three numbers]: “.  For quick and dirty this would probably suffice, the snag is the “.*” tends to be quite greedy.  So if you had:

MSI (s) (A4:4C) [19:51:58:172]: Grabbed execution mutex additional time [19:51:58:172]: etc etc etc.

It would match everything between:

MSI (s) (A4:4C) [19:51:58:172]: Grabbed execution mutex additional time [19:51:58:172]:

So it might be too quick and dirty for this job, let try and hone it down a little for this example:

• ^MSI\s\(\w\)\s\(\w\w.\w\w\)\s\[\d\d:\d\d:\d\d:\d\d\d\]:\s

Again for these logs the \s isn’t required but it helps for the purpose of this blog that we’re looking for a white space type characters.  You could just enter a literal space and get the same results:

• ^MSI \(\w\) \(\w\w.\w\w\) \[\d\d:\d\d:\d\d:\d\d\d\]:

The \w entry finds word character e.g. a-z, 0-9 and a number of other characters (a quick Internet search will demonstrate the full class range).  Again as with [] () are used within RegEx so to get a literal we escape with a “\”.

So that’s a lot of “\”, there are nicer ways to deal with searching for multiple concurrent entries but for this purpose it’s pretty quick just to type simple entries as they appear in the log file.  Remember it’s not about producing a nice bit of reusable (or even reliable RegEx) but to quickly try and clear down a log.  So this line reads as follows:

• ^MSI\s\(\w\)\s\(\w\w.\w\w\)\s\[\d\d:\d\d:\d\d:\d\d\d\]:\s

“StartOfLineMSI (WordChar) (WordCharWordCharAnyCharWordCharWordChar) [DigitDigit:DigitDigit:DigitDigit:DigitDigitDigit]: “

In this case I’ve simply removed the entry and not replaced with any text.  It’s the start of the line and reduces the amount of scrolling left and right.  When we do another compare using WinMerge we can see that the first 4,000 lines or so match, assuming of course that our RegEx didn’t remove something useful.

In this particular incident, this was enough to see where the logs deviated and the reason why but let’s remove these time and date entries.  Again in this case chances are the date actually doesn’t need removing, as I generated both sets of logs on the same.  Again, let’s hack away with this with a RegEx that wouldn’t be suitable for use in any other context:

The date is in the format: dd/mm/yyyy.  So we could try and get clever and consider the multiple formats that dates may appear in e.g. date in the format 3/2/2016, 3/02/2016 or 03/02/16 etc.  But we can see the format being used and I’m not too worried about losing other data in a similar format for the sakes of this quick log parsing.  So let’s keep it simple with:

\d\d/\d\d/\d\d\d\d

Try an Internet search to see just how sophisticated a date RegEx can be.

Same with the time:

\d\d:\d\d:\d\d

For entries like these, replace the found entry with a word e.g. <DATE>, <TIME>, <GUID> etc.  That way it’s easy to see the entries changed and when quickly reviewing an entry in WinMerge if the change could be relevant to what is being investigated.

After letting WinMerge perform another compare we can start seeing clear areas of differences in the logs.  Let’s remove this one last example where there are unique MSIHANDLE and threads being referenced.  A quick scroll through the WinMerge output suggests that both of these are 4 digits long.

Example for MSIHANDLE

• Find: MSIHANDLE\s\(\d{4}\)
• Replace: MSIHANDLE (<HANDLEID>)

But let’s assume that threads can be 3 or 4 digits long:

• Find: thread\s\d{3,4}
• Replace: thread <THREADID>

Where {} can be used to define repetition e.g.

• \d{4} = search for a repeat digit exactly 4 times
• \d{3,4} = search for a repeat digit between 3 to 4 time

Now let’s have a look at the compare again:

After 5 minutes and some very ropey RegEx, WinMerge is starting to show some clear areas of differentiation in a 10MB log file.  Repeat the process by investigating areas of differences to determine if they’re relevant to the issue, caused by log entries out of sequence or unique identifiers.  Hopefully from here we can find an entry point and thread to start investigating in the original log file.

So where was the issue in this set of MSI Logs?

On line 4249 (so a fair chunk in) the Command Line parameter differs between the working and non-working log.  In the working log it matches the Setup.exe log entry in the non-working log it’s quite different.  It transpires that Application Manager hooks the MsiConfigureProductsEx API https://learn.microsoft.com/en-us/windows/win32/api/msi/nf-msi-msiconfigureproductexa.  This API has the parameter szCommandLine which was being used by MS Office to define which components to Add/Remove.  Application Manager wasn’t passing szCommandLine through to the child MSIExec process correctly (fixed in AM 8.9 SP3) resulting in the MSIExec essentially being told not to reconfigure the product, hence why it returned a success code.

Parallel Actions

In the example above, even though msiexec is multi-threaded, huge chunks of the log run in sequence and the offending log line was early enough to not have to worry about non-sequential threads or actions.  If you’ve ever tried to read through an Application Manager or Environment Manager log, you’ll realise that they’re multithreaded with many threads writing to the log at the same time.  In this case, this log searching technique only really works if you can identify a thread of interest.  If I’m not familiar with a log file format I tend to hunt around for these using simple searches e.g. for a process start of Outlook.exe you could try:

• Start.*Outlook
• Process.*Outlook
• Create.*Outlook
• App.*Outlook
• Outlook.*Start
• Outlook.*Process
• Outlook.*Create
• Outlook.*App

Or maybe wrap some of these up with an OR statement e.g.

• (Start|Process|Create|App).*Outlook
• Outlook.*(Start|Process|Create|App)

The reason for using RegEx here is I don’t know what log entries will exist between the two search terms.  Just searching for Outlook would return a significant number of entries as would just searching for Process.

This would be frustrating if you had to do this with a standard text editor and search line by line using “Find Next”.  Notepad++ has the feature to “Find all in current document”.  This allows you to quickly view all entries for your search in a new Window and then quickly jump to that entry in the original file.

Once a thread has been identified, again using another “Find All in Current Document” it would be possible to copy and paste that thread out into a new Notepad++ window.  Repeat with a working log, run a few ropey RegEx to clear down unique identifiers and you should have a series of predominantly sequential actions that you can run a compare against.  In AppSense logs threads tend to be identified as T<ThreadID>, within the MSIExec log it tends to be identified at the start of the line “MSI (WordChar) (<ProcessID>:<ThreadID>)”.  The following image is an example output of the thread (A4:64), which contains over 32,000 lines but this can be copied to a new Window and then compared against the equivalent non-working thread if required.

I hope that this blog has been informative for you, please look out for my future blogs.