Posts Tagged ‘Msi’

Strange case of mixed 32 bit and 64 bit installers in single Suite installer

March 20, 2017

TL;DR; Do not mix 32 bit msi with 64 bit msi installers in single Suite installer. 

Suite installer is an installer that allows orchestrating multiple msi installers into single user experience. A customer reported that our Suite installer fails randomly when run from Chef scripts in AWS but is fine when run from GUI. To make things more complex, the installation would fail only around 50% of the times. Of course we could not get hold of Cloud Formation templates the customer used and we could not access the customer environment because it ran in AWS Gov Cloud and none of us is US citizen.

windows_package 'AppAndPrerequisiteSuite' do
 source 'AppAndPrerequisiteSuite.exe'
 installer_type :custom
 options '/debuglog c:/consolidatedinstaller.log'
end

First thing we asked was to enable individual installers logging. (https://support.microsoft.com/en-us/help/223300/how-to-enable-windows-installer-logging)

This yielded :

Error 1935.An error occurred during the installation of assembly component {6F6751F2-43FB-4C77-9791-B24EB154D406}. HRESULT: 0x800703FA. assembly interface: IAssemblyCacheItem, function: Commit, assembly name: Company.Systems.Services,processorArchitecture=”amd64″,publicKeyToken=”45d8b3bf5a7dd114″,type=”win32″,version=”1.0.0.73″

Hmm. HRESULT: 0x800703FA? A quick Internet search says that it is “Illegal operation attempted on a registry key that has been marked for deletion”. But which key has been deleted? We are only installing at this stage, not uninstalling, right? We tried to set up procmon.exe to capture all DeleteRegKey operations but failed because Chef keeps track of processes it runs and will not continue until the process is finished.

In the mean time customer has modified their Chef scripts to install individual msi installers, and reproduced the problem, hence removing Suite installer out of the equation.

windows_package 'Prerequisite' do
 source 'Prerequisite.msi'
 installer_type :custom
 options '/qn ACCEPT_EULA=1'
end
windows_package 'APP' do
 source 'App.msi'
 installer_type :custom
 options '/qn ACCEPT_EULA=1'
end

Customer sent log files for failed and successful installations but comparison did not really bring any useful information. One thing we noticed, however. The installer log did not include all of the debugging information, so we asked the customer to append /l*vx logfile.log options to get all the information we possibly could:

windows_package 'Prerequisite' do
 source 'Prerequisite.msi'
 installer_type :custom
 options '/qn ACCEPT_EULA=1 /l*vx c:\Prerequisite.log'
end
windows_package 'APP' do
 source 'App.msi'
 installer_type :custom
 options '/qn ACCEPT_EULA=1 /l*vx c:\APP.log'
end

This got us a little bit further:

MSI (s) (D0:C4) [20:29:06:113]: Note: 1: 1935 2: {6F6751F2-43FB-4C77-9791-B24EB154D406} 3: 0x800703FA 4: IAssemblyCacheItem 5: Commit 6: Company.Systems.Services,processorArchitecture=”amd64″,publicKeyToken=”45d8b3bf5a7dd114″,type=”win32″,version=”1.0.0.73″
MSI (s) (D0:C4) [20:29:06:113]: Assembly Error (sxs): Please look into Component Based Servicing Log located at %windir%\logs\cbs\cbs.log to get more diagnostic information.

So after another 24 hour round trip due to time difference we got hold of the %windir%\logs\cbs\cbs.log file which had quite interesting things in it:

2017-03-07 20:34:24, Info                  CBS    Trusted Installer is shutting down because: SHUTDOWN_REASON_AUTOSTOP

2017-03-07 20:34:24, Info                  CBS    TiWorker signaled for shutdown, going to exit.

2017-03-07 20:34:24, Info                  CBS    Ending the TiWorker main loop.

2017-03-07 20:34:24, Info                  CBS    Ending the TrustedInstaller main loop.

2017-03-07 20:34:24, Info                  CBS    Starting TiWorker finalization.

2017-03-07 20:34:24, Info                  CBS    Starting TrustedInstaller finalization.

2017-03-07 20:34:24, Info                  CBS    Ending TrustedInstaller finalization.

2017-03-07 20:34:56, Info                  CBS    TI: — Initializing Trusted Installer —

2017-03-07 20:34:56, Info                  CBS    TI: Last boot time: 2017-03-07 20:10:19.488

2017-03-07 20:34:56, Info                  CBS    Starting TrustedInstaller initialization.

2017-03-07 20:34:56, Info                  CBS    Ending TrustedInstaller initialization.

2017-03-07 20:34:56, Info                  CBS    Starting the TrustedInstaller main loop.

2017-03-07 20:34:56, Info                  CBS    TrustedInstaller service starts successfully.

2017-03-07 20:34:56, Info                  CBS    No startup processing required, TrustedInstaller service was not set as autostart

2017-03-07 20:34:56, Info                  CBS    Startup processing thread terminated normally

2017-03-07 20:34:56, Info                  CBS    Starting TiWorker initialization.

2017-03-07 20:34:56, Info                  CBS    Ending TiWorker initialization.

2017-03-07 20:34:56, Info                  CBS    Starting the TiWorker main loop.

2017-03-07 20:34:56, Info                  CBS    TiWorker starts successfully.

2017-03-07 20:34:56, Info                  CBS    TiWorker: Client requests SxS store object.

2017-03-07 20:34:56, Info                  CBS    Universal Time is: 2017-03-07 20:34:56.619

2017-03-07 20:34:56, Info                  CBS    Loaded Servicing Stack v6.3.9600.18384 with Core: C:\Windows\winsxs\amd64_microsoft-windows-servicingstack_31bf3856ad364e35_6.3.9600.18384_none_fa1d93c39b41b41a\cbscore.dll

2017-03-07 20:34:56, Info                  CSI    00000001@2017/3/7:20:34:56.621 WcpInitialize (wcp.dll version 0.0.0.6) called (stack @0x7ffe61937fa9 @0x7ffe62624924 @0x7ffe6262415b @0x7ff7d6e3d69a @0x7ff7d6e3e1f8 @0x7ffe743420f3)

2017-03-07 20:34:56, Info                  CBS    Could not load SrClient DLL from path: SrClient.dll.  Continuing without system restore points.

2017-03-07 20:34:56, Info                  CBS    SQM: Initializing online with Windows opt-in: False

2017-03-07 20:34:56, Info                  CBS    SQM: Cleaning up report files older than 10 days.

2017-03-07 20:34:56, Info                  CBS    SQM: Requesting upload of all unsent reports.

2017-03-07 20:34:56, Info                  CBS    SQM: Failed to start upload with file pattern: C:\Windows\servicing\sqm\*_std.sqm, flags: 0x2 [HRESULT = 0x80004005 – E_FAIL]

2017-03-07 20:34:56, Info                  CBS    SQM: Failed to start standard sample upload. [HRESULT = 0x80004005 – E_FAIL]

2017-03-07 20:34:56, Info                  CBS    SQM: Queued 0 file(s) for upload with pattern: C:\Windows\servicing\sqm\*_all.sqm, flags: 0x6

2017-03-07 20:34:56, Info                  CBS    SQM: Warning: Failed to upload all unsent reports. [HRESULT = 0x80004005 – E_FAIL]

2017-03-07 20:34:56, Info                  CBS    NonStart: Set pending store consistency check.

2017-03-07 20:34:58, Info                  CBS    Failed to open the registry root: n/a, key: COMPONENTS. [HRESULT = 0x800703fa – ERROR_KEY_DELETED]

2017-03-07 20:34:58, Info                  CBS    Failed loading COMPONENTS hive with ERROR_SHARING_VIOLATION, retry #1

(…)

2017-03-07 20:35:08, Info                  CBS    Failed to load the COMPONENTS hive from ‘C:\Windows\System32\config\COMPONENTS’ into registry key ‘HKLM\COMPONENTS’. [HRESULT = 0x80070020 – ERROR_SHARING_VIOLATION]

2017-03-07 20:35:08, Info                  CBS    Failed to load component store [HRESULT = 0x80070020 – ERROR_SHARING_VIOLATION]

2017-03-07 20:35:08, Error                 CSI    00000002 (F) c0000425 [Error,Facility=(system),Code=1061 (0x0425)] #11# from Windows::Rtl::SystemImplementation::DirectRegistryProvider::SysOpenKey(flg = (AllowKeyNotFound), key = {provider=NULL, handle=0, name= (“null”)}, da = (KEY_READ|KEY_WOW64_64KEY), oa = @0x2c3dc1d7a0->OBJECT_ATTRIBUTES {s:48; rd:NULL; on:[28]”\Registry\Machine\COMPONENTS”; a:(OBJ_CASE_INSENSITIVE)}, disp = Unmapped disposition: 1036114208 (0x3dc1d920))[gle=0xd0000425]

2017-03-07 20:35:09, Error                 CSI    00000003@2017/3/7:20:35:09.270 (F) base\wcp\sil\merged\ntu\ntsystem.cpp(3813): Error c0000425 [Error,Facility=(system),Code=1061 (0x0425)] originated in function Windows::Rtl::SystemImplementation::DirectRegistryProvider::SysOpenKey expression: (null)

[gle=0x80004005]

2017-03-07 20:35:17, Info                  CBS    Added C:\Windows\Logs\CBS\CBS.log to WER report.

2017-03-07 20:35:17, Info                  CBS    Could not get active session for current session file logging [HRESULT = 0x80004003 – E_POINTER]

2017-03-07 20:35:18, Info                  CBS    Not able to add pending.xml to Windows Error Report. [HRESULT = 0x80070002 – ERROR_FILE_NOT_FOUND]

2017-03-07 20:35:18, Info                  CBS    Not able to add pending.xml.bad to Windows Error Report. [HRESULT = 0x80070002 – ERROR_FILE_NOT_FOUND]

2017-03-07 20:35:18, Info                  CBS    Not able to add SCM.EVM to Windows Error Report. [HRESULT = 0x80070002 – ERROR_FILE_NOT_FOUND]

2017-03-07 20:35:19, Info                  CBS    Failed to open regkey configuration. [HRESULT = 0x800703fa – ERROR_KEY_DELETED]

2017-03-07 20:35:19, Info                  CBS    Failed to query Consent Key. [HRESULT = 0x800703fa – ERROR_KEY_DELETED]

2017-03-07 20:35:19, Error                 CSI    00000004 (F) c0000425 [Error,Facility=(system),Code=1061 (0x0425)] #10# from Windows::Rtl::SystemImplementation::CSystemIsolationLayer_IRtlSystemIsolationLayerTearoff::OpenRegistryKey(flags = (KeyNotFoundIsOk), da = (KEY_READ), kn = [ml:58{29},l:56{28}]”\Registry\Machine\COMPONENTS”, key = NULL, disp = Invalid)[gle=0xd0000425]

2017-03-07 20:35:44, Info                  CBS    Ending TiWorker finalization.

Voila!!! We see here some kind of race condition between two TiWorker processes. Second TiWorker  starts initialization before the first one finishes finalization. Looks like a bug in Microsoft Windows Module Installer. 

To buy us some time we decided to add waits before every msi installation using SysInternal’s pslist:

execute "Wait until TiWorker is gone" do
 command "c:/Sysinternals/pslist /accepteula TiWorker"
 retries 1000
 returns 1
 retry_delay 10
 timeout 10
end

This had hope of success because TrustedInstaller.exe launches TiWorker.exe process at some point during installation but its execution can outlive the installation itself.

Customer no longer saw failures but we still needed to get Suite installer working and we could not just add waits there. Further, we observed that the Suite installer was designed in a way that installs various msis in multiple transactions. First thing we did was to wrap all the installations in single transaction. But this resulted in the unexpected: when one of the installers was executed it reported that there is installation already in progress and it cannot continue! We have just configured it to run in a single transaction, so what is going on?

As it turned out some of the installers were 32 bit (as we could say by looking at Summary filed of msi in Installshield) and some of them were 64 bit. Even though internally Installshield always creates 32 bit installers this mix resulted in spawning two concurrently running installations, one for 32 bit and one for 64 bit. How strange?!

Changing the offending msis to 64 bit (by changing Summary field to AMD64) caused it to not report another installation in progress any more and as it turned out, also resolved the original HRESULT: 0x800703FA problem.