Major Upgrade takes a long time to install

[StevenP]

I have an Installscript MSI project that whenever I do a Major upgrade it gets to the point where it says "Unpublishing assembly information" and just stays there for a very long time (10 minutes) before finally going on. The installation will eventually finish and everything is correct. Any ideas as to why this takes so long?

[MattPow]

I have seen major problems with IS2009 InstallScript MSI projects when they perform a Major Upgrade. In fact they crash during the removal of the product being replaced. See this thread.

I would run your updated product installer with the command line:

"setup.exe" /v"/l*v c:\test.log"

Observe the log files it creates when doing the upgrade. Particularly check the second log file it creates "tes2.log" and look to see if anything failed or any MSI handles are leaked.

[StevenP]

I ran the Upgrade as suggested and there is an item in the tes2.log that failed and two MSI handles that are leaked. But I really don't know what the file is telling me.

=== Verbose logging started: 1/12/2009 16:10:17 Build type: SHIP UNICODE 4.00.6001.00 Calling process: C:\Users\STEVEN~1.DHI\AppData\Local\Temp\{111BED65-027E-4CA1-9C3A-3BD869ECBFC8}\setup.exe ===
MSI (c) (DC:7C) [16:10:17:393]: SOFTWARE RESTRICTION POLICY: Verifying package --> 'C:\Windows\Installer\23e75c.msi' against software restriction policy
MSI (c) (DC:7C) [16:10:17:393]: Note: 1: 2262 2: DigitalSignature 3: -2147287038
MSI (c) (DC:7C) [16:10:17:393]: SOFTWARE RESTRICTION POLICY: C:\Windows\Installer\23e75c.msi is not digitally signed
MSI (c) (DC:7C) [16:10:17:393]: SOFTWARE RESTRICTION POLICY: C:\Windows\Installer\23e75c.msi is permitted to run at the 'unrestricted' authorization level.
MSI (c) (DC:7C) [16:10:17:440]: Cloaking enabled.
MSI (c) (DC:7C) [16:10:17:440]: Attempting to enable all disabled privileges before calling Install on Server
MSI (c) (DC:7C) [16:10:17:471]: End dialog not enabled
MSI (c) (DC:7C) [16:10:17:471]: Original package ==> C:\Windows\Installer\23e75c.msi
MSI (c) (DC:7C) [16:10:17:471]: Package we're running from ==> C:\Windows\Installer\23e75c.msi
MSI (c) (DC:7C) [16:10:17:487]: APPCOMPAT: looking for appcompat database entry with ProductCode '{F7683ACE-982C-4D9E-A6FB-DC00FE4095BD}'.
MSI (c) (DC:7C) [16:10:17:487]: APPCOMPAT: no matching ProductCode found in database.
MSI (c) (DC:7C) [16:10:17:503]: MSCOREE not loaded loading copy from system32
MSI (c) (DC:7C) [16:10:17:503]: Machine policy value 'DisablePatch' is 0
MSI (c) (DC:7C) [16:10:17:503]: Machine policy value 'AllowLockdownPatch' is 0
MSI (c) (DC:7C) [16:10:17:503]: Machine policy value 'DisableLUAPatching' is 0
MSI (c) (DC:7C) [16:10:17:503]: Machine policy value 'DisableFlyWeightPatching' is 0
MSI (c) (DC:7C) [16:10:17:596]: APPCOMPAT: looking for appcompat database entry with ProductCode '{F7683ACE-982C-4D9E-A6FB-DC00FE4095BD}'.
MSI (c) (DC:7C) [16:10:17:628]: APPCOMPAT: no matching ProductCode found in database.
MSI (c) (DC:7C) [16:10:17:628]: Transforms are not secure.
MSI (c) (DC:7C) [16:10:17:628]: Note: 1: 2205 2: 3: Control
MSI (c) (DC:7C) [16:10:17:628]: PROPERTY CHANGE: Adding MsiLogFileLocation property. Its value is 'c:\tes2.log'.
MSI (c) (DC:7C) [16:10:17:628]: No Command Line.
MSI (c) (DC:7C) [16:10:17:628]: Product Code passed to Engine.Initialize: '(none)'
MSI (c) (DC:7C) [16:10:17:628]: Product Code from property table before transforms: '{F7683ACE-982C-4D9E-A6FB-DC00FE4095BD}'
MSI (c) (DC:7C) [16:10:17:628]: Product Code from property table after transforms: '{F7683ACE-982C-4D9E-A6FB-DC00FE4095BD}'
MSI (c) (DC:7C) [16:10:17:628]: Product registered: entering maintenance mode
MSI (c) (DC:7C) [16:10:17:628]: PROPERTY CHANGE: Adding ProductState property. Its value is '5'.
MSI (c) (DC:7C) [16:10:17:628]: PROPERTY CHANGE: Adding ProductToBeRegistered property. Its value is '1'.
MSI (c) (DC:7C) [16:10:17:628]: Note: 1: 1402 2: HKEY_CURRENT_USER\Software\Microsoft\Windows\CurrentVersion\Policies\Explorer 3: 2
MSI (c) (DC:7C) [16:10:17:628]: Package name retrieved from configuration data: 'CIM GOLD(TM).msi'
MSI (c) (DC:7C) [16:10:17:628]: Determined that existing product (either this product or the product being upgraded with a patch) is installed per-machine.
MSI (c) (DC:7C) [16:10:17:628]: Note: 1: 2262 2: AdminProperties 3: -2147287038
MSI (c) (DC:7C) [16:10:17:628]: PROPERTY CHANGE: Adding ALLUSERS property. Its value is '1'.
MSI (c) (DC:7C) [16:10:17:628]: Machine policy value 'DisableMsi' is 0
MSI (c) (DC:7C) [16:10:17:628]: Machine policy value 'AlwaysInstallElevated' is 0
MSI (c) (DC:7C) [16:10:17:628]: User policy value 'AlwaysInstallElevated' is 0
MSI (c) (DC:7C) [16:10:17:628]: Product {F7683ACE-982C-4D9E-A6FB-DC00FE4095BD} is admin assigned: LocalSystem owns the publish key.
MSI (c) (DC:7C) [16:10:17:628]: Product {F7683ACE-982C-4D9E-A6FB-DC00FE4095BD} is managed.
MSI (c) (DC:7C) [16:10:17:628]: Running product '{F7683ACE-982C-4D9E-A6FB-DC00FE4095BD}' with elevated privileges: Product is assigned.
MSI (c) (DC:7C) [16:10:17:628]: TRANSFORMS property is now:
MSI (c) (DC:7C) [16:10:17:628]: PROPERTY CHANGE: Adding PRODUCTLANGUAGE property. Its value is '1033'.
MSI (c) (DC:7C) [16:10:17:628]: PROPERTY CHANGE: Adding VersionDatabase property. Its value is '200'.
MSI (c) (DC:7C) [16:10:17:628]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Roaming
MSI (c) (DC:7C) [16:10:17:628]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\Favorites
MSI (c) (DC:7C) [16:10:17:628]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Roaming\Microsoft\Windows\Network Shortcuts
MSI (c) (DC:7C) [16:10:17:628]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\Documents
MSI (c) (DC:7C) [16:10:17:628]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Roaming\Microsoft\Windows\Printer Shortcuts
MSI (c) (DC:7C) [16:10:17:628]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Roaming\Microsoft\Windows\Recent
MSI (c) (DC:7C) [16:10:17:628]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Roaming\Microsoft\Windows\SendTo
MSI (c) (DC:7C) [16:10:17:628]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Roaming\Microsoft\Windows\Templates
MSI (c) (DC:7C) [16:10:17:628]: SHELL32::SHGetFolderPath returned: C:\ProgramData
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Local
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\Pictures
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\ProgramData\Microsoft\Windows\Start Menu\Programs\Administrative Tools
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\ProgramData\Microsoft\Windows\Start Menu\Programs\Startup
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\ProgramData\Microsoft\Windows\Start Menu\Programs
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\ProgramData\Microsoft\Windows\Start Menu
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\Users\Public\Desktop
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Roaming\Microsoft\Windows\Start Menu\Programs\Administrative Tools
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Roaming\Microsoft\Windows\Start Menu\Programs\Startup
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Roaming\Microsoft\Windows\Start Menu\Programs
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\AppData\Roaming\Microsoft\Windows\Start Menu
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\Users\Steven.DHIDOM1\Desktop
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\ProgramData\Microsoft\Windows\Templates
MSI (c) (DC:7C) [16:10:17:643]: SHELL32::SHGetFolderPath returned: C:\Windows\Fonts
MSI (c) (DC:7C) [16:10:17:659]: Note: 1: 2898 2: MS Sans Serif 3: MS Sans Serif 4: 0 5: 16
MSI (c) (DC:7C) [16:10:17:675]: MSI_LUA: Setting AdminUser property to 1 because this is the client or the user has already permitted elevation
MSI (c) (DC:7C) [16:10:17:675]: MSI_LUA: Setting MsiRunningElevated property to 1 because the install is already running elevated.
MSI (c) (DC:7C) [16:10:17:675]: PROPERTY CHANGE: Adding MsiRunningElevated property. Its value is '1'.
MSI (c) (DC:7C) [16:10:17:675]: PROPERTY CHANGE: Adding Privileged property. Its value is '1'.
MSI (c) (DC:7C) [16:10:17:675]: Note: 1: 1402 2: HKEY_CURRENT_USER\Software\Microsoft\MS Setup (ACME)\User Info 3: 2
MSI (c) (DC:7C) [16:10:17:675]: PROPERTY CHANGE: Adding USERNAME property. Its value is 'Steven'.
MSI (c) (DC:7C) [16:10:17:675]: Note: 1: 1402 2: HKEY_CURRENT_USER\Software\Microsoft\MS Setup (ACME)\User Info 3: 2
MSI (c) (DC:7C) [16:10:17:675]: PROPERTY CHANGE: Adding Installed property. Its value is '2008/11/19 07:43:30'.
MSI (c) (DC:7C) [16:10:17:675]: PROPERTY CHANGE: Adding DATABASE property. Its value is 'C:\Windows\Installer\23e75c.msi'.
MSI (c) (DC:7C) [16:10:17:675]: PROPERTY CHANGE: Adding OriginalDatabase property. Its value is 'C:\Windows\Installer\23e75c.msi'.
=== Logging started: 1/12/2009 16:10:17 ===
MSI (c) (DC:7C) [16:10:17:675]: Note: 1: 2205 2: 3: PatchPackage
MSI (c) (DC:7C) [16:10:17:675]: Machine policy value 'DisableRollback' is 0
MSI (c) (DC:7C) [16:10:17:675]: User policy value 'DisableRollback' is 0
MSI (c) (DC:7C) [16:10:17:675]: PROPERTY CHANGE: Adding UILevel property. Its value is '2'.
MSI (c) (DC:7C) [16:10:17:675]: MsiOpenPackageEx is returning 0
MSI (c) (DC:7C) [16:10:17:675]: MsiOpenPackage is returning 0
InstallShield 16:10:17: Ready to initialize ForceRemove, Product code is {F7683ACE-982C-4D9E-A6FB-DC00FE4095BD}
MSI (c) (DC:7C) [16:10:17:878]: Note: 1: 2205 2: 3: ReserveCost
MSI (c) (DC:7C) [16:10:17:878]: Note: 1: 2228 2: 3: ReserveCost 4: SELECT Component_,ReserveFolder,ReserveLocal,ReserveSource FROM ReserveCost
MSI (c) (DC:7C) [16:10:17:878]: Note: 1: 2205 2: 3: DuplicateFile
MSI (c) (DC:7C) [16:10:17:878]: Note: 1: 2228 2: 3: DuplicateFile 4: SELECT Component_,File_,DestFolder FROM DuplicateFile
InstallShield 16:10:18: ForceRemove, failed to open the cab, return code is 0x8000ffff
MSI (c) (DC:7C) [16:10:18:050]: Leaked MSIHANDLE (2) of type 790541 for thread 2940
MSI (c) (DC:7C) [16:10:18:050]: Leaked MSIHANDLE (1) of type 790537 for thread 2940
=== Verbose logging stopped: 1/12/2009 16:10:18 ===

