UGTS Document #15 - Last Modified: 8/29/2015 3:23 PM
Troubleshooting Microsoft Installer (MSI) Failures

The Microsoft Installer platform handles software installation from MSI and MSP installer files. It standardizes installation of software on Windows, and includes options to log all activity to troubleshoot installation failures.

If you have an install that is failing, first disable all antivirus software on the machine (so long as you trust the integrity of the software you are installing). Antivirus software generally interferes with installations and slows them down greatly.

Look in event viewer, Application log for errors with Source = 'MsiInstaller', this will tell you the error code, although it is not usually useful. Usually the error code is too generic to tell you anything, such as 1603 = fatal error during installation. The time of the error is not generally helpful either, since the event log entry is not logged at the exact time of the error, but at the time the install exits.

Run the MSI/MSP file from the command line by placing the install file in a directory and opening a command prompt in that directory. Then run the command line: [msiFile] /lxv* [logFile]. [msiFile] should be the name of the MSI/MSP file, and [logFile] can be a relative path to place the log file in the directory where the MSI/MSP file is. You can then open the log file in a text editor.

The log file is likely to contain a lot of spurious error messages which are not the cause of the failure.  For example, you'll probably see errors like these a lot: DEBUG: Error 2826: Control BottomLine on dialog FatalError extends beyond the boundaries of the dialog to the right by 5 pixels.  The installer ignores these messages except in special cases, and you can ignore them too. 

To find the error which terminated the install, look for a like like the following: Action ended 14:42:29: INSTALL. Return value 3.  Any return value other than 0 indicates a failure.  If this action failure caused the install to fail, you'll see immediately below this a dump of all the property values which can be quite long, and below that a line such as MSI (c) (F8:2C) [14:52:52:589]: Doing action: FatalError.  If you have trouble finding the action failure line, you may want to search for the Doing action: FatalError text, and then search backwards to the last action failure.  From there, look just before the action failure line to try to find the action that failed.

Once you know the exact action that failed, you can search the internet to find out possible reason the action failed.  If the action was running an external program or script, you may need to try running that program or script separately from the command line to find out why it is failing.

CASE STUDY #1: Exchange 2007 SP1 Rollup 10 Upgrade failure
When installing rollup 10 of Exchange 2007 SP1, the installer would spend a few minutes (an abnormally long time) calculating free space available, and then proceed to install but fail after stopping Exchange services.  Troubleshooting began.

The event log showed generic error code 1603, which was not helpful.  Antivirus services were disabled, and then installer was run this time from the command line with full logging.  This greatly sped up the install, but it still failed in the same place.

At first, it was not clear from the logs what the fatal error was, so an internet search was done.  This turned up possibilities of the .NET NGEN service being disabled, causing the install to fail.  The NGEN services for .NET 2.0 had indeed been disabled on the machine, but setting them to automatic startup did not help when the installer was re-run.

Searching the logs again, the fatal error cause was found.  The lines have been highlighted for emphasis, but the log file has no such highlighting:

MSI (s) (E0:4C) [14:42:21:505]: Doing action: CA_SAVEDATA_STOP_SERVICES
Stopping services Action start 14:42:21: CA_SAVEDATA_STOP_SERVICES
MSI (s) (E0:4C) [14:42:21:536]: Transforming table CustomAction.
MSI (s) (E0:4C) [14:42:21:536]: Transforming table CustomAction.
MSI (s) (E0:4C) [14:42:21:536]: Note: 1: 2262 2: CustomAction 3: -2147287038
MSI (s) (E0:4C) [14:42:21:536]: Note: 1: 2235 2: 3: ExtendedType 4: SELECT `Action`,`Type`,`Source`,`Target`, NULL, `ExtendedType` FROM `CustomAction` WHERE `Action` = 'CA_SAVEDATA_STOP_SERVICES'
MSI (s) (E0:4C) [14:42:21:552]: Transforming table CustomAction. MSI (s) (E0:4C) [14:42:21:567]: Transforming table CustomAction.
MSI (s) (E0:4C) [14:42:21:567]: Note: 1: 2262 2: CustomAction 3: -2147287038
MSI (s) (E0:4C) [14:42:21:583]: Transforming table Binary. MSI (s) (E0:4C) [14:42:21:583]: Transforming table Binary.
MSI (s) (E0:4C) [14:42:21:583]: Note: 1: 2262 2: Binary 3: -2147287038
MSI (s) (E0:4C) [14:42:21:599]: Creating MSIHANDLE (11) of type 790542 for thread 5452
MSI (s) (E0:78) [14:42:21:599]: Invoking remote custom action. DLL: C:\WINDOWS\Installer\MSI2E.tmp, Entrypoint: CAQuietExec
MSI (s) (E0:7C) [14:42:21:599]: Generating random cookie.
MSI (s) (E0:7C) [14:42:21:614]: Created Custom Action Server with PID 1652 (0x674).
MSI (s) (E0:90) [14:42:21:630]: Running as a service.
MSI (s) (E0:90) [14:42:21:645]: Hello, I'm your 32bit Impersonated custom action server.
MSI (s) (E0!50) [14:42:21:677]: Creating MSIHANDLE (12) of type 790541 for thread 336
MSI (s) (E0!50) [14:42:21:677]: Creating MSIHANDLE (13) of type 790531 for thread 336
MSI (s) (E0!50) [14:42:21:677]: Closing MSIHANDLE (13) of type 790531 for thread 336
MSI (s) (E0!50) [14:42:21:677]: PROPERTY CHANGE: Deleting QtExecCmdLine property. Its current value is '"C:\Program Files\Microsoft\Exchange Server\\bin\QuietExe.exe" "C:\WINDOWS\system32\WindowsPowerShell\v1.0\powershell.exe" " -command . 'C:\Program Files\Microsoft\Exchange Server\\bin\servicecontrol.ps1' BeforePatch"'.
MSI (s) (E0!50) [14:42:29:177]: Creating MSIHANDLE (14) of type 790531 for thread 336
CAQuietExec: Error 0x80070001: Command line returned an error.
MSI (s) (E0!50) [14:42:29:192]: Closing MSIHANDLE (14) of type 790531 for thread 336
MSI (s) (E0!50) [14:42:29:192]: Creating MSIHANDLE (15) of type 790531 for thread 336
CAQuietExec: Error 0x80070001: CAQuietExec Failed
MSI (s) (E0!50) [14:42:29:192]: Closing MSIHANDLE (15) of type 790531 for thread 336
MSI (s) (E0!50) [14:42:29:192]: Closing MSIHANDLE (12) of type 790541 for thread 336
MSI (s) (E0:78) [14:42:29:192]: Closing MSIHANDLE (11) of type 790542 for thread 5452
Action ended 14:42:29: CA_SAVEDATA_STOP_SERVICES. Return value 3.
MSI (s) (E0:4C) [14:42:29:223]: Transforming table InstallExecuteSequence.
MSI (s) (E0:4C) [14:42:29:223]: Transforming table InstallExecuteSequence.
MSI (s) (E0:4C) [14:42:29:223]: Note: 1: 2262 2: InstallExecuteSequence 3: -2147287038
Action ended 14:42:29: INSTALL. Return value 3.

The above logs showed that the installer was trying to launch the powershell script servicecontrol.ps1 and failing. An internet search showed that Exchange 2010 rollup 1 would fail here if there was a GPO defined which set the Powershell Execution policy, because the update installer would first shut down the WMI service, then run the script, and powershell would fail if there was a GPO defined for the execution policy, because group policy requires WMI to be running to evaluate WMI-targeted policies.

Although this MS KB article referred to Exchange 2010 and not 2007, there was such a GPO defined on the domain which set the UserPolicy to Unrestricted, but the GPO did not directly use WMI targeting for the scope. It was worth trying, so the policy was disabled, and the installer re-run, but it did not help. However, to reduce the number of possible factors, the policy was left disabled for the remainder of the troubleshooting.

To troubleshoot further, the script servicecontrol.ps1 was run directly from a powershell prompt in the Exchange Server\bin directory. An error message was shown, but strangely it did not seem to be fatal error, and yet it was causing the script to stop.

From there, it was discovered that this server had previously had powershell installed on it for other reasons, and there was a Profile.ps1 initialization script in the Windowspowershell directory which was executing the following code prior to running any powershell scripts on this server:

$global:ErrorActionPreference = 'Stop'
set-strictmode -Version 2.0

The ErrorActionPreference line was breaking the servicecontrol.ps1 script. After renaming the profile.ps1 script to something else so that Powershell would not use it, the Exchange update installer ran fine. However, due to running the servicecontrol.ps1 script directly, there was now the side effect that many services such as IIS and W3SVC had been left disabled. These were changed back manually from Disabled to Automatic, and started up to restore the server to the original condition.

It is unknown whether or not the GPO policy for Powershell was also interfering or if the NGEN services being disabled were causing trouble, but is is unlikely that either of these was a factor. The GPO was re-enabled after the install completed, and the NGEN services were left set to Automatic. However, the offending Profile.ps1 script was removed to avoid further conflict with Exchange.

Case closed.