Obscure messages in MSI logs

[datamine]

We are encountering some strange behaviour with Prerequisites, where exactly the same project produces 2 different behaviours depending on which set of components are being included. I have compared the 2 logs and can only find these differences, but I have not been able to find out what they mean so I have been unable to explain the different behaviours:

Log 1:
InstallShield 15:01:02: Invoking script function ReinstallFeatures
MSI (c) (2C!20) [15:01:05:990]: Note: 1: 2727 2:
MSI (c) (2C!20) [15:01:05:990]: Note: 1: 2727 2:
MSI (c) (2C!20) [15:01:05:990]: Note: 1: 2727 2:
InstallShield 15:01:05: CallScriptFunctionFromMsiCA() ends

Which results in the following message a little further down:
InstallShield 15:01:06: No features with associated prerequisites are being installed or advertised. Skipping prerequisites.

Whereas the equivalent lines from Log 2 are as follows:
InstallShield 14:47:36: Invoking script function ReinstallFeatures
InstallShield 14:47:36: CallScriptFunctionFromMsiCA() ends

and
InstallShield 14:47:36: Features with associated prerequisites are being installed or advertised. Finding setup.exe...

All the ReinstallFeatures script does is call MsiSetFeatureState for 3 feature names, setting them to INSTALLSTATE_LOCAL, which in previous tests has forced the prerequisites to run when repairing or performing a minor upgrade.

Can anyone shed any light on what these log messages mean, and thus why we're getting inconsistent behaviour?

Thanks in advance

Ian Johnson.

[MichaelU]

I assume you're primarily talking about the lines with "Note: 1: 2727 2:" in them. You can find out what these mean by consulting the Windows Installer Error Messages document from the SDK. As it turns out, 2727 means "The directory entry '[2]' does not exist in the Directory table." but I'm not sure why there would be an empty directory involved.

The prerequisites line merely reflects the intersection of installation states with the list of features with associated prerequisites, so should theoretically be derivable from other information in the log file.

[datamine]

Thanks Michael - I wondered if that number was an error number. The word "error" in there would make it a little clearer 😉

As these 3 lines are the only noticeable difference between the 2 logs, I'm assuming they are causing the prerequisites not to be installed. I'll continue investigating...

[MichaelU]

Yeah I totally understand what you mean. At the same time, while they're collectively called error messages, they're not always indicative of true errors. This is much like a build warning instead of a build error, and is sometimes even more innocuous.

I'd look for information on the features' install and action states; that's likely to be more relevant.

[datamine]

This is not strictly related to the original topic, but it concerns the same script. Under certain circumstances (which are not clear at this stage) we get this in the log file:

"MSI (c) (3C:BC) [09:04:11:532]: NOTE: custom action ReinstallFeatures.12F84FE2_A21B_44EB_B23A_2B00241D1B6E unexpectedly closed the hInstall handle (type MSIHANDLE) provided to it. The custom action should be fixed to not close that handle."

This is accompanied by literally hundreds of "Creating MSIHANDLE" and "Closing MSIHANDLE" messages sprinkled throughout the log. Eventually it seems Windows Installer gives up and crashes, causing a reboot. One of the things that has been suggested is that the Custom Action is in an invalid location in the sequence - are there any areas of the sequence that are preferable or should be avoided?

TIA

Ian.

[MichaelU]

It sounds like the ReinstallFeatures.___ action is slightly buggy, but that particular sort of bug is not too worrisome. An MSI will typically create and close lots of handles, so that's not worrisome either; in fact, I'd suggest leaving the x out of your log parameters because of all the noise it generates.

How do you figure Windows Installer is crashing--do you come across an odd time gap in the log, followed by a reinitialization?

[datamine]

No, we invariably get an unscheduled reboot (and some people have lost work because if this), and often a truncated log. On one occasion the log ended with the following:
"MSI (c) (3C:10) [09:09:47:617]: Internal Exception during install operation: 0xc0000005 at 0x10078890."

I can't see that the ReinstallFeatures script can be buggy, as it simply consists of three calls to MsiSetFeatureState. This is why I asked if there are some areas of the sequence which are "no-go's" for InstallScript, in case I had sequenced it somewhere that might cause problems.

I wasn't aware that those MSIHANDLE lines were generated by the x parameter (which I've never used, but I see the default Create MSI Logs option does). Thanks for that 🙂

[joshstechnij]

If this is an InstallScript custom action, the unexpected closed handle message is a known issue that will be resolved in the next release of InstallShield. However, this has never caused any adverse behavior such as causing msiexec.exe to crash or anything else that would prevent the install from completing successfully, and is therefore a minor issue. Custom actions should not be able to crash the main msiexec.exe server process since all custom actions run in their own sandboxed process.

If you are seeing a crash (access violation), the action that is currently running should be determined from where the crash is at to at least isolate the cause of the behavior. Most likely, there is an issue with the MSI package itself that is causing this behavior. MSI validation should be run on the package to determine if it valid.

[datamine]

Ok, just as a resolution to this thread. My problem was that I was running InstallShield .exes as prerequisites, but those prerequisites were not set to handle reboots correctly. As they were running silently and I had not specified /norestart, they were performing an unexpected reboot. I'm not sure whether that may have effectively "pulled the rug" from under the parent installer and caused what appear to be Windows Installer crashes, but I've at least now corrected it so that any reboots are deferred till the end of the entire install.

Many thanks for your assistance in this!

Ian.