Software Deployment

There's no way anyone can really know what's going on here. You need to run your favoured process/file/registry monitor to see what the machine is trying to do. My guess would be that a dialog is being invisibly presented, waiting for a user to click 'OK' or 'Yes' or whatever.

Thanks a lot for your reply VBScab.

I have actually tried procmon, regmon and filemon. I have not noticed anything unusual, but then again I may be looking for the wrong things.

One thing I have noticed though:

I turned on full installer logging in the registry, so that a log file is ceated in %Temp% for every .msi package installed.

There was a log file for the main package and each of the chained package. When the installation succeeded (it didn't hang) there was also a log file which had the following content:

=== Verbose logging started: 11/11/2008 13:32:03 Build type: SHIP UNICODE 4.05.6001.00 Calling process: C:\WINDOWS\Installer\MSIE.tmp ===
MSI (c) (C4:80) [13:32:26:109]: Cloaking enabled.
MSI (c) (C4:80) [13:32:26:109]: Attempting to enable all disabled privileges before calling Install on Server
=== Verbose logging stopped: 11/11/2008 13:32:26 ===

The last entry in the log file for the last chained package has a time of 13:32:26:093

In the log file for the main package there are the following two lines:

MSI (s) (B0:E0) [13:30:00:078]: MainEngineThread is returning 0
MSI (c) (B0:B8) [13:32:26:125]: Back from server. Return value: 0

So it seems obvious looking at the times that after the last chained package is installed, something happens which creates the first log file (the one with Cloaking Enabled as the first line). After this process is complete, the log file for the main package reports "Back from server" and everything proceeds as normal.

Now here is the interesting bit. When the installation hangs, there appears a log file which is completely empty (the equivalent of the "Cloaking Enabled log file). The last line in the log file for the main package is:

MSI (s) (5C:F0) [08:28:15:078]: MainEngineThread is returning 0

So, for some reason, the process which creates the "Cloaking Enabled" log file hangs, and this means that the "Back from server" line never appears in the log file for the main package.

Also, when the installation process hangs up, there is a process MSIE.tmp in the task manager. If this process is killed the installation completes (the window with Finish on appears) so I assume that this is the process which is hung.

Does anyone have any idea what is going on here? What is the process which creates the "Cloaking Enabled" log file and what do the two lines in this file mean?

Some explanation...

Cloaking is a COM security capability. See MSDN for a full explanation: it's far too involved to go into here. In WI context, though, it's connected with the hand-over from the MSIExec instance which is running as the 'client' and the associated process which runs as the 'server'. Server entries in the log appear with the prefix 'MSI (s)', like this:

MSI (s) (B0:E0) [13:30:00:078]: MainEngineThread is returning 0

Client entries in the log appear like this:
MSI (c) (B0:B8) [13:32:26:125]: Back from server. Return value: 0

The hand-over occurs when the WI engine has finished 'compiling' its internal script (from instructions in the ExecuteImmediate sequence) and passes it to ExecuteDeferred for execution.

OK, that's that. Now, onwards...

You say that the install hangs if run from a network drive: does it run to completion if you copy the package locally and run it from the local drive?

The package seems to install fine from a local drive. However, even from a network drive the problem is intermittent, so it's kind of hard to pin down.

Do you have an idea which process creates the short log file I mentioned in my last post? And why it would hang? (If I am indeed analysing the situation correctly).

Thanks

The process would still be MSIExec.EXE, Phil! :) You're going to have to return to ProcMon, I think. When the install hangs, you should see ProcMon continually updating with - most likely - attempts to open a file or folder.

The reason I asked about the network drive versus local drive is that, if there's a Custom Action in one of the MSIs which is set to execute in System context against a file that turns out to be network-hosted, that'll never work, as System has no knowledge of any network, much less any access to it.

Just tried to execute it from the desktop and it hung up, so it is not specific to installing from a network drive.

The process was listed as MSIE.tmp in the task manager. It is sometimes called msi7.tmp so I guess there are just random characters stuck on the end. I don't know if this is significant or if this is actually msiexec renamed to something else. I don't see why this is necessary when there are several processes listed as msiexec.exe in the task manager, but then Windows Installer is not my area of expertise (though I'm learning fast just now!).

There is honestly nothing coming out of procmon, the only process which is doing anything is lsass.exe. I only fire it up after the process hangs however, maybe I should start to fire it up during the install process. I still think the key to fixing this is undertstanding what is happening when the small log file I created earlier is created.

Start ProcMon for a brief period so that you get a list of the regular processes, stuff like lsass.exe, svchost.exe, explorer.exe, your a/v process and so on. Stop the capture. Right-click each of the processes and exclude them so that they don't get in your way and make the output unwieldy. This is the step I think you missed: when you have thousands of entries for processes you don't care about, it's easy to miss stuff. Click the 'Registry' and 'Thread' filter buttons, too.

Start the install and when it looks like the offending install is starting, re-start the capture.

Frankly, if this was me, I'd have extracted the MSIs and run them separately to find the rogue one, then built my own stub, having fixed whatever's causing the hang. As it is now, it's pretty much 'needle-in-haystack' time.

I can install the three separate .msis which make up the chained packages independently. None of them hang.

In fact, when the installation hangs the three chained packages have already been installed. The log files for each of these MSIs say "Installation operation completed successfully".

The problem occurs somehere between these chained packages being installed and the final installation screen for the main package appearing.

I still cannot see anything obvious in procmon.

|I may be barking up the entirely wrong tree here, but the only clue I have is the log file which is created (in a succesful installation, not in failed installation) after the chained packages are installed and before the "Back from server: line is seen in the main log file.:

=== Verbose logging started: 11/11/2008 13:32:03 Build type: SHIP UNICODE 4.05.6001.00 Calling process: C:\WINDOWS\Installer\MSIE.tmp ===
MSI (c) (C4:80) [13:32:26:109]: Cloaking enabled.
MSI (c) (C4:80) [13:32:26:109]: Attempting to enable all disabled privileges before calling Install on Server
=== Verbose logging stopped: 11/11/2008 13:32:26 ===

All of the other log files refer to a specific msi. Why does this one not? Is that normal?