The install log for a WIX-based installer indicates the installation process occurs twice, making custom actions occur at unexpected times

I have WiX installers with two C# custom actions (CAs) that first get the default settings, and then save settings provided during the installation.

• The LOAD custom action runs After="CostFinalize"
• The SAVE custom action runs After="InstallFiles"...

Check out the log file, though... You'll see those phases inexplicably occur TWICE in any particular installation run, the FIRST time failing to perform tasks that would normally occur during those phases (such as during InstallFiles, NO files are installed until the second occurrence of the InstallFiles phase in the single install).

This is a problem, because the save function must operate on the app.config file as deployed to its install folder, but after the first ocurrence of InstallFiles, this file has not yet moved to its expected location, causing the load of it to fail during the save custom action....

Looking further through the installation, you'll see the phases repeat, but this time actually deploying files during InstallFiles, but the custom action no longer runs at that point, as it already ran after the first instance...

What is happening here?

Log file

=== Logging started: 1/25/2011  16:08:06 ===
Action 16:08:06: INSTALL. 
Action start 16:08:06: INSTALL.
Action 16:08:06: FindRelatedProducts. Searching for related applications
Action start 16:08:06: FindRelatedProducts.
Action ended 16:08:06: FindRelatedProducts. Return value 1.
Action 16:08:06: ValidateProductID. 
Action start 16:08:06: ValidateProductID.
Action ended 16:08:06: ValidateProductID. Return value 1.
Action 16:08:06: CostInitialize. Computing space requirements
Action start 16:08:06: CostInitialize.
Action ended 16:08:06: CostInitialize. Return value 1.
Action 16:08:06: FileCost. Computing space requirements
Action start 16:08:06: FileCost.
Action ended 16:08:06: FileCost. Return value 1.
Action 16:08:06: CostFinalize. Computing space requirements
Action start 16:08:06: CostFinalize.
Action ended 16:08:06: CostFinalize. Return value 1.
Action 16:08:06: LoadSchedulerConfigDefaults. 
Action start 16:08:06: LoadSchedulerConfigDefaults.
SFXCA: Extracting custom action to temporary directory: C:\DOCUME~1\ELOY06~1\LOCALS~1\Temp\MSI53A.tmp-\
SFXCA: Binding to CLR version v2.0.50727
Calling custom action WIXCustomActions!WIXCustomActions.CustomActions.LoadSchedulerConfigDefaults
*** LoadSchedulerConfigDefaults ***
Attempting to load the REGISTRY settings for database connectivity to the ccp database...
Attempting to set into the session the pre-existing registry keys...
CCP_DATABASE => orangeCCP
CCP_SERVER => desk06096d
CCP_UIS => SSPI
CCP_CONNECTIONTIMEOUT => 240
Attempting to load the REGISTRY settings for database connectivity to the cca database...
Attempting to set into the session the pre-existing registry keys...
CCA_DATABASE => orangeCCA
CCA_SERVER => desk06096d
CCA_UIS => SSPI
CCA_CONNECTIONTIMEOUT => 240
Attempting to load the REGISTRY settings for database connectivity to the ccc database...
Attempting to set into the session the pre-existing registry keys...
CCC_DATABASE => orangeCCC
CCC_SERVER => desk06096d
CCC_UIS => SSPI
CCC_CONNECTIONTIMEOUT => 240
Attempting to load the REGISTRY settings for database connectivity to the ccr database...
Attempting to set into the session the pre-existing registry keys...
CCR_DATABASE => orangeCCR
CCR_SERVER => desk06096d
CCR_UIS => SSPI
CCR_CONNECTIONTIMEOUT => 240
Attempting to load the app.config File to read the defaults at C:\Program Files\eLoyalty\eLoyalty Scheduler Service\eLoyalty.SchedulerService.exe.config.
Unable to read AppConfig file at C:\Program Files\eLoyalty\eLoyalty Scheduler Service\eLoyalty.SchedulerService.exe.config. This is probably a first-time installation.
Action ended 16:08:07: LoadSchedulerConfigDefaults. Return value 1.
Action 16:08:07: WelcomeDlg. 
Action start 16:08:07: WelcomeDlg.
Info 2898. For WixUI_Font_Normal textstyle, the system created a 'Tahoma' font, in 0 character set, of 13 pixels height.
Info 2898. For WixUI_Font_Bigger textstyle, the system created a 'Tahoma' font, in 0 character set, of 19 pixels height.
Action 16:08:07: WelcomeDlg. Dialog created
Info 2898. For WixUI_Font_Title textstyle, the system created a 'Tahoma' font, in 0 character set, of 14 pixels height.
Action 16:08:08: MyInstallDirDlg. Dialog created
Action 16:08:09: LoadSchedulerConfigDefaults. 
Action start 16:08:09: LoadSchedulerConfigDefaults.
Action ended 16:08:10: LoadSchedulerConfigDefaults. Return value 1.
Action 16:08:10: WixUIValidatePath. 
Action start 16:08:10: WixUIValidatePath.
Action ended 16:08:10: WixUIValidatePath. Return value 1.
Action 16:08:10: SetupRegistryDlg. Dialog created
Action 16:08:11: SetupRegistryDlg2. Dialog created
Action 16:08:19: VerifyReadyDlg. Dialog created
Action ended 16:08:19: WelcomeDlg. Return value 1.
Action 16:08:19: ProgressDlg. 
Action start 16:08:19: ProgressDlg.
Action 16:08:19: ProgressDlg. Dialog created
Action ended 16:08:19: ProgressDlg. Return value 1.
Action 16:08:19: ExecuteAction. 
Action start 16:08:19: ExecuteAction.
Action 16:08:20: INSTALL. 
Action start 16:08:20: INSTALL.
Action 16:08:20: FindRelatedProducts. Searching for related applications
Action start 16:08:20: FindRelatedProducts.
Action ended 16:08:20: FindRelatedProducts. Return value 0.
Action 16:08:20: ValidateProductID. 
Action start 16:08:20: ValidateProductID.
Action ended 16:08:20: ValidateProductID. Return value 1.
Action 16:08:20: CostInitialize. Computing space requirements
Action start 16:08:20: CostInitialize.
Action ended 16:08:20: CostInitialize. Return value 1.
Action 16:08:20: FileCost. Computing space requirements
Action start 16:08:20: FileCost.
Action ended 16:08:20: FileCost. Return value 1.
Action 16:08:20: CostFinalize. Computing space requirements
Action start 16:08:20: CostFinalize.
Action ended 16:08:20: CostFinalize. Return value 1.
Action 16:08:20: InstallValidate. Validating install
Action start 16:08:20: InstallValidate.
Action ended 16:08:20: InstallValidate. Return value 1.
Action 16:08:20: RemoveExistingProducts. Removing applications
Action start 16:08:20: RemoveExistingProducts.
Action ended 16:08:20: RemoveExistingProducts. Return value 1.
Action 16:08:20: InstallInitialize. 
Action start 16:08:20: InstallInitialize.
Action ended 16:08:34: InstallInitialize. Return value 1.
Action 16:08:34: ProcessComponents. Updating component registration
Action start 16:08:34: ProcessComponents.
Action 16:08:35: GenerateScript. Generating script operations for action:
GenerateScript: Updating component registration
tion ended 16:08:35: ProcessComponents. Return value 1.
InstallFiles: File: Copying new files,  Directory: ,  Size: 
// At this point, the logfile had some binary data injected, so I removed it.
ction start 16:08:35: InstallFiles.
Action ended 16:08:35: RemoveFiles. Return value 0.tion 16:08:35: InstallFiles. Copying new files
tion start 16:08:35: InstallFiles.
Action start 16:08:35: InstallFiles.tion ended 16:08:35: RemoveFiles. Return value 0.
Action 16:08:35: InstallFiles. Copying new filAction start 16:08:35: InstallFile File: [1],  Directory: [9],  Size: [6 ction ended 16:08:35: RemoveFiles. Return value File: [1],  Directory: [9],  Size: [6]tion start 16:08:35: InstallFiles.
tion ended 16:08:35: RemoveFiles. Return value 0.
tion 16:08:35: InstallFiles. Copying new files
tion start 16:08:35: InstallFiles.
tallFiles: File: Copying new files,  Directory: ,  Size: 
Action ended 16:08:35: InstallFiles. Return value 1.
Action 16:08:35: SetSchedulerConfigOptions. 
tion start 16:08:35: SetSchedulerConfigOptions.
// Logfile returned to normal at this point from binary data injections
XCA: Extracting custom action to temporary directory: C:\WINDOWS\Installer\MSI53E.tmp-\
XCA: Binding to CLR version v2.0.50727
Calling custom action WIXCustomActions!WIXCustomActions.CustomActions.SetSchedulerConfigOptions
*** SetSchedulerConfigOptions ***
*** WriteRegistryDBSettings ***
CCP Database => orangeCCP
CCP Server => desk06096d
CCP UseIntegratedSecurity => SSPI
CCP PortalConnectionTimeout => 240
CCA Database => orangeCCA
CCA Server => desk06096d
CCA UseIntegratedSecurity => SSPI
CCA PortalConnectionTimeout => 240
CCC Database => orangeCCC
CCC Server => desk06096d
CCC UseIntegratedSecurity => SSPI
CCC PortalConnectionTimeout => 240
CCR Database => orangeCCR
CCR Server => desk06096d
CCR UseIntegratedSecurity => SSPI
CCR PortalConnectionTimeout => 240
Registry settings successfully written.
AppConfig file not found @ C:\Program Files\eLoyalty\eLoyalty Scheduler Service\eLoyalty.SchedulerService.exe.config. Could not clear out connection strings.
Action ended 16:08:36: SetSchedulerConfigOptions. Return value 1.
Action 16:08:36: InstallServices. Installing new services
Action start 16:08:36: InstallServices.
InstallServices: Service: 
Action ended 16:08:36: InstallServices. Return value 1.
Action 16:08:36: StartServices. Starting services
Action start 16:08:36: StartServices.
StartServices: Service: Starting services
Action ended 16:08:36: StartServices. Return value 1.
Action 16:08:36: RegisterUser. Registering user
Action start 16:08:36: RegisterUser.
Action ended 16:08:36: RegisterUser. Return value 1.
Action 16:08:36: RegisterProduct. Registering product
Action start 16:08:36: RegisterProduct.
RegisterProduct: Registering product
Action ended 16:08:36: RegisterProduct. Return value 1.
Action 16:08:36: PublishFeatures. Publishing Product Features
Action start 16:08:36: PublishFeatures.
PublishFeatures: Feature: Publishing Product Features
Action ended 16:08:36: PublishFeatures. Return value 1.
Action 16:08:36: PublishProduct. Publishing product information
Action start 16:08:36: PublishProduct.
PublishProduct: 
Action ended 16:08:36: PublishProduct. Return value 1.
Action 16:08:36: InstallFinalize. 
Action start 16:08:36: InstallFinalize.
Action 16:08:36: ProcessComponents. Updating component registration
1: {D83DA1C7-FB6E-4C8A-9122-1D25764CF081} 2: {44FC813B-F7B3-4B54-9D82-5DF3B7C2BCE5} 3: C:\Program Files\eLoyalty\eLoyalty Scheduler Service\eLoyalty.SchedulerService.exe 
Action 16:08:36: StopServices. Stopping services
Action 16:08:36: DeleteServices. Deleting services
Action 16:08:36: InstallFiles. Copying new files
InstallFiles: File: Common.Logging.dll,  Directory: C:\Program Files\eLoyalty\eLoyalty Scheduler Service\,  Size: 28672
InstallFiles: File: eLoyalty.PortalLib.dll,  Directory: C:\Program Files\eLoyalty\eLoyalty Scheduler Service\,  Size: 91136
InstallFiles: File: eLoyalty.SchedulerService.exe,  Directory: C:\Program Files\eLoyalty\eLoyalty Scheduler Service\,  Size: 26112
InstallFiles: File: eLoyalty.SchedulerService.exe.config,  Directory: C:\Program Files\eLoyalty\eLoyalty Scheduler Service\,  Size: 922
InstallFiles: File: eLoyalty.SchedulerService.pdb,  Directory: C:\Program Files\eLoyalty\eLoyalty Scheduler Service\,  Size: 65024
InstallFiles: File: log4net.config,  Directory: C:\Program Files\eLoyalty\eLoyalty Scheduler Service\,  Size: 1405
InstallFiles: File: log4net.dll,  Directory: C:\Program Files\eLoyalty\eLoyalty Scheduler Service\,  Size: 270336
InstallFiles: File: Quartz.dll,  Directory: C:\Program Files\eLoyalty\eLoyalty Scheduler Service\,  Size: 438272
Action 16:08:36: InstallServices. Installing new services
Action 16:08:37: StartServices. Starting services
StartServices: Service: eLoyalty Scheduler Service
Action 16:08:39: RegisterProduct. Registering product
RegisterProduct: {D83DA1C7-FB6E-4C8A-9122-1D25764CF081}
Action 16:08:39: PublishFeatures. Publishing Product Features
PublishFeatures: Feature: ProductFeature
Action 16:08:39: PublishProduct. Publishing product information
1: {D83DA1C7-FB6E-4C8A-9122-1D25764CF081} 
Action 16:08:39: RollbackCleanup. Removing backup files
Action ended 16:08:39: InstallFinalize. Return value 1.
Action ended 16:08:39: INSTALL. Return value 1.
Property(S): UpgradeCode = {2A1341A1-FFFD-4BED-A609-14CB1C265330}
Property(S): FILEINSTALLDIR = C:\Program Files\eLoyalty\eLoyalty Scheduler Service\
Property(S): CCP_DATABASE = orangeCCP
Property(S): CCP_SERVER = desk06096d
Property(S): CCP_UIS = SSPI
Property(S): CCP_CONNECTIONTIMEOUT = 240
Property(S): CCA_DATABASE = orangeCCA
Property(S): CCA_SERVER = desk06096d
Property(S): CCA_UIS = SSPI
Property(S): CCA_CONNECTIONTIMEOUT = 240
Property(S): CCC_DATABASE = orangeCCC
Property(S): CCC_SERVER = desk06096d
Property(S): CCC_UIS = SSPI
Property(S): CCC_CONNECTIONTIMEOUT = 240
Property(S): CCR_DATABASE = orangeCCR
Property(S): CCR_SERVER = desk06096d
Property(S): CCR_UIS = SSPI
Property(S): CCR_CONNECTIONTIMEOUT = 240
Property(S): WIXUI_INSTALLDIR = FILEINSTALLDIR
Property(S): ARPNOMODIFY = 1
Property(S): eLoyalty = C:\Program Files\eLoyalty\
Property(S): ProgramFilesFolder = C:\Program Files\
Property(S): TARGETDIR = C:\
Property(S): SourceDir = C:\development\trunk\PortalsDev\csharp\production\Installers\WIX\eLoyalty.SchedulerServiceWIXInstaller\bin\Debug\
Property(S): VersionNT = 501
Property(S): Manufacturer = eLoyalty
Property(S): ProductCode = {D83DA1C7-FB6E-4C8A-9122-1D25764CF081}
Property(S): ProductLanguage = 1033
Property(S): ProductName = eLoyalty Scheduler Service
Property(S): ProductVersion = 2.7.0
Property(S): CONFIGFILE = eLoyalty.SchedulerService.exe.config
Property(S): DefaultUIFont = WixUI_Font_Normal
Property(S): WixUI_Mode = InstallDir
Property(S): ErrorDialog = ErrorDlg
Property(S): SecureCustomProperties = CCA_CONNECTIONTIMEOUT;CCA_DATABASE;CCA_SERVER;CCA_UIS;CCC_CONNECTIONTIMEOUT;CCC_DATABASE;CCC_SERVER;CCC_UIS;CCP_CONNECTIONTIMEOUT;CCP_DATABASE;CCP_SERVER;CCP_UIS;CCR_CONNECTIONTIMEOUT;CCR_DATABASE;CCR_SERVER;CCR_UIS;NEWERFOUND;OLDERFOUND;PREVIOUSVERSIONSINSTALLED;SELFFOUND
Prop开发者_开发百科erty(S): MsiLogFileLocation = C:\development\trunk\PortalsDev\csharp\production\Installers\WIX\eLoyalty.SchedulerServiceWIXInstaller\bin\Debug\log.txt
Property(S): PackageCode = {C6DD6531-CB70-44EB-8AEC-467BC66C7CC0}
Property(S): ProductState = -1
Property(S): PackagecodeChanging = 1
Property(S): CURRENTDIRECTORY = C:\development\trunk\PortalsDev\csharp\production\Installers\WIX\eLoyalty.SchedulerServiceWIXInstaller\bin\Debug
Property(S): CLIENTUILEVEL = 0
Property(S): CLIENTPROCESSID = 3364
Property(S): USERNAME = eLoyalty
Property(S): COMPANYNAME = eLoyalty
Property(S): VersionDatabase = 200
Property(S): ACTION = INSTALL
Property(S): EXECUTEACTION = INSTALL
Property(S): ROOTDRIVE = C:\
Property(S): INSTALLLEVEL = 1
Property(S): WIXUI_INSTALLDIR_VALID = 1
Property(S): SECONDSEQUENCE = 1
Property(S): ADDLOCAL = ProductFeature
Property(S): MsiSystemRebootPending = 1
Property(S): VersionMsi = 4.05
Property(S): WindowsBuild = 2600
Property(S): ServicePackLevel = 3
Property(S): ServicePackLevelMinor = 0
Property(S): MsiNTProductType = 1
Property(S): WindowsFolder = C:\WINDOWS\
Property(S): WindowsVolume = C:\
Property(S): SystemFolder = C:\WINDOWS\system32\
Property(S): System16Folder = C:\WINDOWS\system\
Property(S): RemoteAdminTS = 1
Property(S): TempFolder = C:\DOCUME~1\ELOY06~1\LOCALS~1\Temp\
Property(S): CommonFilesFolder = C:\Program Files\Common Files\
Property(S): AppDataFolder = C:\Documents and Settings\eloy06096\Application Data\
Property(S): FavoritesFolder = C:\Documents and Settings\eloy06096\Favorites\
Property(S): NetHoodFolder = C:\Documents and Settings\eloy06096\NetHood\
Property(S): PersonalFolder = C:\Documents and Settings\eloy06096\My Documents\
Property(S): PrintHoodFolder = C:\Documents and Settings\eloy06096\PrintHood\
Property(S): RecentFolder = C:\Documents and Settings\eloy06096\Recent\
Property(S): SendToFolder = C:\Documents and Settings\eloy06096\SendTo\
Property(S): TemplateFolder = C:\Documents and Settings\eloy06096\Templates\
Property(S): CommonAppDataFolder = C:\Documents and Settings\All Users\Application Data\
Property(S): LocalAppDataFolder = C:\Documents and Settings\eloy06096\Local Settings\Application Data\
Property(S): MyPicturesFolder = C:\Documents and Settings\eloy06096\My Documents\My Pictures\
Property(S): AdminToolsFolder = C:\Documents and Settings\eloy06096\Start Menu\Programs\Administrative Tools\
Property(S): StartupFolder = C:\Documents and Settings\eloy06096\Start Menu\Programs\Startup\
Property(S): ProgramMenuFolder = C:\Documents and Settings\eloy06096\Start Menu\Programs\
Property(S): StartMenuFolder = C:\Documents and Settings\eloy06096\Start Menu\
Property(S): DesktopFolder = C:\Documents and Settings\eloy06096\Desktop\
Property(S): FontsFolder = C:\WINDOWS\Fonts\
Property(S): GPTSupport = 1
Property(S): OLEAdvtSupport = 1
Property(S): ShellAdvtSupport = 1
Property(S): Intel = 6
Property(S): PhysicalMemory = 3288
Property(S): VirtualMemory = 3291
Property(S): AdminUser = 1
Property(S): LogonUser = eloy06096
Property(S): UserSID = S-1-5-21-15890611-392985980-6498272-20570
Property(S): UserLanguageID = 1033
Property(S): ComputerName = DESK06096D
Property(S): SystemLanguageID = 1033
Property(S): ScreenX = 1680
Property(S): ScreenY = 1050
Property(S): CaptionHeight = 19
Property(S): BorderTop = 1
Property(S): BorderSide = 1
Property(S): TextHeight = 16
Property(S): TextInternalLeading = 3
Property(S): ColorBits = 32
Property(S): TTCSupport = 1
Property(S): Time = 16:08:39
Property(S): Date = 1/25/2011
Property(S): MsiNetAssemblySupport = 4.0.30319.1
Property(S): MsiWin32AssemblySupport = 5.1.2600.5512
Property(S): RedirectedDllSupport = 2
Property(S): Privileged = 1
Property(S): DATABASE = C:\WINDOWS\Installer\da7c51.msi
Property(S): OriginalDatabase = C:\development\trunk\PortalsDev\csharp\production\Installers\WIX\eLoyalty.SchedulerServiceWIXInstaller\bin\Debug\eLoyalty.SchedulerServiceWIXInstaller.msi
Property(S): UILevel = 5
Property(S): Preselected = 1
Property(S): CostingComplete = 1
Property(S): OutOfDiskSpace = 0
Property(S): OutOfNoRbDiskSpace = 0
Property(S): PrimaryVolumeSpaceAvailable = 0
Property(S): PrimaryVolumeSpaceRequired = 0
Property(S): PrimaryVolumeSpaceRemaining = 0
Property(S): SOURCEDIR = C:\development\trunk\PortalsDev\csharp\production\Installers\WIX\eLoyalty.SchedulerServiceWIXInstaller\bin\Debug\
Property(S): SourcedirProduct = {D83DA1C7-FB6E-4C8A-9122-1D25764CF081}
Property(S): ProductToBeRegistered = 1
Action ended 16:08:39: ExecuteAction. Return value 1.
Action 16:08:39: ExitDialog. 
Action start 16:08:39: ExitDialog.
Action 16:08:39: ExitDialog. Dialog created
Action ended 16:09:00: ExitDialog. Return value 1.
Action ended 16:09:00: INSTALL. Return value 1.
Property(C): UpgradeCode = {2A1341A1-FFFD-4BED-A609-14CB1C265330}
Property(C): FILEINSTALLDIR = C:\Program Files\eLoyalty\eLoyalty Scheduler Service\
Property(C): CCP_DATABASE = orangeCCP
Property(C): CCP_SERVER = desk06096d
Property(C): CCP_UIS = SSPI
Property(C): CCP_CONNECTIONTIMEOUT = 240
Property(C): CCA_DATABASE = orangeCCA
Property(C): CCA_SERVER = desk06096d
Property(C): CCA_UIS = SSPI
Property(C): CCA_CONNECTIONTIMEOUT = 240
Property(C): CCC_DATABASE = orangeCCC
Property(C): CCC_SERVER = desk06096d
Property(C): CCC_UIS = SSPI
Property(C): CCC_CONNECTIONTIMEOUT = 240
Property(C): CCR_DATABASE = orangeCCR
Property(C): CCR_SERVER = desk06096d
Property(C): CCR_UIS = SSPI
Property(C): CCR_CONNECTIONTIMEOUT = 240
Property(C): WIXUI_INSTALLDIR = FILEINSTALLDIR
Property(C): ARPNOMODIFY = 1
Property(C): eLoyalty = C:\Program Files\eLoyalty\
Property(C): ProgramFilesFolder = C:\Program Files\
Property(C): TARGETDIR = C:\
Property(C): SourceDir = C:\development\trunk\PortalsDev\csharp\production\Installers\WIX\eLoyalty.SchedulerServiceWIXInstaller\bin\Debug\
Property(C): VersionNT = 501
Property(C): Manufacturer = eLoyalty
Property(C): ProductCode = {D83DA1C7-FB6E-4C8A-9122-1D25764CF081}
Property(C): ProductLanguage = 1033
Property(C): ProductName = eLoyalty Scheduler Service
Property(C): ProductVersion = 2.7.0
Property(C): CONFIGFILE = eLoyalty.SchedulerService.exe.config
Property(C): DefaultUIFont = WixUI_Font_Normal
Property(C): WixUI_Mode = InstallDir
Property(C): ErrorDialog = ErrorDlg
Property(C): SecureCustomProperties = CCA_CONNECTIONTIMEOUT;CCA_DATABASE;CCA_SERVER;CCA_UIS;CCC_CONNECTIONTIMEOUT;CCC_DATABASE;CCC_SERVER;CCC_UIS;CCP_CONNECTIONTIMEOUT;CCP_DATABASE;CCP_SERVER;CCP_UIS;CCR_CONNECTIONTIMEOUT;CCR_DATABASE;CCR_SERVER;CCR_UIS;NEWERFOUND;OLDERFOUND;PREVIOUSVERSIONSINSTALLED;SELFFOUND
Property(C): MsiLogFileLocation = C:\development\trunk\PortalsDev\csharp\production\Installers\WIX\eLoyalty.SchedulerServiceWIXInstaller\bin\Debug\log.txt
Property(C): PackageCode = {C6DD6531-CB70-44EB-8AEC-467BC66C7CC0}
Property(C): ProductState = -1
Property(C): PackagecodeChanging = 1
Property(C): CURRENTDIRECTORY = C:\development\trunk\PortalsDev\csharp\production\Installers\WIX\eLoyalty.SchedulerServiceWIXInstaller\bin\Debug
Property(C): CLIENTUILEVEL = 0
Property(C): CLIENTPROCESSID = 3364
Property(C): MsiSystemRebootPending = 1
Property(C): VersionDatabase = 200
Property(C): VersionMsi = 4.05
Property(C): WindowsBuild = 2600
Property(C): ServicePackLevel = 3
Property(C): ServicePackLevelMinor = 0
Property(C): MsiNTProductType = 1
Property(C): WindowsFolder = C:\WINDOWS\
Property(C): WindowsVolume = C:\
Property(C): SystemFolder = C:\WINDOWS\system32\
Property(C): System16Folder = C:\WINDOWS\system\
Property(C): RemoteAdminTS = 1
Property(C): TempFolder = C:\DOCUME~1\ELOY06~1\LOCALS~1\Temp\
Property(C): CommonFilesFolder = C:\Program Files\Common Files\
Property(C): AppDataFolder = C:\Documents and Settings\eloy06096\Application Data\
Property(C): FavoritesFolder = C:\Documents and Settings\eloy06096\Favorites\
Property(C): NetHoodFolder = C:\Documents and Settings\eloy06096\NetHood\
Property(C): PersonalFolder = C:\Documents and Settings\eloy06096\My Documents\
Property(C): PrintHoodFolder = C:\Documents and Settings\eloy06096\PrintHood\
Property(C): RecentFolder = C:\Documents and Settings\eloy06096\Recent\
Property(C): SendToFolder = C:\Documents and Settings\eloy06096\SendTo\
Property(C): TemplateFolder = C:\Documents and Settings\eloy06096\Templates\
Property(C): CommonAppDataFolder = C:\Documents and Settings\All Users\Application Data\
Property(C): LocalAppDataFolder = C:\Documents and Settings\eloy06096\Local Settings\Application Data\
Property(C): MyPicturesFolder = C:\Documents and Settings\eloy06096\My Documents\My Pictures\
Property(C): AdminToolsFolder = C:\Documents and Settings\eloy06096\Start Menu\Programs\Administrative Tools\
Property(C): StartupFolder = C:\Documents and Settings\eloy06096\Start Menu\Programs\Startup\
Property(C): ProgramMenuFolder = C:\Documents and Settings\eloy06096\Start Menu\Programs\
Property(C): StartMenuFolder = C:\Documents and Settings\eloy06096\Start Menu\
Property(C): DesktopFolder = C:\Documents and Settings\eloy06096\Desktop\
Property(C): FontsFolder = C:\WINDOWS\Fonts\
Property(C): GPTSupport = 1
Property(C): OLEAdvtSupport = 1
Property(C): ShellAdvtSupport = 1
Property(C): Intel = 6
Property(C): PhysicalMemory = 3288
Property(C): VirtualMemory = 3264
Property(C): AdminUser = 1
Property(C): LogonUser = eloy06096
Property(C): UserSID = S-1-5-21-15890611-392985980-6498272-20570
Property(C): UserLanguageID = 1033
Property(C): ComputerName = DESK06096D
Property(C): SystemLanguageID = 1033
Property(C): ScreenX = 1680
Property(C): ScreenY = 1050
Property(C): CaptionHeight = 19
Property(C): BorderTop = 1
Property(C): BorderSide = 1
Property(C): TextHeight = 16
Property(C): TextInternalLeading = 3
Property(C): ColorBits = 32
Property(C): TTCSupport = 1
Property(C): Time = 16:09:00
Property(C): Date = 1/25/2011
Property(C): MsiNetAssemblySupport = 4.0.30319.1
Property(C): MsiWin32AssemblySupport = 5.1.2600.5512
Property(C): RedirectedDllSupport = 2
Property(C): Privileged = 1
Property(C): USERNAME = eLoyalty
Property(C): COMPANYNAME = eLoyalty
Property(C): DATABASE = C:\DOCUME~1\ELOY06~1\LOCALS~1\Temp\e39fd9.msi
Property(C): OriginalDatabase = C:\development\trunk\PortalsDev\csharp\production\Installers\WIX\eLoyalty.SchedulerServiceWIXInstaller\bin\Debug\eLoyalty.SchedulerServiceWIXInstaller.msi
Property(C): SOURCEDIR = C:\development\trunk\PortalsDev\csharp\production\Installers\WIX\eLoyalty.SchedulerServiceWIXInstaller\bin\Debug\
Property(C): VersionHandler = 4.05
Property(C): UILevel = 5
Property(C): ACTION = INSTALL
Property(C): EXECUTEACTION = INSTALL
Property(C): ROOTDRIVE = C:\
Property(C): CostingComplete = 1
Property(C): OutOfDiskSpace = 0
Property(C): OutOfNoRbDiskSpace = 0
Property(C): PrimaryVolumeSpaceAvailable = 0
Property(C): PrimaryVolumeSpaceRequired = 0
Property(C): PrimaryVolumeSpaceRemaining = 0
Property(C): INSTALLLEVEL = 1
Property(C): WIXUI_INSTALLDIR_VALID = 1
=== Logging stopped: 1/25/2011  16:09:00 ===
MSI (c) (24:A0) [16:09:00:211]: Product: eLoyalty Scheduler Service -- Installation completed successfully.

MSI (c) (24:A0) [16:09:00:227]: Windows Installer installed the product. Product Name: eLoyalty Scheduler Service. Product Version: 2.7.0. Product Language: 1033. Installation success or error status: 0.

Updates for more information

The custom actions are defined as such in the .wsx file:

<!-- This package handles the custom actions for importing and setting Application Settings -->
    <Binary Id="WIXCustomActionsPackage.dll" SourceFile="WIXCustomActionsPackage.dll" />
    <CustomAction Id="LoadSchedulerConfigDefaults" Return="check" Execute="immediate" BinaryKey="WIXCustomActionsPackage.dll" DllEntry="LoadSchedulerConfigDefaults"/>
    <CustomAction Id="SetSchedulerConfigOptions" Return="check" Execute="immediate" BinaryKey="WIXCustomActionsPackage.dll" DllEntry="SetSchedulerConfigOptions"/>

They are set up to execute as such:

<InstallUISequence>
      <Custom Action="LoadSchedulerConfigDefaults" After="CostFinalize" />
    </InstallUISequence>
    <InstallExecuteSequence>
      <RemoveExistingProducts Before="InstallInitialize"/>
      <!-- This will fail the installer if a newer installed version is detected -->
      <ScheduleReboot Suppress="yes"></ScheduleReboot>
      <Custom Action="SetSchedulerConfigOptions" After="InstallFiles" ><![CDATA[REMOVE=ALL]]></Custom>
    </InstallExecuteSequence>

... The LoadSchedulerConfigDefaults scours the existing registry and then the app.config file (if one exists from a previous install) and gathers default values to prompt the user during the UI sequence in some custom dialogs...

The user either keeps the defaults, or overwrites them with custom settings, then continues through the install, at which time I would expect, since SaveSchedulerConfigOptions is set to run after InstallFiles, that it would be able to load the newly deployed (or non-overwritten old) app.config, and clear the settings out that it set in the registry...

But unfortunately, as you can tell by the log, they run after InstallFiles, but a version of it that doesn't deploy anything, its file-deploying replica occurring later in the log file...

You can set the CustomAction element's Execute attribute to 'firstSequence' if you want to only run the custom action once.

I suggest reading the following to understand the in's and out's and to make sure you are having it do what you need it to do.

Installation Phases and In-Script Execution Options for Custom Actions in Windows Installer

If you want to do things to files you're installing, the custom action's Execute attribute must be set to either deferred or commit. You may also need to set Impersonate to no.

Based on the other comments it sounds like you want the load action to execute in the firstSequence (during the UI phase) and the save CA to execute as deferred/commit.

Note that modifying an installed app.config is nasty, as now the file no longer matches the original install source and Windows Installer will replace it with the originally installed file if a repair is ever triggered.

"Check out the log file, though... You'll see those phases inexplicably occur TWICE..."

This occurs because several install actions are executed in the InstallUISequence as well as the InstallExecuteSequence, the InstallUISequence entries being executed first.

To get your custom action to run before a UI action, use the InstallUISequence table.

I solved this problem by passing variables through to the CA using CustomActionData this lets me pass through defaults. it also lets me get around the Cannot access session details from a non-immediate custom action issue, I can do things like:

<CustomAction Id="MYCustomParams" Property ="Thingy" Value ='MSIPATH=[OriginalDatabase]/>
<CustomAction Id="Thingy" BinaryKey="MYCustomDLL" DllEntry="MyFunc" Execute="deferred" Impersonate="no" Return="check"/>

You can also pass things via the command line to the MSI and pick them up like this

CMD> MyMSI.msi MYPARAM="default stuff"

<CustomAction Id="MYCustomParams" Property ="Thingy" Value ='MSIPARAM=[MYPARAM]/>