Upgrading a product that includes an event manifest registered by UtilExtension fails

[BdN3504]

Bug

This issue is a bug:

• Which version of WiX are you building with?
  3.11.1701.0

• Which version of Visual Studio are you building with (if any)?
  Microsoft Visual Studio Professional 2017 Version 15.4.1 VisualStudio.15.Release/15.4.1+27004.2005

• Which version of the WiX Toolset Visual Studio Extension are you building with (if any)?
  0.9.21.62588

• Which version of .NET are you building with?
  4.6.2

• If the problem occurs when installing your packages built with WiX, what is the version of Windows the package is running on?
  Windows 10 (VersionNT 603, with Fall Creators Update)

• Describe the problem and the steps to reproduce it.
  Installing a new version of the product removes the eventmanifest but does not install the newer version.

• Steps to reproduce:
  Create a product that is versioned as 1.0.0.0. Include a component that installs and registers an event manifest file using the UtilExtension:

<Fragment>
  <ComponentGroup Directory="ProgramdataVersion" Id="EventlogProviderFiles">
    <Component Id="CMP_etwManifest.dll" Guid="PUTYOURGUIDHERE">
      <File Id="etwManifest.dll" Assembly=".net" AssemblyApplication="etwManifest.dll" AssemblyManifest="etwManifest.dll" Source="$(var.Common.TargetDir)etwManifest.man" KeyPath="yes" />
    </Component>
    <Component Id="CMP_etwManifest.man" Guid="PUTYOURGUIDHERE">
      <File Id="etwManifest.man" KeyPath="yes" Source="$(var.Common.TargetDir)etwManifest.man">
        <util:EventManifest MessageFile="[#etwManifest.dll]" ResourceFile="[#etwManifest.dll]"/>
      </File>
    </Component>
  </ComponentGroup>
</Fragment>

Compile and install this product. Next Modify the EventManifest, increase the version number of the product to 1.0.1.0 to trigger an update and recompile.
In the installer log you will notice that the custom actions used to register and unregister event manifest are executed in the following order:

MSI (s) (84:1C) [15:48:51:767]: Doing action: ConfigureEventManifestUnregister
MSI (s) (84:88) [15:48:51:767]: Invoking remote custom action. DLL: C:\WINDOWS\Installer\MSI2551.tmp, Entrypoint: ConfigureEventManifestUnregister
MSI (s) (84:1C) [15:48:54:299]: Doing action: ConfigureEventManifestRegister
MSI (s) (84:B8) [15:48:54:299]: Invoking remote custom action. DLL: C:\WINDOWS\Installer\MSI2F3D.tmp, Entrypoint: ConfigureEventManifestRegister
MSI (s) (84!1C) [15:48:54:346]: PROPERTY CHANGE: Adding RollbackRegisterEventManifest property. Its value is '"wevtutil.exe" um "C:\ProgramData\NewVersion\etwManifest.man"'.
MSI (s) (84!1C) [15:48:54:346]: Doing action: RollbackRegisterEventManifest
MSI (s) (84!1C) [15:48:54:346]: PROPERTY CHANGE: Adding RegisterEventManifest property. Its value is '"wevtutil.exe" im "C:\ProgramData\NewVersion\etwManifest.man"'.
MSI (s) (84!1C) [15:48:54:346]: Doing action: RegisterEventManifest
MSI (s) (84:B0) [15:49:08:283]: Doing action: ConfigureEventManifestUnregister
MSI (s) (84:AC) [15:49:08:283]: Invoking remote custom action. DLL: C:\WINDOWS\Installer\MSI65EC.tmp, Entrypoint: ConfigureEventManifestUnregister
MSI (s) (84!20) [15:49:08:283]: PROPERTY CHANGE: Adding RollbackUnregisterEventManifest property. Its value is '"wevtutil.exe" im "C:\ProgramData\OldVersion\etwManifest.man"'.
MSI (s) (84!20) [15:49:08:283]: Doing action: RollbackUnregisterEventManifest
MSI (s) (84!20) [15:49:08:283]: PROPERTY CHANGE: Adding UnregisterEventManifest property. Its value is '"wevtutil.exe" um "C:\ProgramData\OldVersion\etwManifest.man"'.
MSI (s) (84!20) [15:49:08:298]: Doing action: UnregisterEventManifest
MSI (s) (84:B0) [15:49:08:830]: Doing action: ConfigureEventManifestRegister
MSI (s) (84:C4) [15:49:08:830]: Invoking remote custom action. DLL: C:\WINDOWS\Installer\MSI6816.tmp, Entrypoint: ConfigureEventManifestRegister

