InstallValidate does not detect files in use

[Vadim Rapp]

Hello,

 

I have an installation that installs an ADE file, compiled Microsoft Access project. Version 1 is already installed on XP SP3 machine with Installer 4.5; and the file is opened in Access. New installation is supposed to upgrade the file (major upgrade; RemoveExistingProducts is in the very end, after InstallFinalize); against my expectations, InstallValidate does not show FilesInUse dialog, and in the log file (below) there's no indication of even an attempt to detect them. It's however successfully detected later by FileCopy, which then schedules the reboot.

 

What can be the reason for InstallValidate to not detect it?

 

regards

 

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

 

MSI (s) (EC:30) [15:00:36:774]: Doing action: InstallValidate
Action 15:00:36: InstallValidate. Validating install...
Action start 15:00:36: InstallValidate.
MSI (s) (EC:30) [15:00:36:774]: Feature: Complete; Installed: Absent;   Request: Local;   Action: Local
MSI (s) (EC:30) [15:00:36:774]: Component: PIMS.ade; Installed: Absent;   Request: Local;   Action: Local
MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262 2: BindImage 3: -2147287038
MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262 2: ProgId 3: -2147287038
MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262 2: PublishComponent 3: -2147287038
MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262 2: SelfReg 3: -2147287038
MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262 2: Extension 3: -2147287038
MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262 2: Font 3: -2147287038
MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262 2: Class 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: RemoveFile 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2205 2:  3: _RemoveFilePath
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: DuplicateFile 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: ReserveCost 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: PROPERTY CHANGE: Modifying CostingComplete property. Its current value is '0'. Its new value: '1'.
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: BindImage 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: ProgId 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: PublishComponent 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: SelfReg 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: Extension 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: Font 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: Class 3: -2147287038
MSI (s) (EC:30) [15:00:36:784]: PROPERTY CHANGE: Modifying PrimaryVolumeSpaceAvailable property. Its current value is '0'. Its new value: '17024824'.
MSI (s) (EC:30) [15:00:36:784]: PROPERTY CHANGE: Modifying PrimaryVolumeSpaceRequired property. Its current value is '0'. Its new value: '10520'.
MSI (s) (EC:30) [15:00:36:784]: PROPERTY CHANGE: Modifying PrimaryVolumeSpaceRemaining property. Its current value is '0'. Its new value: '17014304'.
MSI (s) (EC:30) [15:00:36:784]: PROPERTY CHANGE: Adding PrimaryVolumePath property. Its value is 'C:'.
Action ended 15:00:39: InstallValidate. Return value 1.

 

.....

 