Does it make any sense to anybody else?

[tommex]

StevenP wrote:

InstallShield 16:10:18: ForceRemove, failed to open the cab, return code is 0x8000ffff
MSI (c) (DC:7C) [16:10:18:050]: Leaked MSIHANDLE (2) of type 790541 for thread 2940
MSI (c) (DC:7C) [16:10:18:050]: Leaked MSIHANDLE (1) of type 790537 for thread 2940
=== Verbose logging stopped: 1/12/2009 16:10:18 ===

Does it make any sense to anybody else?

i have exactly the same problem. did you solve it?

[tommex]

after some further investigtions i encounter this error even when creating a new test installshield.

1. create a new installscript msi installshield with a major upgrade item (completly uninstall then reinstall) and one single feature with one single file
2. install it on a clean xp sp2 machine
3. change product version & product code
4. install again (major upgrade is detected) with logfile
-> a second logfile is created (name_of_logfile2.log) which shows the result of the uninstallation. within this logfile it is obvious that it does NOT completely uninstall. it finishes with:

InstallShield 16:10:18: ForceRemove, failed to open the cab, return code is 0x8000ffff
MSI (c) (DC:7C) [16:10:18:050]: Leaked MSIHANDLE (2) of type 790541 for thread 2940
MSI (c) (DC:7C) [16:10:18:050]: Leaked MSIHANDLE (1) of type 790537 for thread 2940

after that the installation proceeds with installing the new files (alltough the old installation has not been uninstalled).

so this is obviously an installshield bug.
i found some threads within this forum which also seem to have this issue, but without a solution. is acresso working on a solution?

[StevenP]

I never found a solution for the particular problem. However, I did have a problem with a major upgrade where after the uninstall and reinstall everything seemed to work fine, but when you go into Add/Remove programs there is an item there for you old and new version. Acresso confirmed that this was their problem. They gave me a work around that was completely unusable for me. They did not offer a hotfix. My guess is that it will be fixed in the next version, which means we will have to pay to get the fix. I believe that this problem is related to the slow upgrade problem. So I guess unless we move to a different type of installation product we are at the mercy of Acresso. Good luck. If you learn any move please share.

[joshstechnij]

A hotfix was posted in the thread referenced by MattPow. In order for the hotfix to correct the behavior, it must be applied to both the old and new setups. If this cannot be done because the old setup was already released, a "manual" major upgrade can be performed to uninstall the old product.