WiX removing windows service after major upgrade

3
votes

I'm seeing an intermittent issue doing a major upgrade using WiX on about 1 out of 100 systems. The windows service gets removed on the uninstall of the old version of the product, then gets installed and started on the install of the new version of the product. But after 1 or 2 seconds, the new version of the windows service gets uninstalled. I thought it might be a violation of the component rules or file versioning rules such as this question, but I'm not seeing a problem in the WiX script. I'm not changing the component GUID or referencing the resource in other components and the windows service exe is going from version 1.4.3 to 1.4.7.

After the upgrade fails, I can uninstall the new version of product, install the old version of the product, and then do the major upgrade to the new version of the product without any problems. After the first initial upgrade failure, all other upgrades work. Any help would be appreciated.

The code is:

<RemoveExistingProducts After="InstallExecute" />

<Component Id="ProgFiles" Guid="C692BAF6-17DB-4E8B-8225-9F0614080B16" Shared="no" Permanent="no">

        <ServiceInstall Id="InstallWindowsService"
                        Name="$(var.WindowsServiceName)"
                        DisplayName="[WINDOWS_SERVICE_DISPLAY_NAME]"
                        Type="ownProcess"
                        Start="auto"
                        ErrorControl="critical"
                        Description="$(var.AppDescription)">

            <ServiceConfig Id="WindowsServiceConfig"
                           DelayedAutoStart="yes"
                           OnInstall="yes"
                           OnReinstall="yes"/>              
        </ServiceInstall>
       <File Id='_04' DiskId='1' Name='Service.exe'                  Source='..\bin\$(var.BinariesToUse)\Service.exe' KeyPath='yes'/>
    </Component>
         <Component Id="ReleaseInstallRegEntries" Guid="5AB1B28B-C884-4230-9275-4095DDD06085" Shared="no" Permanent="no">
              <ServiceControl Id="WindowsServiceControl_USER"
                              Name="$(var.WindowsServiceName)"
                              Stop="both"
                              Start="install"
                              Remove="uninstall"
                              Wait="yes" />
            </Component>
    <Upgrade Id="$(var.UpgradeCode)">

    <UpgradeVersion Minimum="$(var.ProductVersion)"
                    IncludeMinimum="no"
                    OnlyDetect="yes"
                    Language="1033"
                    Property="NEWERPRODUCTFOUND" />

    <UpgradeVersion Minimum="0.0.0"
                    IncludeMinimum="yes"
                    Maximum="$(var.ProductVersion)"
                    IncludeMaximum="no"
                    Language="1033"
                    Property="UPGRADEFOUND" />

</Upgrade>

The entire msi install log downloaded from here

The msi install log:

