Reading Windows Installer Logs

As we all know Windows Installer is a complicated and a elegant technology. Its beastly complexities are beautifully abstracted by the authoring packages like InstallShield X, DevStudio and Developer. But we live in a less than perfect world and Murphy’s Law still holds good for the Windows Installer world too. There might be several reasons why an Installation might fail. Some errors might be meaningful while others might just spit out a cryptic error message with an error number during installation. The only way to make sense of these would be to look at the log files generated during installation. You can generate a log file for the installation using the following command line.

msiexec /i productname.msi /l*v package.log

This command generates a verbose log file logging all errors, warnings and debug messages and produces a huge log file in the text format. The first look at the log file might be slightly intimidating. This article tries to break the ice with the basics of reading the log file to troubleshoot problems with installation. Discussing all the error messages and its aspects is out of scope of this article. If you have specific questions, feel free to drop me a word. (at installneo@yahoo.com)

The Bottom Up Approach:

Whenever I read a log file, I start reading it from the bottom of the file. You might dismiss this technique as one of my eccentricities but I believe that this is the quickest, if not the most efficient, way of reading a log file in case of errors like 1603 or 1721. As a convention, the letter 'C' within brackets denotes the client context and the letter 'S' denotes the server context. So all messages in the log, which start as below, are messages in the client's context.

MSI (c) (A0:4C): Doing action: INSTALL
Action start 0:12:20: INSTALL.
MSI (c) (A0:4C): UI Sequence table 'InstallUISequence' is present and populated.
MSI (c) (A0:4C): Running UISequence

All messages in the log which start as below are messages from the MSI running in the server's context.

MSI (s) (1C:7C): Doing action: INSTALL
Action start 0:12:54: INSTALL.
MSI (s) (1C:7C): Running ExecuteSequence

Let us first analyze a successful log file and get ready to compare the anomalies with a not so perfect log file. I have used a simple Basic MSI project created with InstallShield X that just installs notepad.exe and I have disabled Update Ser. What we should be looking at is actions that do not have a return code of 1. You would find lines similar to the ones below just above the Server context property dump.

MSI (c) (04:B0): Doing action: SetupCompleteSuccess
Action start 18:03:47: SetupCompleteSuccess.
Action 18:03:47: SetupCompleteSuccess. Dialog created
Action ended 18:03:48: SetupCompleteSuccess. Return value 2.
Action ended 18:03:48: INSTALL. Return value 1.


Hmm... What does this mean? The "Action ended 18:03:48: SetupCompleteSuccess. Return value 2." message indicates that user cancelled the action or the operation was aborted due to a user instruction. But god knows that I did not instruct it stop. There must be something else that is wrong. The most obvious place to look for it would be the "Finish" button in the SetupCompleteSuccess dialog. You would find a line like the one below once you click on the Behavior tab of the dialog and select the OK control. If you insist on doing it via Orca, you can look at the ControlEvent table for the OK control in the SetupCompleteSuccess dialog.

EndDialog - Exit - 1

BINGO! We have found the culprit. The argument for the control event must be 'Return' instead of 'Exit'. Refer Windows Installer SDK help library article titled "EndDialog ControlEvent" for more information. Rebuild the project after changing it to 'Return' and you would find that none of the actions have return values other than '1'.

We have thus finally solved a trivial problem with the help of the log file, which would have gone unnoticed otherwise. Ah! Sweet Perfection.

:-)

Deferred Custom Actions:

One of the common places where users get confused is with deferred custom actions. Deferred Execution Custom Actions are not executed the first time the installer processes the custom actions in the Execute Sequence table. They are instead written to the MSI script. All these actions are executed within the InstallFinalize action. In these cases, you would have to look at the return value of the InstallFinalize action. A few lines above the line that indicates the return value of InstallFinalize would hint the action that failed. Let us verify this with a simple VBScript Custom Action that does nothing else but cause the install to fail </wink>. This is the code for the VBScript.

function MyFunction
MyFunction=1603
end function

I then create a Type 1030 custom action (VBScript Stored in Binary Table + Deferred Execution). This custom action is scheduled after InstallFiles action in the Install Execute Sequence. Run and log the installation. The installation proceeds and comes up with a dialog, which states that the Installation operation has failed. Let us look into the log for more information.

The final few lines in the log file complain that installation failed. But it still does have not enough information to identify an error.

MSI (c) (34:30): Product: SimpleInstaller -- Installation operation failed.

MSI (c) (34:30): Grabbed execution mutex.
MSI (c) (34:30): Cleaning up uninstalled install packages, if any exist
MSI (c) (34:30): MainEngineThread is returning 1603

Above the client contexts' property dump, the following lines of code indicate that INSTALL (Top level action) returns a value of 3 and the main thread is returning 1603. The SetupCompleteError is the same as we discussed earlier. This does not give much information either.

MSI (s) (DC:D8): MainEngineThread is returning 1603
MSI (c) (34:30): Back from server. Return value: 1603
MSI (c) (34:30): Decrementing counter to disable shutdown. If counter >= 0, shutdown will be denied. Counter after decrement: -1
Action ended 19:24:28: ExecuteAction. Return value 3.
MSI (c) (34:30): Doing action: SetupCompleteError
Action start 19:24:28: SetupCompleteError.
Action 19:24:29: SetupCompleteError. Dialog created
Action ended 19:24:30: SetupCompleteError. Return value 2.
Action ended 19:24:30: INSTALL. Return value 3.

Assuming that you have opened the log in notepad, search quickly for the word 'InstallFinalize' and specify the direction of search as up. You will now be able to see the following lines.

...
Our custom action is being called
MSI (s) (DC:D8): Executing op: ActionStart(Name=NewCustomAction1,,)
Action 19:24:28: NewCustomAction1.
MSI (s) (DC:D8): Executing op: CustomActionSchedule(Action=NewCustomAction1,ActionType=1030,Source=function MyFunction
MyFunction=1603
end function,Target=MyFunction,)
MSI (s) (DC:D8): Creating MSIHANDLE (3) of type 790536 for thread 2008
MSI (s) (DC:D8): Creating MSIHANDLE (4) of type 0 for thread 2008
MSI (s) (DC:D8): Closing MSIHANDLE (4) of type 0 for thread 2008
MSI (s) (DC:D8): Closing MSIHANDLE (3) of type 790536 for thread 2008
Our custom action fails causing the InstallFinalize action to fail
Action ended 19:24:28: InstallFinalize. Return value 3.
Initiate Rollback
MSI (s) (DC:D8): User policy value 'DisableRollback' is 0
MSI (s) (DC:D8): Machine policy value 'DisableRollback' is 0
MSI (s) (DC:D8): Executing op: Header
...
Rolls back changes

As you would have aptly guessed, the lines in bold are my comments. So you can nail most of troublesome deferred custom action using this technique.

I am really sleepy and have got some real work to do. I am sure I would touch on the log files again covering more aspects. Love it or Hate it, feel free to post your comments.