Home » Groups » Application Packaging

Troubleshooting Wise Packages with Windows Installer Logs

Troubleshooting Wise Packages with Windows Installer Logs
Filed under: Wise Package Studio Software Delivery
Submitted by DavidLockwood on 30 March, 2007 - 08:54.

When you create an MSI package with Wise Package Studio an error may prevent the package from installing. This will cause the install to fail and a rollback will occur. A rollback means that any changes made by the installation will be removed. Read on to learn more.

The main tool you should use to troubleshoot install time errors is the Windows Installer log file. There are two way to create a log file. You can either use a command line or activate a group policy.

The command line to activate verbose logging is:

Msiexec /I "Pathtomsifile" /L*v "Pathtologfile"

For instance:

Msiexec /I "C\test.msi" /L*v "C:\mylog.log"

The /L*v parameter activates verbose logging. This means that everything will be logged.

The Command Line Builder tool in Wise Package Studio can be used to automatically generate a correct command line.

Parameters to create log file:

v - Verbose output
o - Out-of-disk-space messages
i - Status 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
u - User requests
p - Terminal properties
+ - Append to existing file
! - Flush each line to the log

"*" - Wildcard, log all information except for the v option. To include the v option, specify "/l*v".

To activate the group policy for logging run the gpedit.msc tool from a command line. Under Computer Configuration > Administrative Templates > Windows Components > Windows Installer choose the logging option. Set this to be enabled. Set the logging field to voicewarmup to ensure that everything is logged.

Click to view.

Click to view.

How to Read a Windows Installer Log File

A Windows Installer package installs an application by launching a set of actions, in sequences, which read from specific tables. This can be remembered with the acronym T-A-S (Tables, actions, sequences). You should keep this in mind when reading a log file.

The log file shows each action as it launches and the corresponding result, success or failure. The log file also shows which relevant group policies are applied and the final value of all properties.

Here is an annotation of a Windows Installer log files. Remarks are highlighted in green. They discuss the parts of the log file highlighted in yellow. 

=== Verbose logging started: 24/07/2006  22:01:16  Build type: SHIP UNICODE 3.01.4000.2435  Calling process: C:\WINDOWS\System32\msiexec.exe ===
MSI (c) (08:D4) [22:01:16:269]: Resetting cached policy values
MSI (c) (08:D4) [22:01:16:269]: Machine policy value 'Debug' is 0
MSI (c) (08:D4) [22:01:16:269]: ******* RunEngine:
           ******* Product: C:\Wise Share Point\Projects\Versions\1.0\versions.msi
                                         The original package we have launched
           ******* Action:
           ******* CommandLine: **********
MSI (c) (08:D4) [22:01:16:269]: Machine policy value 'DisableUserInstalls' is 0
MSI (c) (08:D4) [22:01:16:730]: SOFTWARE RESTRICTION POLICY: Verifying package ~1\Temp\deec6a3.msi
A temp company used for the duration of the install
MSI (c) (08:D4) [22:01:17:280]: APPCOMPAT: looking for appcompat database entry with ProductCode '{94D53C30-374B-44CB-90C9-B96B9714AD5E}'.
MSI (c) (08:D4) [22:01:17:320]: Note: 1: 2262 2: MsiFileHash 3: -2147287038
MSI (c) (08:D4) [22:01:17:320]: Machine policy value 'DisablePatch' is 0
MSI (c) (08:D4) [22:01:17:320]: Machine policy value 'AllowLockdownPatch' is 0
MSI (c) (08:D4) [22:01:17:320]: Machine policy value 'DisableLUAPatching' is 0
MSI (c) (08:D4) [22:01:17:320]: Machine policy value 'DisableFlyWeightPatching' is 0
We can see which group policies have been set. 
... 
 
MSI (c) (08:D4) [22:01:17:891]: Doing action: INSTALL
The c stand for client. We are in the client/UI part of the install.
Action 22:01:18: INSTALL.
Action start 22:01:18: INSTALL.
MSI (c) (08:D4) [22:01:18:182]: UI Sequence table 'InstallUISequence' is present and populated.
The Install sequence is starting using the InstallUISequence table. This means it is a full non-silent install.
MSI (c) (08:D4) [22:01:18:182]: Running UISequence
MSI (c) (08:D4) [22:01:18:182]: PROPERTY CHANGE: Adding EXECUTEACTION property. Its value is 'INSTALL'.
MSI (c) (08:94) [22:01:18:222]: Cloaking enabled.
MSI (c) (08:94) [22:01:18:222]: Attempting to enable all disabled priveleges before calling Install on Server
The original developer has included an incorrect spelling for privilege
MSI (c) (08:D4) [22:01:20:795]: Doing action: LaunchConditions
Action 22:01:20: LaunchConditions. Evaluating launch conditions...
Action start 22:01:20: LaunchConditions.
The first action to be launched is called LaunchConditions
MSI (c) (08:D4) [22:01:20:795]: Note: 1: 2262 2: LaunchCondition 3: -2147287038
Action ended 22:01:20: LaunchConditions. Return value 1.
A return value of 1 means this action has terminated successfully.
MSI (c) (08:D4) [22:01:20:795]: Skipping action: SetPatchMode (condition is false)
MSI (c) (08:D4) [22:01:20:795]: Skipping action: SetPatchReinstallMode (condition is false)
This action is not executed because a condition, in the condition column of the InstallUISequence table, has resolved to false.
MSI (c) (08:D4) [22:01:20:795]: Doing action: Setup_Dialog 
... 

MSI (c) (08:D4) [22:01:21:076]: Doing action: CostInitialize
Action 22:01:21: CostInitialize. Computing space requirements...
Action start 22:01:21: CostInitialize.
MSI (c) (08:D4) [22:01:21:076]: Machine policy value 'MaxPatchCacheSize' is 10
MSI (c) (08:D4) [22:01:21:086]: PROPERTY CHANGE: Adding ROOTDRIVE property. Its value is 'E:\'.
The ROOTDRIVE has been set to the drive with the most space. In this case this is E:\. You might want to hardcode this to C:\
MSI (c) (08:D4) [22:01:21:086]: PROPERTY CHANGE: Adding CostingComplete property. Its value is '0'.
Action ended 22:01:21: CostInitialize. Return value 1.
MSI (c) (08:D4) [22:01:21:086]: Doing action: FileCost
Action 22:01:21: FileCost. Computing space requirements...
Action start 22:01:21: FileCost.
Action ended 22:01:21: FileCost. Return value 1.
MSI (c) (08:D4) [22:01:21:086]: Doing action: IsolateComponents
Action 22:01:21: IsolateComponents.
... 

MSI (c) (08:D4) [22:01:26:113]: Skipping action: Maintenance_Welcome_Dialog (condition is false)
MSI (c) (08:D4) [22:01:26:113]: Doing action: Progress_Dialog
Action 22:01:26: Progress_Dialog.
Action start 22:01:26: Progress_Dialog.
DEBUG: Error 2826:  Control Line7 on dialog Progress_Dialog extends beyond the boundaries of the dialog to the right by 1 pixels
Internal Error 2826. Progress_Dialog, Line7, to the right
Action 22:01:26: Progress_Dialog. Dialog created
Action ended 22:01:26: Progress_Dialog. Return value 1.
MSI (c) (08:D4) [22:01:26:133]: Doing action: ExecuteAction
Action 22:01:26: ExecuteAction.
Action start 22:01:26: ExecuteAction.
MSI (c) (08:D4) [22:01:26:173]: PROPERTY CHANGE: Adding SECONDSEQUENCE property. Its value is '1'.
MSI (c) (08:D4) [22:01:26:173]: Grabbed execution mutex.
After this point in the sequence only one instance of an MSI can be running. A mutex is a construct designed to provide mutually exclusive access to a resource This is why you see an error when you try to install two MSI packages at the same time (but only after this stage in the client sequence). This is to prevent a race condition occurring.
MSI (c) (08:D4) [22:01:26:173]: Incrementing counter to disable shutdown. Counter after increment: 0
MSI (c) (08:D4) [22:01:26:173]: Switching to server: SECONDSEQUENCE="1" ALLUSERS="1" ROOTDRIVE="E:\" INSTALLDIR="C:\Program Files\Versions\" SOURCEDIR="C:\Wise Share Point\Projects\Versions\1.0\" TARGETDIR="E:\" GAC="E:\" WWWROOT="E:\" COMPANYNAME="Altiris Services GmbH" USERNAME="Altiris Services GmbH" EXECUTEACTION="INSTALL" ACTION="INSTALL" CLIENTPROCESSID="1800" CLIENTUILEVEL="0" CURRENTDIRECTORY="C:\"  ADDLOCAL=Complete 
Properties are passed from the client side to the server side. Only PUBLIC properties, which you can easily differentiate because they are upper case, are passed. The values of all private properties are lost when you move from the client side to the server side.
MSI (s) (C4:D8) [22:01:26:283]: Grabbed execution mutex.
MSI (s) (C4:00) [22:01:26:283]: Resetting cached policy values
Now the s indicates the server or execute part of the installation. This is the held in the InstallExecuteSequence table. This is the only sequence which will run during a silent installation.
MSI (s) (C4:00) [22:01:26:293]: Machine policy value 'Debug' is 0
MSI (s) (C4:00) [22:01:26:293]: ******* RunEngine:

           ******* Product: C:\Wise Share Point\Projects\Versions\1.0\versions.msi
           ******* Action: INSTALL
           ******* CommandLine: **********
