How to Troubleshoot Failed MSI Installs

I was given the Aventail VPN client software to install on a customer’s Windows 7 x64 computer. That failed miserably. Here is what I did to find the root cause of the problem.

Running the MSI

The Aventail VPN client software comes with multiple MSIs. One of those is ngclient.msi. When I ran it, I got the following error:

Troubleshooting MSI Execution

In order to find out what was happening, I re-ran the MSI with full logging enabled:

msiexec /i ngclient.msi /l*vx ngclient.msi.log

Then I inspected the generated log file. MSI logs can be a little confusing and it can be hard to find the actual error. It often helps so search for the string “return value 3” and work your way upwards from there. I got the following:

MSI (s) (70:E0) [13:22:51:551]: Executing op: ActionStart(Name=_7EE946E2_AD8A_4497_AD9C_565F98E3E0F0,,)
Action 13:22:51: _7EE946E2_AD8A_4497_AD9C_565F98E3E0F0. 
MSI (s) (70:E0) [13:22:51:551]: Executing op: CustomActionSchedule(Action=_7EE946E2_AD8A_4497_AD9C_565F98E3E0F0,ActionType=3089,Source=C:\Windows\ngmsi.dll,Target=DoInstallActions,)
MSI (s) (70:E0) [13:22:51:551]: Creating MSIHANDLE (1) of type 790536 for thread 4064
MSI (s) (70:A4) [13:22:51:551]: Invoking remote custom action. DLL: C:\Windows\ngmsi.dll, Entrypoint: DoInstallActions
MSI (s) (70:F4) [13:22:51:551]: Generating random cookie.
MSI (s) (70:F4) [13:22:51:567]: Created Custom Action Server with PID 3024 (0xBD0).
MSI (s) (70:1C) [13:22:51:739]: Running as a service.
MSI (s) (70:1C) [13:22:51:739]: Hello, I'm your 32bit Impersonated custom action server.
MSI (s) (70!F8) [13:22:51:754]: Creating MSIHANDLE (2) of type 790531 for thread 3576
MSI (s) (70!F8) [13:22:51:754]: Creating MSIHANDLE (3) of type 790531 for thread 3576
Action 13:22:51: DoInstallActions. Registering Product Services.....
DoInstallActions: Creating VPN Adapter Service
MSI (s) (70!F8) [13:22:52:004]: Closing MSIHANDLE (3) of type 790531 for thread 3576
MSI (s) (70!F8) [13:22:52:004]: Closing MSIHANDLE (2) of type 790531 for thread 3576
CustomAction _7EE946E2_AD8A_4497_AD9C_565F98E3E0F0 returned actual error code 1603 (note this may not be 100% accurate if translation happened inside sandbox)
MSI (s) (70:A4) [13:22:52:004]: Closing MSIHANDLE (1) of type 790536 for thread 4064
Action ended 13:22:52: InstallFinalize. Return value 3.

As one can see, a custom action is executed, and it fails. An MSI custom action may be any kind of code that is run outside of the control of Windows Installer. Generally speaking, custom actions are bad mostly because they are very difficult to get right but also because MSI logging stops at the boundaries of the custom action. Windows Installer has no way of looking into the action to see what is happening there.

In this case, the custom action even creates one line of log output (“DoInstallActions: Creating VPN Adapter Service”), but that does not really help here. OK, we now know that creating the VPN adapter fails, but why?

Monitoring the System

In order to find out more I re-ran the MSI, but this time with Process Monitor enabled. By comparing time stamps and filtering for MsiExec.exe I could determine roughly the area where things went wrong. But that time interval still consisted of hundreds of entries. A search for the usual suspects (“access denied”) did not yield anything helpful. But when I looked at the individual log entries I found references to the file “C:\ProgramData\Aventail\ngsetup.log”. That looked promising!

More Logs

Opening ngsetup.log I found the following near the end:

12:22:51: Performing custom installation actions
12:22:51: Moved "C:\Windows\Inf\ngvpn.inf" to "C:\ProgramData\Aventail\ngvpn.inf"
12:22:51: Moved "C:\Program Files (x86)\Aventail Connect\Install\ngvpn.cat" to "C:\ProgramData\Aventail\ngvpn.cat"
12:22:51: Moved "C:\Windows\system32\Drivers\ngvpn.sys" to "C:\ProgramData\Aventail\ngvpn.sys"
12:22:51: Moved "C:\Windows\system32\Drivers\nglog.sys" to "C:\ProgramData\Aventail\nglog.sys"
12:22:51: Moved "C:\Windows\system32\Drivers\ngfilter.sys" to "C:\ProgramData\Aventail\ngfilter.sys"
12:22:51: Moved "C:\Windows\system32\Drivers\ngwfp.sys" to "C:\ProgramData\Aventail\ngwfp.sys"
12:22:51: CopySignedDeviceFiles complete, status 0
12:22:51: InstallNgDeviceOnVista error: "ERROR_IN_WOW64"
12:22:51: CreateDevice complete, status 0
12:22:52: InstallNgDevice error: "ERROR_IN_WOW64"
12:22:52: DoInstallActions failed, error 3758096949
12:46:45: SvcRemove complete, status 0
12:46:45: Microsoft Windows 64-Bit
12:46:45: Performing custom installation actions
12:46:45: Moved "C:\Windows\Inf\ngvpn.inf" to "C:\ProgramData\Aventail\ngvpn.inf"
12:46:45: Moved "C:\Program Files (x86)\Aventail Connect\Install\ngvpn.cat" to "C:\ProgramData\Aventail\ngvpn.cat"
12:46:45: "C:\ProgramData\Aventail\ngvpn.sys" exists, failed to delete before move
12:46:45: CopySignedDeviceFiles complete, status 32
12:46:45: DoInstallActions failed, error 32

Finally, an error message! Searching for ERROR_IN_WOW64 quickly returned the following description:

“If the return value is ERROR_IN_WOW64, the 32-bit application is executing on a 64-bit platform and cannot update “in-box” drivers.”

At that point I slapped my forehead. Could it be that I had been given the 32-bit version of the software? Since it comes with drivers, it clearly cannot work on a 64-bit version of Windows. To confirm this hypothesis I opened one of the SYS files in EXE Explorer:

32 bit it is! With the root cause identified, all that remains is hunting down a 64-bit version of the software.