Wednesday 13 June 2012

wix, managed code custom action may fail when temp folder is compressed

msi installer was created by WiX 3.5. VM with Windows Server 2003 SP1 32 bit, Windows Installer 4.5, .Net 3.5 SP1.

It had a c# custom action named Managed_PutFeatureState. That custom action was failing with not many clues in the log (see below). Added logging to c# code, added try\catch constructs to prevent any possible failures and it still was failing. Noticed that it fails maybe 80% of times which was even more annoying.

I thought that it had something to do with files it creates in %TEMP% folder, by some reason I suspected that it either couldn't unpack or couldn't find an unpacked .dll file with the custom action itself.

Ran ProcMon.exe from sysinternals to see what is going on on the disk. And it stopped failing when ProcMon was capturing the events!

This started me thinking about disk i\o. Played with various virtualization settings, host i\o enabled\disabled, etc to no joy. Still it was failing.

Solution: disable "compressed" attribute on %TEMP% folder!

ran via command line with logging like this:
msiexec /l*vx! install.log /i MySetup.msi 
The log:

MSI (c) (50:54) [13:02:15:952]: Doing action: Managed_PutFeatureState
Action 13:02:15: Managed_PutFeatureState.
Action start 13:02:15: Managed_PutFeatureState.
MSI (c) (50:54) [13:02:16:046]: Creating MSIHANDLE (5) of type 790542 for thread 3924
MSI (c) (50:E8) [13:02:16:046]: Invoking remote custom action. DLL: C:\DOCUME~1\ADMINI~1\LOCALS~1\Temp\MSI9.tmp, Entrypoint: PutFeatureState
MSI (c) (50!F0) [13:02:16:108]: Creating MSIHANDLE (6) of type 790531 for thread 4080
MSI (c) (50!F0) [13:02:16:124]: Closing MSIHANDLE (6) of type 790531 for thread 4080
MSI (c) (50!F0) [13:02:16:186]: Creating MSIHANDLE (7) of type 790531 for thread 4080
MSI (c) (50!F0) [13:02:16:186]: Closing MSIHANDLE (7) of type 790531 for thread 4080
MSI (c) (50!F0) [13:02:16:327]: Creating MSIHANDLE (8) of type 790531 for thread 4080
MSI (c) (50!F0) [13:02:16:343]: Closing MSIHANDLE (8) of type 790531 for thread 4080
MSI (c) (50!F0) [13:02:16:374]: Note: 1: 2727 2:
MSI (c) (50!F0) [13:02:16:389]: Note: 1: 2205 2:  3: MsiAssembly
MSI (c) (50!F0) [13:02:16:389]: Note: 1: 2228 2:  3: MsiAssembly 4:  SELECT `MsiAssembly`.`Attributes`, `MsiAssembly`.`File_Application`, `MsiAssembly`.`File_Manifest`,  `Component`.`KeyPath` FROM `MsiAssembly`, `Component` WHERE  `MsiAssembly`.`Component_` = `Component`.`Component` AND `MsiAssembly`.`Component_` = ?
MSI (c) (50!F0) [13:02:16:389]: Note: 1: 1402 2: HKEY_CLASSES_ROOT\.4 3: 2
MSI (c) (50!F0) [13:02:16:405]: Note: 1: 2205 2:  3: _RemoveFilePath
MSI (c) (50!F0) [13:02:16:405]: Note: 1: 2727 2:
MSI (c) (50!F0) [13:02:16:514]: Note: 1: 2727 2:
MSI (c) (50!F0) [13:02:16:546]: Note: 1: 2727 2:
MSI (c) (50:E8) [13:02:16:577]: Closing MSIHANDLE (5) of type 790542 for thread 3924
Action ended 13:02:16: Managed_PutFeatureState. Return value 3.
DEBUG: Error 2896:  Executing action Managed_PutFeatureState failed.
The installer has encountered an unexpected error installing this package. This may indicate a problem with this package. The error code is 2896. The arguments are: Managed_PutFeatureState, ,
Action ended 13:02:16: WelcomeDlg. Return value 3.
MSI (c) (50:58) [13:02:16:608]: Doing action: FatalError
Action 13:02:16: FatalError.
Action start 13:02:16: FatalError.
Action 13:02:16: FatalError. Dialog created
Action ended 13:02:17: FatalError. Return value 2.
Action ended 13:02:17: INSTALL. Return value 3.
MSI (c) (50:58) [13:02:17:686]: Destroying RemoteAPI object.
MSI (c) (50:9C) [13:02:17:686]: Custom Action Manager thread ending.

No comments:

Post a Comment