MSI (s) (C4:00) [22:01:26:804]: Original package ==> C:\Wise Share Point\Projects\Versions\1.0\versions.msi
MSI (s) (C4:00) [22:01:26:804]: Package we're running from ==> C:\WINDOWS\Installer\deeed72.msi
MSI (s) (C4:00) [22:01:26:814]: APPCOMPAT: looking for appcompat database entry with ProductCode '{94D53C30-374B-44CB-90C9-B96B9714AD5E}'. 
.. 

MSI (s) (C4:00) [22:01:26:834]: Command Line: SECONDSEQUENCE=1 ALLUSERS=1
ALLUSERS=1 means this is a per-machine install.
ROOTDRIVE=E:\ INSTALLDIR=C:\Program Files\Versions\ SOURCEDIR=C:\Wise Share Point\Projects\Versions\1.0\ TARGETDIR=E:\ GAC=E:\ WWWROOT=E:\ COMPANYNAME=Altiris Services GmbH USERNAME=Altiris Services GmbH EXECUTEACTION=INSTALL ACTION=INSTALL CLIENTPROCESSID=1800 CLIENTUILEVEL=0 CURRENTDIRECTORY=C:\ ADDLOCAL=Complete
Action start 22:02:03: BindImage.
MSI (s) (C4:00) [22:02:03:567]: Note: 1: 2262 2: BindImage 3: -2147287038
Action ended 22:02:03: BindImage. Return value 1.
MSI (s) (C4:00) [22:02:03:567]: Doing action: CreateShortcuts
Action 22:02:03: CreateShortcuts. Creating shortcuts...
Action start 22:02:03: CreateShortcuts.
Action ended 22:02:03: CreateShortcuts. Return value 1.
MSI (s) (C4:00) [22:02:03:567]: Doing action: RegisterClassInfo
Action 22:02:03: RegisterClassInfo. Registering class servers...
Action start 22:02:03: RegisterClassInfo.
MSI (s) (C4:00) [22:02:03:577]: Note: 1: 2262 2: Class 3: -2147287038
Action ended 22:02:03: RegisterClassInfo. Return value 1.
MSI (s) (C4:00) [22:02:03:577]: Doing action: RegisterExtensionInfo
Action 22:02:03: RegisterExtensionInfo. Registering extension servers...
Action start 22:02:03: RegisterExtensionInfo.
MSI (s) (C4:00) [22:02:03:577]: Note: 1: 2262 2: Extension 3: -2147287038
Action ended 22:02:03: RegisterExtensionInfo. Return value 1.
MSI (s) (C4:00) [22:02:03:577]: Doing action: RegisterProgIdInfo
Action 22:02:03: RegisterProgIdInfo. Unregistering program identifiers...
Action start 22:02:03: RegisterProgIdInfo.
MSI (s) (C4:00) [22:02:03:577]: Note: 1: 2262 2: ProgId 3: -2147287038
MSI (s) (C4:00) [22:02:03:577]: Note: 1: 2262 2: Class 3: -2147287038
MSI (s) (C4:00) [22:02:03:587]: Note: 1: 2262 2: ProgId 3: -2147287038
MSI (s) (C4:00) [22:02:03:587]: Note: 1: 2262 2: Extension 3: -2147287038
Action ended 22:02:03: RegisterProgIdInfo. Return value 1.
MSI (s) (C4:00) [22:02:03:587]: Doing action: RegisterMIMEInfo
Action 22:02:03: RegisterMIMEInfo. Registering MIME information...
Action start 22:02:03: RegisterMIMEInfo.
MSI (s) (C4:00) [22:02:03:587]: Note: 1: 2262 2: MIME 3: -2147287038
MSI (s) (C4:00) [22:02:03:587]: Note: 1: 2262 2: Extension 3: -2147287038
Action ended 22:02:03: RegisterMIMEInfo. Return value 1.
MSI (s) (C4:00) [22:02:03:587]: Doing action: WriteRegistryValues
Action 22:02:03: WriteRegistryValues. Writing system registry values...
Action start 22:02:03: WriteRegistryValues.
Action ended 22:02:03: WriteRegistryValues. Return value 1.
This is an important action responsible for writing most registry values
ActionStart(Name=InstallFiles,Description=Copying new files...,Template=File: [1]
Directory: [9]
Size: [6])
Action 22:02:03: InstallFiles. Copying new files...
MSI (s) (C4:00) [22:02:03:697]: Executing op: SetTargetFolder(Folder=C:\Program Files\Versions\)
MSI (s) (C4:00) [22:02:03:697]: Executing op: SetSourceFolder(Folder=1\Progra~1\Versions\|Program Files\Versions\)
MSI (s) (C4:00) [22:02:03:697]: Executing op: ChangeMedia(,MediaPrompt=Please insert the disk: [ProductName] LABEL,MediaCabinet=Cabs.w1.cab,BytesPerTick=32768,CopierType=2,ModuleFileName=C:\WINDOWS\Installer\deeed72.msi,,,,,IsFirstPhysicalMedia=1)
MSI (s) (C4:00) [22:02:03:697]: Executing op: FileCopy(SourceName=notepad.exe,SourceCabKey=notepad.exe,DestName=notepad.exe,Attributes=1024,FileSize=69120,PerTick=32768,,VerifyMedia=1,,,,,CheckCRC=0,Version=5.1.2600.2180,Language=1033,InstallMode=58982400,,,,,,,)
MSI (s) (C4:00) [22:02:03:707]: File: C:\Program Files\Versions\notepad.exe; Won't Overwrite; Won't patch; Existing file is of an equal version
Here we can see file versioning rules in action. This install will not install the notepad.exe file because an version of that file already exists in that location and the version is equal. Windows Installer will only replace files with if the new one has a higher version.
MSI (s) (C4:00) [22:02:03:707]: Executing op: CacheSizeFlush(,)
MSI (s) (C4:00) [22:02:03:707]: Executing op: InstallProtectedFiles(AllowUI=1)
Action ended 22:02:05: InstallFinalize. Return value 1.
MSI (s) (C4:00) [22:02:05:199]: Doing action: RemoveExistingProducts
Action 22:02:05: RemoveExistingProducts. Removing applications
Action start 22:02:05: RemoveExistingProducts.
MSI (s) (C4:00) [22:02:05:199]: Note: 1: 2262 2: Upgrade 3: -2147287038
Action ended 22:02:05: RemoveExistingProducts. Return value 1.
Action ended 22:02:05: INSTALL. Return value 1.
Property(S): SourcedirProduct = {94D53C30-374B-44CB-90C9-B96B9714AD5E}
Property(S): SourceDir = C:\Wise Share Point\Projects\Versions\1.0\
Property(S): PrimaryVolumePath = C:
Property(S): PrimaryVolumeSpaceRemaining = 8808328
Property(S): PrimaryVolumeSpaceRequired = 576
Property(S): PrimaryVolumeSpaceAvailable = 8808904
The end of the log file contains all properties and their final values. This is very useful if you need to find out which property a particular value has been stored in.
Property(S): CommonFilesFolder = C:\Program Files\Common Files\
Property(S): VersionNT = 501
The VersionNT property was set to 50. This means this package was installed on an XP machine.
Property(S): COMPANYNAME = Altiris Services GmbH
Property(S): USERNAME = Altiris Services GmbH
Property(S): ARPINSTALLLOCATION = C:\Program Files\Versions\
Property(S): Preselected = 1
Property(S): LogonUser = david.lockwood
Property(S): AdminUser = 1
Property(C): MsiWin32AssemblySupport = 5.1.2600.2180
Property(C): MsiNetAssemblySupport = 2.0.50727.42
Property(C): Time = 22:02:06
Property(C): TTCSupport = 1
Property(C): ColorBits = 32
Property(C): TextHeight = 16
Property(C): GPTSupport = 1
Property(C): RemoteAdminTS = 1
Property(C): WindowsVolume = C:\
Property(C): MsiNTProductType = 1
(C): PackagecodeChanging = 1
Property(C): ProductState = -1
Property(C): PackageCode = {C9D8DBA4-06E3-47D5-9027-D8F35D5982F1}
=== Logging stopped: 24/07/2006  22:02:06 ===
MSI (c) (08:D4) [22:02:06:681]: Note: 1: 1707
MSI (c) (08:D4) [22:02:06:681]: Product: Versions -- Installation operation completed successfully.
Right at the end of a non-silent install the Windows Installer engine switches back to the client sequence.
MSI (c) (08:D4) [22:02:06:872]: Grabbed execution mutex.
MSI (c) (08:D4) [22:02:06:872]: Cleaning up uninstalled install packages, if any exist
MSI (c) (08:D4) [22:02:06:892]: MainEngineThread is returning 0
=== Verbose logging stopped: 24/07/2006  22:02:06 ===
4.1
Average: 4.1 (10 votes)

Log MSI installations through RegKey setting

rpfenninger's picture
Submitted by rpfenninger on 30 March, 2007 - 09:27.

Hi David

Nice article about logging.
However, don't forget to mention that logging an MSI installation can be triggered through the following RegKey setting:

[HKEY_LOCAL_MACHINE\SOFTWARE\Policies\Microsoft\Windows\Installer]
"Logging"="voicewarmup"

That's my preferred method.

Cheers
Roland

Yes, good point.

Submitted by DavidLockwood on 30 March, 2007 - 10:45.

Yes, good point.

That is the registry key set up by the group policy discussed in the article. You can set the key directly as well.

Monitor MSI installation actions in real time.

Submitted by AngelD on 30 March, 2007 - 11:02.

You can also monitor MSI installation actions in real time.

Create the Debug (REG_DWORD) registry entry under HKLM\SOFTWARE\Policies\Microsoft\Windows\Installer and set the data value to 00000002.

Download DebugView for Windows from SysInternals/Microsoft.

Start DebugView either on the local machine or by connecting remotely to the target machine.

MSI (Windows Installer) installations on the target machine will write their Standard/Custom Actions to the debug port and this will be displayed in DebugView

This is handy when you for example want to know what a specific button, input or any other selection does or sets in a Dialog. If you don't have InstallTailor to create the transform from you could use this to see any changes in the Dialogs and then just add/modify those properties with the info you got from the DebugView tool.

Amazing tip

trb48's picture
Submitted by trb48 on 31 March, 2007 - 22:47.

Thanks for the amazing tip! I have needed something like this for a long time. It is hard to know why a program did not install, but with this you can see! I am excited to try this out!

Troubleshooting Windows Installer logs

Submitted by AngelD on 30 March, 2007 - 13:23.

You referenced in which context an action occurs: the Client context indicated by "MSI (c)" and the Server context indicated by "MSI (s)". You also have the CustomAction Server context which is indicated by "MSI (a)".

A good starting point for troubleshooting Windows Installer log files can be found under the "Strategies for Troubleshooting" section and below at Windows Installer: Benefits and Implementation for System Administrators. There is also an "Appendix A: An Annotated Windows Installer Log File" section that goes through a sample log with some great information regarding the different log entries.

Realtime - Read on Error

Submitted by Richard Jeffrey on 10 December, 2007 - 14:00.

Hope this may help someone else.

If an installation is causing issues and stops with a dialog window, I always try looking at the log file at the point of the error. Just leave the dialog window without a response and read / copy the log file. I have mostly found the last line in the log file refers to the error, this saves time in finding the error within the final log file.