[wix-users] Files Held In Use Are Deleted After Reboot

[Edwin Castro]

This is a Windows Installer question. I'm hoping the experts here can help
guide me. Is there a better place I should ask this question?

I am troubleshooting a verbose log for a major upgrade started with
REBOOT=ReallySuppress. RemoveExistingProducts is scheduled immediately
after InstallInitialize. A number of files are identified as held in use
during InstallValidate but are typically no longer in use when they are
removed/copied. However, I see two files that cannot be deleted during
uninstall and are scheduled to be deleted at reboot. Later it appears the
files are successfully copied to their target locations during the install
of the new version. Later, the machine is rebooted and the files are
deleted during reboot causing the application to break.

Below I have verbose log snippets showing this behavior. Names have been
changed below to protect the innocent/guilty.

-------------------
File #1

RemoveDuplicateFiles attempts to delete one file and it appears it tried to
move the file to C:\Config.Msi but perhaps failed to do so and as a result
it just schedules the original file to be deleted at reboot.

MSI (s) (34:18) [01:26:47:634]: Executing op:
SetTargetFolder(Folder=C:\Program Files\Company\Product\x86\)
MSI (s) (34:18) [01:26:47:634]: Executing op:
FileRemove(,FileName=component1.dll,,)
MSI (s) (34:18) [01:26:47:634]: Verifying accessibility of file:
component1.dll
MSI (s) (34:18) [01:26:47:634]: Verifying accessibility of file:
component1.dll
MSI (s) (34:18) [01:26:47:634]: Using source file security for destination.
MSI (s) (34:18) [01:26:47:634]: Note: 1: 2318 2: C:\Config.Msi\85833f1a.rbf
MSI (s) (34:18) [01:26:47:634]: Note: 1: 2329 2: 32 3: C:\Program
Files\Company\Product\x86\component1.dll
MSI (s) (34:18) [01:26:47:634]: Verifying accessibility of file:
component1.dll
MSI (s) (34:18) [01:26:47:634]: Note: 1: 2318 2:
MSI (s) (34:18) [01:26:47:634]: Note: 1: 2318 2:
...
Info 1903.Scheduling reboot operation: Deleting file C:\Program
Files\Company\Product\x86\component1.dll. Must reboot to complete operation.

Normally, I expect for the *.rbf file to be created in C:\Config.Msi\ and
deleted at reboot. But it seems like this didn't happen in this case.
Instead it seems the file was still in place when the new file was copied.
There is no indication if the file was moved and there is no indication
that the file on disk was actually overwritten.

MSI (s) (34:64) [01:26:57:384]: Executing op:
SetSourceFolder(Folder=C:\Program Files\Company\Product\x86\)
MSI (s) (34:64) [01:26:57:384]: Executing op:
SetTargetFolder(Folder=C:\Program Files\Company\Product\x86\)
MSI (s) (34:64) [01:26:57:384]: Executing op:
FileCopy(SourceName=component1.bin,,DestName=component1.dll,Attributes=16384,FileSize=779008,PerTick=0,IsCompressed=0,VerifyMedia=0,,,,,CheckCRC=0,Version=65535.0.0.0,Language=1033,InstallMode=262144,,,,,,,)
MSI (s) (34:64) [01:26:57:384]: File: C:\Program
Files\Company\Product\x86\component1.dll; Overwrite; Won't patch; Existing
file is a lower version
MSI (s) (34:64) [01:26:57:384]: Source for file 'component1.bin' is
uncompressed, at 'C:\Program Files\Company\Product\x86\'.
MSI (s) (34:64) [01:26:57:384]: Re-applying security from existing file.
MSI (s) (34:64) [01:27:01:072]: Product: Product Name. The file C:\Program
Files\Company\Product\x86\component1.dll is being used by the following
process: Name: proc , Id 1128.
...
MSI (s) (34:64) [01:27:01:072]: Verifying accessibility of file:
component1.dll
MSI (s) (34:64) [01:27:01:088]: Note: 1: 2318 2:
MSI (s) (34:64) [01:27:01:088]: Note: 1: 2318 2:
MSI (s) (34:64) [01:27:01:088]: Note: 1: 2318 2: C:\Program
Files\Company\Product\x86\component1.dll
MSI (s) (34:64) [01:27:01:088]: File will have security applied from OpCode.
Info 1603.The file C:\Program Files\Company\Product\x86\component1.dll is
being held in use.  Close that application and retry.