MSI (s) (60:74) [12:09:04:691]: Doing action: RemoveExistingProducts
MSI (s) (60:74) [12:09:04:691]: Note: 1: 2205 2:  3: ActionText 
Action ended 12:09:04: PublishProduct. Return value 1.
MSI (s) (60:74) [12:09:04:691]: Skipping RemoveExistingProducts action: current configuration is maintenance mode or an uninstall
Action start 12:09:04: RemoveExistingProducts.
MSI (s) (60:74) [12:09:04:691]: Doing action: CleanUpgradeFolder
MSI (s) (60:74) [12:09:04:691]: Note: 1: 2205 2:  3: ActionText 
Action ended 12:09:04: RemoveExistingProducts. Return value 0.
Action start 12:09:04: CleanUpgradeFolder.
MSI (s) (60:74) [12:09:04:691]: Skipping action: WixFailWhenDeferred (condition is false)
MSI (s) (60:74) [12:09:04:691]: Doing action: InstallFinalize
MSI (s) (60:74) [12:09:04:691]: Note: 1: 2205 2:  3: ActionText 
Action ended 12:09:04: CleanUpgradeFolder. Return value 1.
MSI (s) (60:74) [12:09:04:691]: Running Script: C:\Windows\Installer\MSI4518.tmp
MSI (s) (60:74) [12:09:04:691]: PROPERTY CHANGE: Adding UpdateStarted property. Its value is '1'.
MSI (s) (60:74) [12:09:04:769]: Note: 1: 2265 2:  3: -2147287035 
MSI (s) (60:74) [12:09:04:769]: Machine policy value 'DisableRollback' is 0
MSI (s) (60:74) [12:09:04:769]: Executing op: Header(Signature=1397708873,Version=500,Timestamp=1225810211,LangId=1033,Platform=0,ScriptType=1,ScriptMajorVersion=21,ScriptMinorVersion=4,ScriptAttributes=1)
Action start 12:09:04: InstallFinalize.
MSI (s) (60:74) [12:09:04:769]: Executing op: ProductInfo(ProductKey={2BFA1207-9A98-4D55-9182-5C433ED6A55A},ProductName=Dell Customer Connect,PackageName=OTBSurvey.1.4.3.0.msi,Language=1033,Version=17039363,Assignment=1,ObsoleteArg=0,ProductIcon=dnd.ico,,PackageCode={11C5914C-B010-41D1-B920-D4C97AC61404},,,InstanceType=0,LUASetting=0,RemoteURTInstalls=0,ProductDeploymentFlags=3)
MSI (s) (60:74) [12:09:04:769]: Executing op: DialogInfo(Type=0,Argument=1033)
MSI (s) (60:74) [12:09:04:769]: Executing op: DialogInfo(Type=1,Argument=Dell Customer Connect)
MSI (s) (60:74) [12:09:04:769]: Executing op: RollbackInfo(,RollbackAction=Rollback,RollbackDescription=Rolling back action:,RollbackTemplate=[1],CleanupAction=RollbackCleanup,CleanupDescription=Removing backup files,CleanupTemplate=File: [1])
MSI (s) (60:74) [12:09:04:769]: Executing op: SetBaseline(Baseline=0,)
MSI (s) (60:74) [12:09:04:769]: Executing op: SetBaseline(Baseline=1,)
MSI (s) (60:74) [12:09:04:769]: Executing op: ActionStart(Name=InstallInitialize,,)
MSI (s) (60:74) [12:09:04:785]: Executing op: ProductUnregister(UpgradeCode={29D88272-5B32-4441-B6F3-568230D61331})
MSI (s) (60:74) [12:09:04:785]: Note: 1: 1402 2: UNKNOWN\Products\7021AFB289A955D41928C534E36D5AA5\Transforms 3: 2 
MSI (s) (60:74) [12:09:04:785]: Note: 1: 1402 2: UNKNOWN\Products\7021AFB289A955D41928C534E36D5AA5\Transforms 3: 2 
MSI (s) (60:74) [12:09:04:785]: Scheduling file 'C:\Windows\Installer\74bb8.msi' for deletion during post-install cleanup (not post-reboot).
MSI (s) (60:74) [12:09:04:800]: Note: 1: 1402 2: UNKNOWN\Products\7021AFB289A955D41928C534E36D5AA5\Usage 3: 2 
MSI (s) (60:74) [12:09:04:800]: Executing op: ProductCPDisplayInfoUnregister()
MSI (s) (60:74) [12:09:04:800]: Executing op: ProductUnpublish(PackageKey={11C5914C-B010-41D1-B920-D4C97AC61404})
MSI (s) (60:74) [12:09:04:800]: Using cached product context: machine assigned for product: 7021AFB289A955D41928C534E36D5AA5
MSI (s) (60:74) [12:09:04:816]: Executing op: UpgradeCodeUnpublish(UpgradeCode={29D88272-5B32-4441-B6F3-568230D61331})
MSI (s) (60:74) [12:09:04:816]: Executing op: IconRemove(Icon=dnd.ico,)
MSI (s) (60:74) [12:09:04:816]: Scheduling file 'C:\Windows\Installer\{2BFA1207-9A98-4D55-9182-5C433ED6A55A}\dnd.ico' for deletion during post-install cleanup (not post-reboot).
MSI (s) (60:74) [12:09:04:816]: Executing op: ProductUnpublishClient(,,)
MSI (s) (60:74) [12:09:04:816]: Note: 1: 1402 2: UNKNOWN\Installer\Products\7021AFB289A955D41928C534E36D5AA5 3: 2 
MSI (s) (60:74) [12:09:04:816]: Executing op: SourceListUnpublish(,)
MSI (s) (60:74) [12:09:04:816]: Note: 1: 1402 2: UNKNOWN\Installer\Products\7021AFB289A955D41928C534E36D5AA5\SourceList 3: 2 
MSI (s) (60:74) [12:09:04:816]: Executing op: ActionStart(Name=ProcessComponents,Description=Updating component registration,)
MSI (s) (60:74) [12:09:04:816]: Executing op: ProgressTotal(Total=12,Type=1,ByteEquivalent=24000)
MSI (s) (60:74) [12:09:04:816]: Executing op: UnregisterSharedComponentProvider(Component={F48BF778-F931-42C4-9D18-BE9A27E1D9F9},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:816]: Executing op: ComponentUnregister(ComponentId={F48BF778-F931-42C4-9D18-BE9A27E1D9F9},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:816]: Executing op: UnregisterSharedComponentProvider(Component={9A35F430-54AA-4FD6-9936-DD72910CF898},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:816]: Executing op: ComponentUnregister(ComponentId={9A35F430-54AA-4FD6-9936-DD72910CF898},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:816]: Executing op: UnregisterSharedComponentProvider(Component={DAA28A1B-1403-49C5-966E-E8C1989061D0},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:816]: Executing op: ComponentUnregister(ComponentId={DAA28A1B-1403-49C5-966E-E8C1989061D0},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:816]: Executing op: UnregisterSharedComponentProvider(Component={4F8B0F06-392A-4963-8A99-B32F436F802D},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:816]: Executing op: ComponentUnregister(ComponentId={4F8B0F06-392A-4963-8A99-B32F436F802D},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:816]: Executing op: UnregisterSharedComponentProvider(Component={1FF47611-4ABF-4A40-8278-133E73DF0461},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:816]: Executing op: ComponentUnregister(ComponentId={1FF47611-4ABF-4A40-8278-133E73DF0461},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:816]: Executing op: UnregisterSharedComponentProvider(Component={A2612202-F609-4C42-8FBC-2BE733A3D1FB},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:816]: Executing op: ComponentUnregister(ComponentId={A2612202-F609-4C42-8FBC-2BE733A3D1FB},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:816]: Executing op: UnregisterSharedComponentProvider(Component={9817EEDA-E4CC-4B5A-B97D-F9CF0C7DF493},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:816]: Executing op: ComponentUnregister(ComponentId={9817EEDA-E4CC-4B5A-B97D-F9CF0C7DF493},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:816]: Executing op: UnregisterSharedComponentProvider(Component={23FB7BF8-C385-4FE2-8A3F-AC4D7BE23CAF},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:816]: Executing op: ComponentUnregister(ComponentId={23FB7BF8-C385-4FE2-8A3F-AC4D7BE23CAF},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:816]: Executing op: UnregisterSharedComponentProvider(Component={350DEE79-78D9-46B6-8442-90A9299C8DDD},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:816]: Executing op: ComponentUnregister(ComponentId={350DEE79-78D9-46B6-8442-90A9299C8DDD},,BinaryType=0,)
MSI (s) (60:74) [12:09:04:832]: Executing op: UnregisterSharedComponentProvider(Component={8B227A34-6400-433B-84BD-F4BA9CC26E75},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:832]: Executing op: ComponentUnregister(ComponentId={8B227A34-6400-433B-84BD-F4BA9CC26E75},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:832]: Executing op: UnregisterSharedComponentProvider(Component={0DE95021-65AC-47DD-9158-A931C0363522},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:832]: Executing op: ComponentUnregister(ComponentId={0DE95021-65AC-47DD-9158-A931C0363522},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:832]: Executing op: UnregisterSharedComponentProvider(Component={CB46CF46-8580-4739-84BE-A7F8005B88AA},ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A})
MSI (s) (60:74) [12:09:04:832]: Executing op: ComponentUnregister(ComponentId={CB46CF46-8580-4739-84BE-A7F8005B88AA},,BinaryType=0,PreviouslyPinned=1)
MSI (s) (60:74) [12:09:04:832]: Executing op: ActionStart(Name=UnpublishFeatures,Description=Unpublishing Product Features,Template=Feature: [1])
MSI (s) (60:74) [12:09:04:832]: Executing op: FeatureUnpublish(Feature=MainFeature,,Absent=2,Component=oOhZwZc(O93_IgYZf`AysfrWYMS(aAH`zvLW+y1YKOr=oNHBe?(lECg)&h{kng%XA4jrY?**1D3.j'^2of{=-h$Or?u3qy72QN3GP8%4]bMHS@-6DAsx2KxyL5%tX%L]6@$$_pk6?{VWgq~W.N@IbAAYxz@snACa!~H'5xXlf=$O@R_YxY5p*P!fTand[9pcL*el).hM7d&P'`i=+?B@dz3w@T~-Pn@DjY@kt=bq}vxbrim_)
MSI (s) (60:74) [12:09:04:832]: Note: 1: 1402 2: UNKNOWN\Installer\Features\7021AFB289A955D41928C534E36D5AA5 3: 2 
MSI (s) (60:74) [12:09:04:832]: Executing op: ActionStart(Name=StopServices,Description=Stopping services,Template=Service: [1])
MSI (s) (60:74) [12:09:04:832]: Executing op: ProgressTotal(Total=1,Type=1,ByteEquivalent=1300000)
MSI (s) (60:74) [12:09:04:832]: Executing op: ServiceControl(,Name=Dell Customer Connect,Action=2,Wait=1,)
MSI (s) (60:74) [12:09:19:681]: Executing op: ActionStart(Name=DeleteServices,Description=Deleting services,Template=Service: [1])
MSI (s) (60:74) [12:09:19:681]: Executing op: ProgressTotal(Total=1,Type=1,ByteEquivalent=1300000)
MSI (s) (60:74) [12:09:19:681]: Executing op: ServiceControl(,Name=Dell Customer Connect,Action=8,Wait=1,)
MSI (s) (60:74) [12:09:19:681]: Executing op: ActionStart(Name=InstallFiles,Description=Copying new files,Template=File: [1],  Directory: [9],  Size: [6])
MSI (s) (60:74) [12:09:19:681]: Executing op: RemoveBaseline(ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A},ProductVersion=1.4.3)
MSI (s) (60:74) [12:09:19:681]: Verifying accessibility of file: _01
MSI (s) (60:74) [12:09:19:696]: Verifying accessibility of file: _04
MSI (s) (60:74) [12:09:19:696]: Verifying accessibility of file: _05
MSI (s) (60:74) [12:09:19:696]: Verifying accessibility of file: _06
MSI (s) (60:74) [12:09:19:712]: Verifying accessibility of file: _16
MSI (s) (60:74) [12:09:19:712]: Verifying accessibility of file: _17
MSI (s) (60:74) [12:09:19:728]: Verifying accessibility of file: _19
MSI (s) (60:74) [12:09:19:728]: Verifying accessibility of file: _20
MSI (s) (60:74) [12:09:19:728]: Verifying accessibility of file: _21
MSI (s) (60:74) [12:09:19:743]: Verifying accessibility of file: _22
MSI (s) (60:74) [12:09:19:743]: Verifying accessibility of file: _40
MSI (s) (60:74) [12:09:19:771]: Verifying accessibility of file: _41
MSI (s) (60:74) [12:09:19:786]: Verifying accessibility of file: _42
MSI (s) (60:74) [12:09:19:786]: Verifying accessibility of file: _43
MSI (s) (60:74) [12:09:19:802]: Verifying accessibility of file: _44
MSI (s) (60:74) [12:09:19:802]: Verifying accessibility of file: _77
MSI (s) (60:74) [12:09:19:802]: Verifying accessibility of file: _78
MSI (s) (60:74) [12:09:19:818]: Verifying accessibility of file: _79
MSI (s) (60:74) [12:09:19:818]: Verifying accessibility of file: _80
MSI (s) (60:74) [12:09:19:818]: Verifying accessibility of file: _81
MSI (s) (60:74) [12:09:19:818]: Verifying accessibility of file: _82
MSI (s) (60:74) [12:09:19:833]: Note: 1: 2318 2: C:\Windows\Installer\$PatchCache$\Managed\7021AFB289A955D41928C534E36D5AA5\CacheSize.txt 
MSI (s) (60:74) [12:09:19:833]: Executing op: RemoveBaseline(ProductCode={2BFA1207-9A98-4D55-9182-5C433ED6A55A},)
MSI (s) (60:74) [12:09:19:833]: Verifying accessibility of file: CacheSize.txt
MSI (s) (60:74) [12:09:19:833]: Executing op: ActionStart(Name=PublishProduct,Description=Publishing product information,)
MSI (s) (60:74) [12:09:19:833]: Executing op: CleanupConfigData()
MSI (s) (60:74) [12:09:19:833]: Executing op: RegisterPatchOrder(Continue=0,SequenceType=0,Remove=1)
MSI (s) (60:74) [12:09:19:833]: Note: 1: 1402 2: UNKNOWN\Installer\Products\7021AFB289A955D41928C534E36D5AA5\Patches 3: 2 
MSI (s) (60:74) [12:09:19:833]: Executing op: RegisterPatchOrder(Continue=0,SequenceType=1,Remove=1)
MSI (s) (60:74) [12:09:19:833]: Executing op: CleanupConfigData(RemovingProduct=1)
MSI (s) (60:74) [12:09:19:833]: Note: 1: 1402 2: HKEY_LOCAL_MACHINE\Software\Microsoft\Windows\CurrentVersion\Installer\UserData\S-1-5-18\Products\7021AFB289A955D41928C534E36D5AA5\Patches 3: 2 
MSI (s) (60:74) [12:09:19:833]: Executing op: ActionStart(Name=CleanUpgradeFolder,,)
MSI (s) (60:74) [12:09:19:833]: Executing op: CustomActionSchedule(Action=CleanUpgradeFolder,ActionType=3110,Source='MsgBox Session.Property("CleanUpgradeFolder")

      'delete the settings file:

      Set filesys = CreateObject("Scripting.FileSystemObject")
      sSettingsFilePath = "C:\ProgramData\Dell\OTBS\OTBSService.State.settings"

      If filesys.FileExists(sSettingsFilePath) Then
        filesys.DeleteFile sSettingsFilePath
      End If,,)
MSI (s) (60:74) [12:09:19:833]: Creating MSIHANDLE (7) of type 790536 for thread 884
MSI (s) (60:78) [12:09:19:833]: Creating MSIHANDLE (8) of type 0 for thread 1912
MSI (s) (60:78) [12:09:19:861]: Closing MSIHANDLE (8) of type 0 for thread 1912
MSI (s) (60:78) [12:09:19:861]: Closing MSIHANDLE (7) of type 790536 for thread 884
MSI (s) (60:74) [12:09:19:861]: Executing op: End(Checksum=0,ProgressTotalHDWord=0,ProgressTotalLDWord=2888000)
MSI (s) (60:74) [12:09:19:877]: PROPERTY CHANGE: Deleting UpdateStarted property. Its current value is '1'.

The windows service log:

2016-08-16 17:08:59,522 [1776] INFO  Service shutting down.    [ShutDownService]
2016-08-16 17:08:59,616 [1776] DEBUG    Service Stopped    [PreStopOperations]
2016-08-16 17:09:03,488 [3868] INFO  Service Started; Client Version: 1.4.7.0; OS: WIN8; Thread UI: en-US; Installed UI: en-US    [OnStart]
2016-08-16 17:09:04,832 [3868] INFO  OTBSurveyService: Stop event received    [OnStop]
2016-08-16 17:09:04,847 [3868] INFO  Service shutting down.    [ShutDownService]
2016-08-16 17:09:18,931 [3868] DEBUG    Service Stopped    [PreStopOperations]
1
windowswixwix3.8
If you can reproduce this one more time try using /l*v "C:\ProgramData\mycompany\msi_install_log.txt" to get a much more verbose log file which may be more useful. It will tell you what it is actually doing during the Standard actions instead of just saying Action start 13:01:40: InstallFinalize. Action ended 13:01:41: InstallFinalize. Return value 1. – Brian Sutherland
If this is an upgrade you should say where it's sequenced, the after..... setting. – PhilDW
I've updated the code with the upgrade and RemoveExistingProducts info and updated the log file with a section of verbose logging. The verbose log file was rather large so I only added the section around the issue. Let me know if you need more of the log. – Sam Henderson
That section of log isn't showing enough. In an upgrade there are several ServiceControl calls that are not shown here, and you may have shown the "immediate" script log entries not the actual calls that do something. Is Dell Customer connect is actually your service? Is there a reason for the time discrepancy between the two logs? And if only the hour is incorrect the service log times aren't shown in the MSI log. – PhilDW
Dell Customer connect is the name of the service. There is a 5 hour discrepancy between the logs due to the msi log is in local time and the service log is in UTC. The time that the service was uninstalled was 17:09:04,832. That would be 12:09:04:832 in the msi log. You'll notice that is when the installer stopped and uninstalled the service. I've updated the log entry to include as much of the msi log as I can within the 30000 character limit. – Sam Henderson

1 Answers

1
votes

Your described sequence of events as "The windows service gets removed on the uninstall of the old version of the product, then gets installed and started on the install of the new version of the product" is almost certainly incorrect, based on the log and the RemoveExistingProducts docs. The actual sequence of events when your upgrade is afterInstallExecute is that the new version is installed first, then the uninstall of the older product takes place.

Stopping the old service (from the upgrade install) is at 12:08:59, followed by deleting the old service. The new service is then installed, and started at 12:09:03.222, the service configuration actions take place there also. At 12:09:04.535 RemoveExistingProducts runs, the uninstall of your older product. That uninstall has a ServiceControl at 12:09:04:832 to stop the service (that you just installed), because your ServiceControl has stop=both, which means it will stop it at uninstall time, and this is the uninstall of the older product.

Since this is static defined behavior, perhaps the most likely explanation for variable behavior is a timing race. For example, your newly installed service might not be ready to accept stop requests in most installs, so it does not stop when the uninstall of the older product occurs. However sometimes it does respond and shuts down.

However, theorizing aside, the bottom line is still that you have code with a ServiceControl stop=both, and the uninstall of the older product with its stop is the last thing that happens (and note that you start only on install, not on uninstall!). You probably need to change your upgrade sequence because that stop=both is in the older installed product and can't be fixed without changing it with a patch, for example. Your upgrade afterInstallInitialize should be ok because the install is then actually after the uninstall of the older product.