[wix-users] 1601 errors followed by 1618

[Jacques Eloff]

I did some more digging and it seems like a number of failures or some
domino effect.

1. Nested bundle executes an MSI and gets 1601. The bundle retries the MSI
and reports an exit code of 0 (At this point 3 or 4 other MSIs have been
executed and uninstalled before encountering the error)
2. The bundle reports error messages about the named pipe, but still
terminates with 0
3. The outer bundle continues uninstalling the next package. Turns out at
this point, the MSI that was retried is actually still running and stuck in
a fight with Restart Manager - this takes around 2 minutes based on logs.
Either MsiReinstallProduct returned 0 incorrectly, or whatever caused the
installer service to return 1601 maybe messed with the named pipes and the
client thought it got a response, but never did.

I can only post excerpts of the logs:

[52480:23AF4][2021-08-10T06:24:34]e000: Error 0x80070641: Failed to
configure per-machine MSI package.
[52480:23AF4][2021-08-10T06:24:34]w348: Application requested retry of
package: xxxxxxxxx encountered error: 0x80070641. Retrying...
[18C64:54AC0][2021-08-10T06:24:37]i301: Applying execute package: xxxxxxxxxx
[52480:23AF4][2021-08-10T06:25:44]i319: Applied execute package: xxxxxxxx,
result: 0x0, restart: None
[52480:23AF4][2021-08-10T06:25:44]e000: Error 0x800700e8: Failed to write
message type to pipe.
[52480:23AF4][2021-08-10T06:25:44]e000: Error 0x800700e8: Failed to write
send message to pipe.
[52480:23AF4][2021-08-10T06:25:44]e000: Error 0x800700e8: Failed to send
BURN_ELEVATION_MESSAGE_TYPE_CLEAN_PACKAGE message to per-machine process.
.. about 10 more similar pipe errors
[52480:23AF4][2021-08-10T06:25:44]i399: Apply complete, result: 0x0,
restart: None, ba requested restart:  No
[52480:23AF4][2021-08-10T06:25:44]i500: Shutting down, exit code: 0x0

There's no details in the event logs that I've been able to find other than
that the service falls over, plans to restart two minutes later, then
something else restarts it within 30 seconds and then it tries a restart
and fails again.

| Error       | 8/4/2021 4:38:22 AM | Service Control Manager    |     7032
| The Service Control Manager tried to take a corrective action (Restart
the service) after the unexpected termination of the Windows Installer
service, but this action failed with the following error: \r\nAn instance
of the service is already running. |
| Information | 8/4/2021 4:36:56 AM | Service Control Manager    |     7036
| The Windows Installer service entered the running state.


| Error       | 8/4/2021 4:36:22 AM | Service Control Manager    |     7031
| The Windows Installer service terminated unexpectedly.  It has done this
1 time(s).  The following corrective action will be taken in 120000
milliseconds: Restart the service.
                                  |

>From the MSI log, the one that reported success on attempt nr. 2, Notice
the timestamp of 6.27 vs the bundle reporting success at 6:25.

MSI (s) (44:E4) [06:26:34:323]: Running as a service.
MSI (s) (44:80) [06:27:21:019]: RESTART MANAGER: Failed to shut down all
applications in the service's session. Error: 351

Is there any way to tell whether the elevated copy of Burn died or turned
into a zombie process? The [18C64:xxx] in the log, that's the process ID. I
seem to remember something about the log using process:thread IDs

Thanks,
Jacques

On Wed, Aug 4, 2021 at 11:09 PM Jacques Eloff <repstosd at gmail.com> wrote:

> Hi
>
> I'm looking into an odd failure and curious if anyone has come across it
> before.
>
> 1. Nested bundles are executing.
> 2. First bundle runs fine, then triggers uninstall (upgrade related
> bundle).
> 3. Second bundle executes a number of MSIs and the 3rd MSI fails with
> 1601, but then succeeds on retry.
> 4. Next bundle executes, but then all the MSIs return 1618.
>
> Based on the event logs, there were no other installs running - I also
> checked CBS/Windows Update logs. My working theory is that whatever caused
> the installer services to wobble, failed to release the MSI global mutex,
> causing subsequent installs to think there are other installs in progress
> when there weren't.
>
> Has anyone seen this behavior before? The worrying part is that it repro's
> consistently on some machines, but they're all using the same OS image.
> There's nothing odd about the MSIs, we're talking file copying and registry
> keys, nothing complicated. I've also compared some of the policy settings
> in the registry around the installer service and everything matches.
>
> Shortly after the service failure, the bundle reported having issues
> sending some requests over the named pipe to the elevated engine, but the
> pipe is never reported as being closed or broken. I'm not sure the two
> issues are related. The bundle appears to shut down normally.
>
> I know Burn implemented returning 1618, but that code was turned off
> because of nested bundles and hasn't been turned on in 3.x AFAIK.
>
> From what I could tell, the retry mechanism overwrote the log of the first
> attempt when 1601 was encountered.
>
> Thanks,
> Jacques
>