I suppose I can infer that it was able to move the file because error 2318
tells me C:\Program Files\Company\Product\x86\component1.dll does not exist
and presumably it is able to copy the file.

-------------------
File #2

We see very similar behavior with this second file. The *.rbf files does
not exist and the original seems to be scheduled to be deleted at reboot.

MSI (s) (34:18) [01:26:47:884]: Executing op:
FileRemove(,FileName=component2.dll,,ComponentId={GUID})
MSI (s) (34:18) [01:26:47:884]: Verifying accessibility of file:
component2.dll
MSI (s) (34:18) [01:26:47:884]: Verifying accessibility of file:
component2.dll
MSI (s) (34:18) [01:26:47:884]: Using source file security for destination.
MSI (s) (34:18) [01:26:47:884]: Note: 1: 2318 2: C:\Config.Msi\85833f4f.rbf
MSI (s) (34:18) [01:26:47:900]: Note: 1: 2329 2: 32 3: C:\Program
Files\Company\Product\x86\component2.dll
MSI (s) (34:18) [01:26:47:900]: Verifying accessibility of file:
component2.dll
MSI (s) (34:18) [01:26:47:900]: Note: 1: 2318 2:
MSI (s) (34:18) [01:26:47:900]: Note: 1: 2318 2:
...
Info 1903.Scheduling reboot operation: Deleting file C:\Program
Files\Company\Product\x86\componen2.dll. Must reboot to complete operation.

It is unclear if the original file was still held in use when the new
version was installed.

MSI (s) (34:64) [01:26:56:994]: Executing op:
RegisterSharedComponentProvider(,,File=component2.dll,Component={GUID},ComponentVersion=65535.0.0.0,ProductCode={GUID},ProductVersion=v.v.vvv,PatchSize=0,PatchAttributes=0,PatchSequence=0,SharedComponent=0,IsFullFile=0)
MSI (s) (34:64) [01:26:56:994]: Executing op:
FileCopy(SourceName=component2.dll,SourceCabKey=component2.dll,DestName=component2.dll,Attributes=16384,FileSize=427232,PerTick=65536,,VerifyMedia=1,,,,,CheckCRC=0,Version=65535.0.0.0,Language=1033,InstallMode=58982400,,,,,,,)
MSI (s) (34:64) [01:26:56:994]: File: C:\Program
Files\Company\Product\x86\component2.dll; Overwrite; Won't patch; Existing
file is a lower version
MSI (s) (34:64) [01:26:56:994]: Source for file 'component2.dll' is
compressed
MSI (s) (34:64) [01:26:56:994]: Re-applying security from existing file.
MSI (s) (34:64) [01:26:56:994]: Verifying accessibility of file:
component2.dll
MSI (s) (34:64) [01:26:56:994]: Note: 1: 2318 2:
MSI (s) (34:64) [01:26:56:994]: Note: 1: 2318 2:

-------------------

I still need to identify what had these files held in use *but* it seems
the expected behavior of move/delete on reboot didn't occur successfully
causing problems after reboot.

Has anybody seen this kind of behavior previously? Any ideas on what might
cause the move to fail?

Ideally I would get a ProcMon trace when this happens so that I can have a
better idea of what is actually going on but this doesn't reproduce
consistently so it is hard to have everything capturing and ready to go.
I'm hoping for ideas that might help me generate hypotheses to investigate
and test.

--
Edwin G. Castro