Thursday, 13 October 2011

How To Read A Windows Installer Verbose Log

 
This document explains the main concepts of how to read a verbose log file created by the Windows Installer.  Non-verbose logs may not contain as much information talked about below and may not provide enough useful information for a failed setup installation.
Verbose logs will contain at least the following information:
  • Errors that occur during the installation including internal Windows Installer errors
  • All standard actions executed as well as any custom actions that were executed
  • If a reboot was requested and completed
  • The source location of the installation media
  • If the installation was completed
  • If the installation was rolled back, this will also be notated in the log
On Windows NT 4, Windows 2000 and Windows XP, the Windows Installer executes an installation in two distinct processes.  One is a client process and the other is a server process.  The log file will show the installation information for both processes.  An installation on a Windows 98, Windows 98 or Windows Millennium will run only in a client process, there is no concept of a server process on these platforms.  In a typical verbose log file, you will see lines like the following for a line that denotes the information presented was done on the client context of the installation:
MSI (c) (29:28) : Resetting cached policy values
In a typical verbose log file, you will see lines like the following for a line that denotes the information presented was done on the server process of the installation:
        MSI (s) (A0:EC): Original package ==> D:\TEMP\Default.msi
The (29:28) and (A0:EC) entries above represent the last two digits of the process and thread ids respectively that generated the entry in the log file.  Generally, this information is not too useful but can shed some light on which process and thread is associated with log entry.  In the above entry, we also see where the original source package is located at.  In this case, if an uninstall or repair is performed, the location of the package will be first read from d:\temp\default.msi.
The log file will first show the client process while the setup user interface is running.  After the setup user interface has been completed by the end user, the log file will show the a line like the following:
        MSI (c) (29:28) : Switching to server: COMPANYNAME="Microsoft" USERNAME="Admininstrator" ...
This line signals that the installation execution is now passing to the server process.  Only approved public properties which will be in all uppercase are propagated to the server process to enforce the final changes of the setup installation.  Non-uppercase properties are considered private properties and are not passed to the server process.
The beginning of the server process will look very similar to the beginning of the client process.  The service must re-evaluate all of the settings to prevent a user without sufficient privileges from performing a setup request that should not allowed.  This includes revaluating the private properties, policies and other installation state settings such as the features and components to be installed.
The  server process performs the actual installation functions such as copying files, writing to the registry, etc.  Most actions appear in two forms in a verbose log file.  The first form is to add it to the installation script that will be ran later on in the installation.
    MSI (s) (24:24): Doing action: RegisterTypeLibraries
Action start 13:02:32: RegisterTypeLibraries.
    GenerateScript: Registering type libraries
Action ended 13:02:32: RegisterTypeLibraries. Return value 1.
The second form is the actual execution of the action:
        MSI (s) (24:24): Executing op: ActionStart(Name=RegisterTypeLibraries,Description=Registering type libraries,Template=LibID: )
        Action 13:04:42: RegisterTypeLibraries. Registering type libraries
For standard and custom actions, the return values can be one of the following values in the table.  For more information on the return values, please see the help file topic Logging of Action Return Values in the the Windows Installer SDK.
Value
Meaning
0
action not executed
1
success
2
user canceled
3
fatal error
4
suspended, waiting for a reboot
In the example above, we see that the return value for the RegisterTypeLibraries standard action was 1 meaning the action completed successfully.  If this action failed and caused an error, a return value of 3 would have been returned and would have caused the rest of the installation to stop and the rollback process would begin which would return the system back to the same state before the installation began.
When copying  files, the log file will explain why a particular file was or was not copied.  This can be useful when trying to determine why a particular file is or is not copied to the machine.  An example line in the log file may look like the following, note the areas highlighted in bold.
       MSI (s) (34:A1): Executing op:
FileCopy(SourceName=Global_Vba_VBStockProp_f0.7EBEDD3E_AA66_11D2_B980_006097C4DE24,DestName=msstkprp.dll,Attributes=0,FileSize=94208,Version=6.0.81.69,Language=1033,InstallMode=58982400)
       MSI (s) (34:A1): File: C:\WINNT\System32\msstkprp.dll; Won't Overwrite; Existing file is of an equal version
Another useful item that is included in a verbose log file is the feature and component state values that are used during the installation.  The following  is an example entry in a verbose log file for a feature state, note the areas highlighted in bold.
       MSI (s) (34:A1): Feature: _MainFeature; Installed: Absent; Request: Local; Action: Local
For a feature state entry in the log file, the entry will be prefaced with Feature: and the feature name will follow.  In this case, the feature state being displayed is for the feature named _MainFeature. The Installed entry represents the current state of the feature on the machine.  When the setup package is being in installed for the first time, this value following Installed: will typically be Absent meaning the feature is not currently installed on the machine.  Other values are possible such as Local, Null, Request, etc.  For the complete list and their meaning, consult the MsiGetFeatureState documentation in the Windows Installer SDK.  The Request entry represents what the user has requested for the particular feature.  For this example, the user has requested to install the _MainFeature Local.  If this was an uninstall and the user selected to remove the _MainFeature feature, Request would be set to Absent which means to uninstall this feature.  A value of Null for Request would represent the feature will neither be installed nor removed.  The last entry, Action, represents what the Windows Installer is going to actually do for Request entry.  It would be rare that the Action entry did not equal the Request entry.  In this case, the Action to be taken is to install the _MainFeature locally to disk.
The following  is an example entry in a verbose log file for a component state, note the areas highlighted in bold.
        MSI (s) (34:A1): Component: Global_Notepad; Installed: Local; Request: Null; Action: Null
For a component state entry in the log file, the entry will be prefaced with Component: and the component name will follow.  In this case, the component state being displayed is for the component named Global_Notepad. The Installed entry represents the current state of the feature on the machine.  When the setup package is being in installed for the first time, this value following Installed will typically be Absent meaning the component is not currently installed on the machine.  For this example, Installed is set to Local meaning that the underlying component is already installed on the machine.  There are other values are possible for Installed such as Local, Null, Request, etc.  For the complete list and their meaning, consult the MsiGetComponentState documentation in the Windows Installer SDK.  The Request entry represents what the user has requested for the particular feature that this component belongs to.  For this example, the Windows Installer engine has determined based on the user's feature selection to do nothing for the Global_Notepad component which is denoted by Request being set to Null.  If this was an uninstall and the user selected to remove the feature that the Global_Notepad component belong to, Request could be set to Absent which means to uninstall this component.  The last entry, Action, represents what the Windows Installer is going to actually do for Request entry.  It would be rare that the Action entry did not equal the Request entry.  In this case, the Action to be taken is to neither install nor remove the Global_Notepad component.
If a setup installation encounters an error, a verbose log file will contain information about rolling back the installation.  You can find rollback information in the log file by searching for Rollback:.  The following line is an example line which states what action is currently being rolled back
        Rollback: Registering type libraries
In this example, we can see that the RegisterTypeLibraries standard action is rolling back the previous work done earlier in the installation when the RegisterTypeLibraries action executed.
At the end of the verbose log file is a complete property dump of the property names and values which can have either client and server properties listed, client only or server only depending on what operating system the log was generated on and what the user interface level was set to.  For example, in a quiet mode installation on Windows NT, 2000 or XP, only the server process is executed and only server process properties would be displayed at the end of the log file.  The following is an example line found in a verbose log file of a property and its value at the end of the client part of the installation before switching to the server process.
Property(C): USERNAME = someuser
This line shows the value of the USERNAME property on the client side of the installation before switching over to the server process was set to someuser.  You can tell this is a client property by noticing the C in the Property (C) notation.
The following is an example line found in a verbose log file of a property and its value at the end of the server part of the installation just before the installation terminated.
Property(S): USERNAME = someuser
This line shows the value of the USERNAME property on the server side of the installation was set to someuser.  You can tell this is a server property by noticing the S in the Property (S) notation.  Please note that the USERNAME property in this case has the same value on both the client and server side, however this may not always be the case for all properties as some properties may change on the server side due to custom actions changing the property.

























No comments:

Post a Comment