So it seems that the Custom Action is registering the new event manifest before it unregisters the old one. I think this is the root of the problem, but I am not sure. I checked the InstallExecuteSequence Table, but in there the ConfigureEventManifestRegister is correctly sequenced after ConfigureEventManifestUnregister. I tried Sequencing RegisterEventManifest after UnregisterEventManifest manually, but that failed.

• Describe the behavior you expected and how it differed from the actual behavior.
  After doing a major upgrade on a product that installed and registered an event manifest, I expect the upgraded event manifest to be registered properly. The actual behaviour is that the old event manifest is unregistered and the new one is not registered at all.

[barnson]

Please attach a complete verbose log.

[BMurri]

I suspect an issue related to the scheduling of RemoveExistingProducts. A complete verbose log would identity that. Was this discussed in wix-users?

[barnson]

We need more data to do anything with this issue.

[barnson]

Without data, not much we can do.

[mattpwhite]

I believe I'm seeing the same thing. I have attached a verbose log.
redacted-log.txt

[barnson]

@mattpwhite that log shows the removal but not the install. It looks truncated.

[mattpwhite]

The log is taken from the point at which my installer fails. I had to add a custom action to configure the log with wevtutil sl because those options don't seem to be available with EventManifest. That custom action was sequenced with something like:

<Custom Action="SetEventLogConfig" After="RegisterEventManifest">$(var.OnInstallOrUpgradeCondition)</Custom>

I think it was after "RegisterEventManifest", it was whatever looked like the right stage when I looked at the msi in orca. That worked fine on initial install - the manifest was registered by the time the custom action to do wevtutil sl ran. On an upgrade, it doesn't work because when that custom action to do wevtutil sl runs, the manifest is not registered, so it can't configure a log that doesn't exist. This appears to be due to this section from my log:

MSI (s) (C4!1C) [19:32:07:206]: PROPERTY CHANGE: Adding RollbackUnregisterEventManifest property. Its value is '"wevtutil.exe" im "C:\Program Files\Redacted\Redacted.etwManifest.man"'. MSI (s) (C4!1C) [19:32:07:206]: Doing action: RollbackUnregisterEventManifest Action 19:32:07: RollbackUnregisterEventManifest. Action start 19:32:07: RollbackUnregisterEventManifest. RollbackUnregisterEventManifest: Action ended 19:32:07: RollbackUnregisterEventManifest. Return value 1. MSI (s) (C4!1C) [19:32:07:206]: PROPERTY CHANGE: Adding UnregisterEventManifest property. Its value is '"wevtutil.exe" um "C:\Program Files\Redacted\Redacted.etwManifest.man"'. MSI (s) (C4!1C) [19:32:07:206]: Doing action: UnregisterEventManifest Action 19:32:07: UnregisterEventManifest. Action start 19:32:07: UnregisterEventManifest. UnregisterEventManifest: Action ended 19:32:07: UnregisterEventManifest. Return value 1. Action ended 19:32:07: ConfigureEventManifestUnregister. Return value 1.

So, at the start of the upgrade it re-registers the manifest (without providing the /rf or /mf switches, despite those attributes being specified in my EventManifest element, a separate issue), then unregisters it. Nowhere between that point and "after" the InstallEventManifest stage does it actually re-install the manifest.

Because of the problem with sequencing on upgrades and the fact that wevtutil im doesn't seem to actually use the specified resource file or message file, I ended up just creating my own custom actions. I am not very good with WiX, but these excerpts from my wxs seem to work,

`

...

 <InstallExecuteSequence>
 ...
  <Custom Action="InstallEventManifest" After="InstallFiles">$(var.OnInstallOrUpgradeCondition)</Custom>
  <Custom Action="SetEventLogConfig" After="InstallEventManifest">$(var.OnInstallOrUpgradeCondition)</Custom>
  <Custom Action="UninstallEventManifest" After="InstallInitialize">$(var.OnUpgradeOrUninstallCondition)</Custom>
</InstallExecuteSequence>

`