MSI (s) (EC:30) [15:00:40:157]: Executing op: FileCopy(SourceName=PIMS.ade,SourceCabKey=PIMS.ade,DestName=PIMS.ade,Attributes=0,FileSize=4335104,PerTick=32768,,VerifyMedia=1,,,,,CheckCRC=0,,,InstallMode=58982400,HashOptions=0,HashPart1=1924052871,HashPart2=1553980841,HashPart3=1683386880,HashPart4=1526520394,,)
MSI (s) (EC:30) [15:00:40:157]: File: C:\Program Files\polyscience\PIMS.ade; Overwrite; Won't patch; Existing file is unversioned and unmodified - hash doesn't match source file
MSI (s) (EC:30) [15:00:40:157]: Source for file 'PIMS.ade' is compressed
InstallFiles: File: PIMS.ade
Directory: C:\Program Files\Polyscience\
Size: 4335104
MSI (s) (EC:30) [15:00:40:157]: Re-applying security from existing file.
Info 1603. The file C:\Program Files\Polyscience\PIMS.ade is being held in use.  Close that application and retry    <--------- (very useful here, isn't it :-)
MSI (s) (EC:30) [15:00:42:751]: Verifying accessibility of file: PIMS.ade
MSI (s) (EC:30) [15:00:42:751]: Verifying accessibility of file: PIMS.ade
MSI (s) (EC:30) [15:00:42:751]: Note: 1: 2318 2: C:\Config.Msi\10164.rbf
MSI (s) (EC:30) [15:00:42:751]: Using source file security for destination.
MSI (s) (EC:30) [15:00:42:801]: Note: 1: 2329 2: 32 3: C:\Program Files\Polyscience\PIMS.ade
MSI (s) (EC:30) [15:00:42:801]: Verifying accessibility of file: PIMS.ade
Info 1903. Scheduling reboot operation: Deleting file C:\Program Files\Polyscience\PIMS.ade. Reboot to complete the operation.
Info 1902. Scheduling reboot operation: Renaming file C:\Program Files\Polyscience\TBM1D.tmp to C:\Program Files\Polyscience\PIMS.ade. Reboot to complete the operation.

[Wilson, Phil]

I'm not sure what your expectations are, but MSI 4.5 does not have any enhanced detection on XPSP3.   A Restart Manager OS is required to get better in-use detection than previous OS versions.

In general, you won't see a FilesInUse window unless the process with the files open has a top level window open that the user can be asked to close. Does that fit what you're seeing.

Also, I know the entire log isn't there, but when MSI detects files in use it lists them and the using process is whether there's going to be a FilesInUse dialog or not. They are usually something like Info 1603. Are there any of those in the log?
--
Phil Wilson
The Definitive Guide to Windows Installer
http://www.apress.com/book/view/1590592972

"Vadim Rapp" <nos...@sbcglobal.net> wrote in message news:uA5lnqnV...@TK2MSFTNGP05.phx.gbl...

[Vadim Rapp]

Yes, you can see 1603 in the 2nd part of the log that I posted - detected by FileCopy. Remarkably, the message says:

Info 1603. The file C:\Program Files\Polyscience\PIMS.ade is being held in use.  Close that application and retry   .

 

I'm not sure if "that" application was supposed to be named in the 1st sentence or not - does not seem to be, there's no "by" in it. But in any case, the file is opened by Access, its window is wide open on the screen, and application such as TaskInfo (www.iarsn.com) has no problem detecting that the file is opened by MSACCESS.EXE, so naturally, my expectation is that Installer's InstallValidate should do the same.

 

Here's equivalent piece from the log of another installation that I created, where this feature works ok:

 

---

MSI (s) (7C:88) [20:12:45:807]: Doing action: InstallValidate
Action 20:12:45: InstallValidate. Validating install...
Action start 20:12:45: InstallValidate.
MSI (s) (7C:88) [20:12:45:807]: Feature: Complete; Installed: Absent;   Request: Local;   Action: Local
MSI (s) (7C:88) [20:12:45:807]: Component: v1.exe; Installed: Absent;   Request: Local;   Action: Local
MSI (s) (7C:88) [20:12:45:807]: Note: 1: 2262 2: BindImage 3: -2147287038
MSI (s) (7C:88) [20:12:45:807]: Note: 1: 2262 2: ProgId 3: -2147287038
MSI (s) (7C:88) [20:12:45:807]: Note: 1: 2262 2: PublishComponent 3: -2147287038
MSI (s) (7C:88) [20:12:45:807]: Note: 1: 2262 2: SelfReg 3: -2147287038
MSI (s) (7C:88) [20:12:45:807]: Note: 1: 2262 2: Extension 3: -2147287038
MSI (s) (7C:88) [20:12:45:807]: Note: 1: 2262 2: Font 3: -2147287038
MSI (s) (7C:88) [20:12:45:807]: Note: 1: 2262 2: Class 3: -2147287038
MSI (c) (80:84) [20:12:45:807]: Note: 1: 2262 2: Billboard 3: -2147287038
MSI (s) (7C:88) [20:12:45:807]: Note: 1: 2262 2: RemoveFile 3: -2147287038
MSI (s) (7C:88) [20:12:45:807]: Note: 1: 2205 2:  3: _RemoveFilePath
MSI (s) (7C:88) [20:12:45:817]: Note: 1: 2262 2: DuplicateFile 3: -2147287038
MSI (s) (7C:88) [20:12:45:817]: Note: 1: 2262 2: ReserveCost 3: -2147287038
MSI (s) (7C:88) [20:12:45:817]: PROPERTY CHANGE: Modifying CostingComplete property. Its current value is '0'. Its new value: '1'.
MSI (s) (7C:88) [20:12:45:817]: Note: 1: 2262 2: BindImage 3: -2147287038
MSI (s) (7C:88) [20:12:45:817]: Note: 1: 2262 2: ProgId 3: -2147287038
MSI (s) (7C:88) [20:12:45:817]: Note: 1: 2262 2: PublishComponent 3: -2147287038
MSI (s) (7C:88) [20:12:45:817]: Note: 1: 2262 2: SelfReg 3: -2147287038
MSI (s) (7C:88) [20:12:45:817]: Note: 1: 2262 2: Extension 3: -2147287038
MSI (s) (7C:88) [20:12:45:817]: Note: 1: 2262 2: Font 3: -2147287038
MSI (s) (7C:88) [20:12:45:817]: Note: 1: 2262 2: Class 3: -2147287038
MSI (s) (7C:88) [20:12:45:817]: PROPERTY CHANGE: Modifying PrimaryVolumeSpaceAvailable property. Its current value is '0'. Its new value: '17026040'.
MSI (s) (7C:88) [20:12:45:817]: PROPERTY CHANGE: Modifying PrimaryVolumeSpaceRequired property. Its current value is '0'. Its new value: '664'.
MSI (s) (7C:88) [20:12:45:817]: PROPERTY CHANGE: Modifying PrimaryVolumeSpaceRemaining property. Its current value is '0'. Its new value: '17025376'.
MSI (s) (7C:88) [20:12:45:817]: PROPERTY CHANGE: Adding PrimaryVolumePath property. Its value is 'C:'.
Info 1603. The file C:\Program Files\test\v1.exe is being held in use by the following process: Name: v1, Id: 1052, Window Title: '(not determined yet)'.  Close that application and retry.
MSI (s) (7C:88) [20:12:49:902]: 1 application(s) had been reported to have files in use.
MSI (c) (80:84) [20:12:49:902]: Note: 1: 2262 2: ListBox 3: -2147287038
MSI (s) (7C:3C) [20:12:53:427]: I/O on thread 3632 could not be cancelled. Error: 127
MSI (s) (7C:3C) [20:12:53:427]: I/O on thread 904 could not be cancelled. Error: 127
MSI (s) (7C:3C) [20:12:53:427]: I/O on thread 3392 could not be cancelled. Error: 127
MSI (s) (7C:3C) [20:12:53:427]: I/O on thread 852 could not be cancelled. Error: 127
MSI (s) (7C:3C) [20:12:53:427]: I/O on thread 2240 could not be cancelled. Error: 127
MSI (s) (7C:3C) [20:12:53:427]: I/O on thread 3040 could not be cancelled. Error: 127
MSI (s) (7C:3C) [20:12:53:427]: I/O on thread 3464 could not be cancelled. Error: 127
MSI (s) (7C:3C) [20:12:53:427]: I/O on thread 3432 could not be cancelled. Error: 127
Action ended 20:12:53: InstallValidate. Return value 2.

---

 

So I'm wondering, is it only detecting the utables, perhaps? in any case, if this could be done by FileCopy, and even the message is the same 1603, then why not by InstallValidate?

 

But there's even more. During investigation, I created another pair of installations, v2 upgrading v1, with the same pims.ade . There, InstallValidate still did not do anything, however FileCopy showed a dialog "Another application has exclusive access to the file 'C:\Program Files\test\PIMS.ade.  Please shut down all other applications, then click Retry". I did not find any difference that could explain this. Remarkably, even though I obediently closed and retried, in the end it still scheduled the reboot.

 

Would be interesting to try on Vista or W7.

 

Vadim Rapp

 WP> I'm not sure what your expectations are, but MSI 4.5 does not have any
 WP> enhanced detection on XPSP3.   A Restart Manager OS is required to get
 WP> better in-use detection than previous OS versions. In general, you
 WP> won't see a FilesInUse window unless the process with the files open
 WP> has a top level window open that the user can be asked to close. Does
 WP> that fit what you're seeing. Also, I know the entire log isn't there,
 WP> but when MSI detects files in use it lists them and the using process
 WP> is whether there's going to be a FilesInUse dialog or not. They are
 WP> usually something like Info 1603. Are there any of those in the log? --
 WP> Phil Wilson
 WP> The Definitive Guide to Windows Installer
 WP> http://www.apress.com/book/view/1590592972

 WP>   "Vadim Rapp" <nos...@sbcglobal.net> wrote in message news:uA5lnqnV...@TK2MSFTNGP05.phx.gbl...
 WP>   Hello,

 WP>   I have an installation that installs an ADE file, compiled Microsoft
 WP> Access project. Version 1 is already installed on XP SP3 machine with
 WP> Installer 4.5; and the file is opened in Access. New installation is
 WP> supposed to upgrade the file (major upgrade; RemoveExistingProducts is
 WP> in the very end, after InstallFinalize); against my expectations,
 WP> InstallValidate does not show FilesInUse dialog, and in the log file
 WP> (below) there's no indication of even an attempt to detect them. It's
 WP> however successfully detected later by FileCopy, which then schedules
 WP> the reboot.

 WP>   What can be the reason for InstallValidate to not detect it?

 WP>   regards

 WP>   ---------------------------------------------------------------------

 WP>   MSI (s) (EC:30) [15:00:36:774]: Doing action: InstallValidate
 WP>   Action 15:00:36: InstallValidate. Validating install...
 WP>   Action start 15:00:36: InstallValidate.
 WP>   MSI (s) (EC:30) [15:00:36:774]: Feature: Complete; Installed: Absent;   Request: Local;   Action:
 WP> Local MSI (s) (EC:30) [15:00:36:774]: Component: PIMS.ade; Installed: Absent;   Request: Local;
 WP> Action: Local MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262 2: BindImage 3:
 WP> -2147287038  MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262 2: ProgId 3:
 WP> -2147287038  MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262 2:
 WP> PublishComponent 3: -2147287038  MSI (s) (EC:30) [15:00:36:774]: Note: 1:
 WP> 2262 2: SelfReg 3: -2147287038  MSI (s) (EC:30) [15:00:36:774]: Note: 1:
 WP> 2262 2: Extension 3: -2147287038  MSI (s) (EC:30) [15:00:36:774]: Note: 1:
 WP> 2262 2: Font 3: -2147287038  MSI (s) (EC:30) [15:00:36:774]: Note: 1: 2262
 WP> 2: Class 3: -2147287038  MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2:
 WP> RemoveFile 3: -2147287038  MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2205 2:
 WP> 3: _RemoveFilePath  MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2:
 WP> DuplicateFile 3: -2147287038  MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262
 WP> 2: ReserveCost 3: -2147287038  MSI (s) (EC:30) [15:00:36:784]: PROPERTY
 WP> CHANGE: Modifying CostingComplete property. Its current value is '0'. Its new
 WP> value: '1'. MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: BindImage 3:
 WP> -2147287038  MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2: ProgId 3:
 WP> -2147287038  MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262 2:
 WP> PublishComponent 3: -2147287038  MSI (s) (EC:30) [15:00:36:784]: Note: 1:
 WP> 2262 2: SelfReg 3: -2147287038  MSI (s) (EC:30) [15:00:36:784]: Note: 1:
 WP> 2262 2: Extension 3: -2147287038  MSI (s) (EC:30) [15:00:36:784]: Note: 1:
 WP> 2262 2: Font 3: -2147287038  MSI (s) (EC:30) [15:00:36:784]: Note: 1: 2262
 WP> 2: Class 3: -2147287038  MSI (s) (EC:30) [15:00:36:784]: PROPERTY CHANGE:
 WP> Modifying PrimaryVolumeSpaceAvailable property. Its current value is
 WP> '0'. Its new value: '17024824'. MSI (s) (EC:30) [15:00:36:784]: PROPERTY CHANGE:
 WP> Modifying PrimaryVolumeSpaceRequired property. Its current value is
 WP> '0'. Its new value: '10520'. MSI (s) (EC:30) [15:00:36:784]: PROPERTY CHANGE:
 WP> Modifying PrimaryVolumeSpaceRemaining property. Its current value is
 WP> '0'. Its new value: '17014304'. MSI (s) (EC:30) [15:00:36:784]: PROPERTY CHANGE:
 WP> Adding PrimaryVolumePath property. Its value is 'C:'. Action ended 15:00:39:
 WP> InstallValidate. Return value 1.

 WP>   .....

 WP>   MSI (s) (EC:30) [15:00:40:157]: Executing op:
 WP> FileCopy(SourceName=PIMS.ade,SourceCabKey=PIMS.ade,DestName=PIMS.ade,At
 WP> tributes=0,FileSize=4335104,PerTick=32768,,VerifyMedia=1,,,,,CheckCRC=0
 WP> ,,,InstallMode=58982400,HashOptions=0,HashPart1=1924052871,HashPart2=15
 WP> 53980841,HashPart3=1683386880,HashPart4=1526520394,,) MSI (s) (EC:30)
 WP> [15:00:40:157]: File: C:\Program Files\polyscience\PIMS.ade; Overwrite;
 WP> Won't patch; Existing file is unversioned and unmodified - hash doesn't
 WP> match source file MSI (s) (EC:30) [15:00:40:157]: Source for file
 WP> 'PIMS.ade' is compressed InstallFiles: File: PIMS.ade
 WP>   Directory: C:\Program Files\Polyscience\
 WP>   Size: 4335104
 WP>   MSI (s) (EC:30) [15:00:40:157]: Re-applying security from existing
 WP> file. Info 1603. The file C:\Program Files\Polyscience\PIMS.ade is
 WP> being held in use.  Close that application and retry    <---------
 WP> (very useful here, isn't it :-) MSI (s) (EC:30) [15:00:42:751]:
 WP> Verifying accessibility of file: PIMS.ade MSI (s) (EC:30) [15:00:42:751]:
 WP> Verifying accessibility of file: PIMS.ade MSI (s) (EC:30) [15:00:42:751]: Note:
 WP> 1: 2318 2: C:\Config.Msi\10164.rbf  MSI (s) (EC:30) [15:00:42:751]:
 WP> Using source file security for destination. MSI (s) (EC:30)
 WP> [15:00:42:801]: Note: 1: 2329 2: 32 3: C:\Program
 WP> Files\Polyscience\PIMS.ade  MSI (s) (EC:30) [15:00:42:801]: Verifying
 WP> accessibility of file: PIMS.ade Info 1903. Scheduling reboot operation: Deleting
 WP> file C:\Program Files\Polyscience\PIMS.ade. Reboot to complete the
 WP> operation. Info 1902. Scheduling reboot operation: Renaming file C:\Program
 WP> Files\Polyscience\TBM1D.tmp to C:\Program Files\Polyscience\PIMS.ade.
 WP> Reboot to complete the operation.

Regards

[Wilson, Phil]

My question about Info 1603 wasn't clear. Specifically, I just wanted to
verify that there were none in the InstallValidate action. Apparently there
were none, so it looks like there was no detection at all that the file was
in use until it was time to replace it, when that message was shown again. I
wouldn't place too much emphasis on the logging outputs comments about
closing that application. It's just diagnostic goop.

I don't know what's going on there. There might be some cases that can't be
resolved - just speculating. An exe in use is relatively simple, it's open
for read/execute (not for update). Something like Process Explorer might
show the file in use by something else.

--
Phil Wilson

The Definitive Guide to Windows Installer

http://www.apress.com/book/view/1590592972

"Vadim Rapp" <v...@nospam.myrealbox.com> wrote in message
news:eFzAN7qV...@TK2MSFTNGP06.phx.gbl...

Yes, you can see 1603 in the 2nd part of the log that I posted - detected by
FileCopy. Remarkably, the message says:

Info 1603. The file C:\Program Files\Polyscience\PIMS.ade is being held in
use. Close that application and retry .

I'm not sure if "that" application was supposed to be named in the 1st
sentence or not - does not seem to be, there's no "by" in it. But in any
case, the file is opened by Access, its window is wide open on the screen,
and application such as TaskInfo (www.iarsn.com) has no problem detecting
that the file is opened by MSACCESS.EXE, so naturally, my expectation is
that Installer's InstallValidate should do the same.

Here's equivalent piece from the log of another installation that I created,
where this feature works ok: