MSI Understanding the Windows Installer Logs
When people are beginning to use Windows Installer the first look at the logs is often so daunting they tend to never look at them again. I find that the most common reason people avoid the logs is they don’t understand the sequencing. Funnily enough the sequences and the logs tend to correspond with each other (I’m not sure why that is)
Anyway if you take Windows Installer and break it down you would know that the Installer basically consists of a service and a database that processes table’s then sequences and actions. The installer service records everything that happens in sequential logic. The end result is a transactional record of the actions that are run during the installation. The beauty of this is as its transactional its quite simple to apply the reverse logic to handle the uninstall.
Now the trusty old log files record this process in its entirety, basically what I am getting at here is if you take the time to actually read the logs you would also understand the sequencing logic as well because they are one in the same. Alternatively if you work out the sequences you also workout the logs.
So first things first with the logs. How do we enable Windows Installer logging ?
Before we enable logging there is a number of available logging options which you need to know, there are:
|Logging Option||Option Description|
|o||Out of disk space messages|
|c||Initial UI Parameters|
|e||All error messages|
|w||Non fatal warnings|
|a||start up of actions|
|r||action specific records|
|m||Out of memory or fatal exit information|
|+||Append to existing file|
|!||Flush each line to the log|
|x||Extra logging (Version 3.0 up, Windows 2003 + OS’s)|
Note: Each letter corresponds to a different setting. Adding a collection of all letters increases logging capabilities.
Logging via Registry
Note: A common acronym of VOICEWARMUP is used as its a word that contains all available settings (prior to V3.0)
Debugging via Registry
By enabling the debug key you can monitor the installation using debugview
Install script logging
Windows Installer 4.0 +
So then we got Windows Installer 4.0 from which came two new Windows Installer properties.
MSILogging property hosts the same values listed in the above table.
MSILogFileLocation property has the path to where the logs should be created.
Command Line Logging
So last but not least command line logging, probably the one you will most often use.
msiexec.exe /i <path to msi> /l*v <path to logfile>
msiexec.exe /i <path to msi> /l*vx <path to logfile> (version 3.0 on Windows 2003 + OS’s)
Reading the logs
Ok so now you have the logs how do we interpret the garbage that it generates. Well for those of you who always like to take the easy road. Get your hands on this little utility WILOGUTL.EXE it makes pretty it all a little more legible and takes the guess work out of things.
However for all of you hard core propeller heads here’s how to really understand the seemingly difficult mess that arrive after setting some of the above options to log.
As you are aware the Installer Service on WindowsNT based platforms offers a client and server based process. The first section depicted in the following log excerpt in blue identifies the process is running client or server side.
MSI (s) (DC:D8) [22:18:04:544]: MainEngineThread is returning 1603
MSI (c) (34:30) [22:18:05:544]: Back from server. Return value: 1603
MSI (S) is server side
MSI (C) is client side
MSI (N) is a nested action
The next items depicted above in the red text is the ProcessID:ThreadID that generated the entry. Only the last 2 (hexadecimal) digits of the process and thread IDs are given. If the process ID was 2DC and thread ID 2D8 the Hex item show in the log would be (DC:D8).
The green section following is the date time stamp the action occurred.
The ProductState property can be any one of these values
|-1||The product is neither advertised nor installed.|
|1||The product is advertised but not installed|
|2||The product is installed for a different user|
|5||The product is installed for the current user|
Feature Component State
So every feature and component is checked for state prior to it being marked as something that needs to be installed. So selecting different features “usually” changes the feature state and subsequently all the components within that feature (of course there are exceptions to every rule, the condition table and feature / component conditions all have effect here also.).
The first item here, show the feature name as Complete and it is currently Absent. So the requested action is to install it Local. So the components follow the same pattern. This one is a little tricky so more detail here
|already installed to run local
already installed to run from source
already installed as advertised
|requests to install the item to run local
requests to install the item to run from source
requests to advertise the item
requests to reinstall the item
should not be installed
|actually performs install to run local
actually performs install to run from source
actually reinstalls the item
actually removes the item
MSI (s) (94:28) [20:46:12:390]: Feature: Complete; Absent: Local; Request: Local; Action: Local
MSI (s) (94:28) [20:46:12:390]: Component: Registry; Installed: Absent; Request: Local; Action: Local
MSI (s) (94:28) [20:46:12:390]: Component: VersionRegistry; Installed: Local; Request: Local; Action: Local
MSI (s) (94:28) [20:46:12:390]: Component: slupExecutable; Installed: Absent; Request: Local; Action: Local
MSI (s) (94:28) [20:46:12:390]: Component: CoreLibrary; Installed: Absent; Request: Local; Action: Local
MSI (s) (94:28) [20:46:12:390]: Component: CtrlLibrary; Installed: Absent; Request: Local; Action: Local
Reading Actions and return codes
Action start 1:18:02: INSTALL. MSI (c) (A1:6A): UI Sequence table 'InstallUISequence' is present and populated. MSI (c) (A1:6A): Running UISequence MSI (c) (A1:6A): Skipping action: ResumeInstall (condition is false) MSI (c) (A1:6A): Doing action: CheckOSandSPAction Action start 1:18:02: CheckOSandSPAction. MSI (c) (A1:6A): Creating MSIHANDLE (1) of type 790542 for thread 110 Action ended 1:18:02: CheckOSandSPAction. Return value 1.
The valid return codes are:
Action not invoked; most likely does not exist.
Completed actions successfully.
User terminated prematurely.
Unrecoverable error occurred.
Sequence suspended, to be resumed later.
Shell32 API calls
Where you see one of these there is a good chance a directory is being resolved for the current target platform.
MSI (s) (94:28) [20:46:11:843]: SHELL32::SHGetFolderPath returned: C:\Documents and Settings\All Users\Templates
Old hands tips for log reading
1) Start at the bottom and work up
2) If your install fails with dialogs open. Leave dialogs on screen and goto log whilst error message is still visible
3) Use WiLogUtl.exe
4) Don’t forget the newest extended logging options /l*vx (most of you are still using /l*v)
5) Keep the sequences in mind when reading a logfile (strangely enough they coincide nicely)
6) Enable GPO logging or policy registry option if you need to log repairs
7) Now you have this information take a 30 minutes out of your day and read an entire log you’ll be surprised what you learn.
Now all that being said, I’m not getting a lot of feedback about these blogs so its hard to gauge if anyone is really reading or even interested in this stuff or not.