This website uses cookies. By clicking Accept, you consent to the use of cookies. Click Here to learn more about how we use cookies.
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
- Revenera Community
- :
- InstallShield
- :
- InstallShield Forum
- :
- Re: Two errors in logfile: MsiProcessDrivers and ExecuteAction
Subscribe
- Mark Topic as New
- Mark Topic as Read
- Float this Topic for Current User
- Subscribe
- Mute
- Printer Friendly Page
- Mark as New
- Subscribe
- Mute
- Permalink
- Report Inappropriate Content
‎Jan 20, 2010
02:47 PM
Two errors in logfile: MsiProcessDrivers and ExecuteAction
Hi all, thanks in advance for any help!
I'm trying to build an installer that was handed off to me (see my other thread for more background information).
During the final steps of the installer, the installer window reads "registering product", and either during this step or immediately after (it's too close to tell), the install begins "rolling back" the changes that were made.
Now, I took at the install log file that was created during the install process and I found two "fatal errors"
One was the "ExecutionAction" during the "InstallWelcome", and the other was the "MsiProcessDrivers" during the "INSTALL".
I was hoping somebody might be able to shed some light on why I might be getting these errors, or how I might go about tracking down the cause of these issues. They're the only issues I see in the log file...
I'm trying to build an installer that was handed off to me (see my other thread for more background information).
During the final steps of the installer, the installer window reads "registering product", and either during this step or immediately after (it's too close to tell), the install begins "rolling back" the changes that were made.
Now, I took at the install log file that was created during the install process and I found two "fatal errors"
One was the "ExecutionAction" during the "InstallWelcome", and the other was the "MsiProcessDrivers" during the "INSTALL".
I was hoping somebody might be able to shed some light on why I might be getting these errors, or how I might go about tracking down the cause of these issues. They're the only issues I see in the log file...
InstallWelcome 2:57:45 PM 2:58:04 PM 19 seconds 1 - Success
EvaluateLic 2:57:54 PM 2:58:02 PM 8 seconds 1 - Success
CALLLOGDRIVER 2:58:04 PM 2:58:59 PM 55 seconds 1 - Success
CALLDRIVER 2:58:59 PM 2:59:42 PM 43 seconds 1 - Success
SetupProgress 2:59:42 PM 2:59:44 PM 2 seconds 1 - Success
SetODBCPath.9C... 2:59:44 PM 2:59:44 PM 0 seconds 1 - Success
ExecuteAction 2:59:44 PM 3:04:40 PM 296 seconds 3 - Fatal Error
SetupCompleteError 3:04:40 PM 3:04:51 PM 11 seconds 2 - User Cancelled
MsiProcessDrivers 3:02:46 PM 3:02:46 PM 0 seconds 3 - Fatal Error
(8) Replies
- Mark as New
- Subscribe
- Mute
- Permalink
- Report Inappropriate Content
‎Jan 20, 2010
03:38 PM
I just looked through the actual logfile (as apposed to the report that IS2008 gives) and this is what I found:
[CODE]
MSI (s) (B4:C4) [15:02:46:198]: Doing action: MsiProcessDrivers
Action 15:02:46: MsiProcessDrivers.
Action start 15:02:46: MsiProcessDrivers.
MSI (s) (B4:C4) [15:02:46:213]: Note: 1: 2235 2: 3: ExtendedType 4: SELECT `Action`,`Type`,`Source`,`Target`, NULL, `ExtendedType` FROM `CustomAction` WHERE `Action` = 'MsiProcessDrivers'
MSI (s) (B4:F4) [15:02:46:229]: Invoking remote custom action. DLL: C:\WINDOWS\Installer\MSIB151.tmp, Entrypoint: ProcessDriverPackages
Action ended 15:02:46: MsiProcessDrivers. Return value 3.
[/CODE]
[CODE]
MSI (s) (B4:C4) [15:02:46:198]: Doing action: MsiProcessDrivers
Action 15:02:46: MsiProcessDrivers.
Action start 15:02:46: MsiProcessDrivers.
MSI (s) (B4:C4) [15:02:46:213]: Note: 1: 2235 2: 3: ExtendedType 4: SELECT `Action`,`Type`,`Source`,`Target`, NULL, `ExtendedType` FROM `CustomAction` WHERE `Action` = 'MsiProcessDrivers'
MSI (s) (B4:F4) [15:02:46:229]: Invoking remote custom action. DLL: C:\WINDOWS\Installer\MSIB151.tmp, Entrypoint: ProcessDriverPackages
Action ended 15:02:46: MsiProcessDrivers. Return value 3.
[/CODE]
- Mark as New
- Subscribe
- Mute
- Permalink
- Report Inappropriate Content
‎Jan 20, 2010
05:53 PM
Hi There,
MsiProcessDrivers should have more verbose output than that. Does the top of your log start with "Verbose logging started"? If not, I'd try recreating it with more verbose options:
msiexec.exe /i package.msi /l*v c:\install.log
setup.exe /v"/l*vx c:\install.log"
or with the logging policy, a value of:
voicewarmup
If it does prove not to be a full verbose log, try posting the section around MsiProcessDrivers if it shows more information. Usually this will have an explicit reason as to why it decided to throw a return value of 3 (unless it outright fell over and crashed, which let's hope that isn't the case).
MsiProcessDrivers should have more verbose output than that. Does the top of your log start with "Verbose logging started"? If not, I'd try recreating it with more verbose options:
msiexec.exe /i package.msi /l*v c:\install.log
setup.exe /v"/l*vx c:\install.log"
or with the logging policy, a value of:
voicewarmup
If it does prove not to be a full verbose log, try posting the section around MsiProcessDrivers if it shows more information. Usually this will have an explicit reason as to why it decided to throw a return value of 3 (unless it outright fell over and crashed, which let's hope that isn't the case).
- Mark as New
- Subscribe
- Mute
- Permalink
- Report Inappropriate Content
‎Jan 21, 2010
07:40 AM
Thank you so much for your help!
You're right, there was more info in the log file I created (I was using the log file analyzer it turns out).
Unfortunately, I'm still not really able to make sense of what happened. Here is what I found before the rollback, and it's also includes the MsiProcessDrivers bit, but I don't see any "ERROR THIS HAPPENED" anywhere. Frankly even if I did I'm not sure I'd know what ot make of it.
Any ideas?
[code]
RegisterUser: Registering user
Action ended 15:02:41: RegisterUser. Return value 1.
MSI (s) (B4:C4) [15:02:41:916]: Doing action: RegisterProduct
Action 15:02:41: RegisterProduct. Registering product
Action start 15:02:41: RegisterProduct.
MSI (s) (B4:C4) [15:02:41:932]: Note: 1: 2205 2: 3: MsiDigitalSignature
RegisterProduct: Registering product
MSI (s) (B4:C4) [15:02:46:198]: PROPERTY CHANGE: Adding ProductToBeRegistered property. Its value is '1'.
Action ended 15:02:46: RegisterProduct. Return value 1.
MSI (s) (B4:C4) [15:02:46:198]: Doing action: PublishComponents
Action 15:02:46: PublishComponents. Publishing qualified components
Action start 15:02:46: PublishComponents.
PublishComponents: Component ID: Publishing qualified components, Qualifier:
Action ended 15:02:46: PublishComponents. Return value 1.
MSI (s) (B4:C4) [15:02:46:198]: Doing action: MsiProcessDrivers
Action 15:02:46: MsiProcessDrivers.
Action start 15:02:46: MsiProcessDrivers.
MSI (s) (B4:C4) [15:02:46:213]: Note: 1: 2235 2: 3: ExtendedType 4: SELECT `Action`,`Type`,`Source`,`Target`, NULL, `ExtendedType` FROM `CustomAction` WHERE `Action` = 'MsiProcessDrivers'
MSI (s) (B4:F4) [15:02:46:229]: Invoking remote custom action. DLL: C:\WINDOWS\Installer\MSIB151.tmp, Entrypoint: ProcessDriverPackages
Action ended 15:02:46: MsiProcessDrivers. Return value 3.
MSI (s) (B4:C4) [15:02:46:276]: User policy value 'DisableRollback' is 0
MSI (s) (B4:C4) [15:02:46:276]: Machine policy value 'DisableRollback' is 0
MSI (s) (B4:C4) [15:02:46:307]: Executing op: Header(Signature=1397708873,Version=405,Timestamp=1010071559,LangId=1033,Platform=0,ScriptType=2,ScriptMajorVersion=21,ScriptMinorVersion=4,ScriptAttributes=1)
MSI (s) (B4:C4) [15:02:46:307]: Executing op: DialogInfo(Type=0,Argument=1033)
MSI (s) (B4:C4) [15:02:46:307]: Executing op: DialogInfo(Type=1,Argument=TheIDMakerSystem3)
MSI (s) (B4:C4) [15:02:46:307]: Executing op: RollbackInfo(,RollbackAction=Rollback,RollbackDescription=Rolling back
[/code]
You're right, there was more info in the log file I created (I was using the log file analyzer it turns out).
Unfortunately, I'm still not really able to make sense of what happened. Here is what I found before the rollback, and it's also includes the MsiProcessDrivers bit, but I don't see any "ERROR THIS HAPPENED" anywhere. Frankly even if I did I'm not sure I'd know what ot make of it.
Any ideas?
[code]
RegisterUser: Registering user
Action ended 15:02:41: RegisterUser. Return value 1.
MSI (s) (B4:C4) [15:02:41:916]: Doing action: RegisterProduct
Action 15:02:41: RegisterProduct. Registering product
Action start 15:02:41: RegisterProduct.
MSI (s) (B4:C4) [15:02:41:932]: Note: 1: 2205 2: 3: MsiDigitalSignature
RegisterProduct: Registering product
MSI (s) (B4:C4) [15:02:46:198]: PROPERTY CHANGE: Adding ProductToBeRegistered property. Its value is '1'.
Action ended 15:02:46: RegisterProduct. Return value 1.
MSI (s) (B4:C4) [15:02:46:198]: Doing action: PublishComponents
Action 15:02:46: PublishComponents. Publishing qualified components
Action start 15:02:46: PublishComponents.
PublishComponents: Component ID: Publishing qualified components, Qualifier:
Action ended 15:02:46: PublishComponents. Return value 1.
MSI (s) (B4:C4) [15:02:46:198]: Doing action: MsiProcessDrivers
Action 15:02:46: MsiProcessDrivers.
Action start 15:02:46: MsiProcessDrivers.
MSI (s) (B4:C4) [15:02:46:213]: Note: 1: 2235 2: 3: ExtendedType 4: SELECT `Action`,`Type`,`Source`,`Target`, NULL, `ExtendedType` FROM `CustomAction` WHERE `Action` = 'MsiProcessDrivers'
MSI (s) (B4:F4) [15:02:46:229]: Invoking remote custom action. DLL: C:\WINDOWS\Installer\MSIB151.tmp, Entrypoint: ProcessDriverPackages
Action ended 15:02:46: MsiProcessDrivers. Return value 3.
MSI (s) (B4:C4) [15:02:46:276]: User policy value 'DisableRollback' is 0
MSI (s) (B4:C4) [15:02:46:276]: Machine policy value 'DisableRollback' is 0
MSI (s) (B4:C4) [15:02:46:307]: Executing op: Header(Signature=1397708873,Version=405,Timestamp=1010071559,LangId=1033,Platform=0,ScriptType=2,ScriptMajorVersion=21,ScriptMinorVersion=4,ScriptAttributes=1)
MSI (s) (B4:C4) [15:02:46:307]: Executing op: DialogInfo(Type=0,Argument=1033)
MSI (s) (B4:C4) [15:02:46:307]: Executing op: DialogInfo(Type=1,Argument=TheIDMakerSystem3)
MSI (s) (B4:C4) [15:02:46:307]: Executing op: RollbackInfo(,RollbackAction=Rollback,RollbackDescription=Rolling back
[/code]
- Mark as New
- Subscribe
- Mute
- Permalink
- Report Inappropriate Content
‎Jan 21, 2010
08:59 AM
- Mark as New
- Subscribe
- Mute
- Permalink
- Report Inappropriate Content
‎Jan 21, 2010
11:26 AM
Hi,
It looks like this might actually be outright crashing here. There is a little bit of time that goes by when it tries to load the custom action *.dll:
15:02:46:229
15:02:46:276
But yet there's no output to speak of. Maybe check a few things:
--The inclusion of the MsiDriverPackages table in the MSI
--Perhaps perform validation against the MSI, and look for ICE errors
--Also, the problem might be with the *.inf file in the driver component. I might try installing the *.inf manually using DPInst.exe to see if this also gives problems.
It looks like this might actually be outright crashing here. There is a little bit of time that goes by when it tries to load the custom action *.dll:
15:02:46:229
15:02:46:276
But yet there's no output to speak of. Maybe check a few things:
--The inclusion of the MsiDriverPackages table in the MSI
--Perhaps perform validation against the MSI, and look for ICE errors
--Also, the problem might be with the *.inf file in the driver component. I might try installing the *.inf manually using DPInst.exe to see if this also gives problems.
- Mark as New
- Subscribe
- Mute
- Permalink
- Report Inappropriate Content
‎Jan 25, 2010
11:24 AM
Thank you!
I ended up running the "driver wizard" again, and including the INF file that I needed. After this, everything seems to be working!
I'm guessing there was a missing file somewhere.
I ended up running the "driver wizard" again, and including the INF file that I needed. After this, everything seems to be working!
I'm guessing there was a missing file somewhere.
- Mark as New
- Subscribe
- Mute
- Permalink
- Report Inappropriate Content
‎Jan 25, 2010
01:09 PM
bonus question (though this might deserve it's own thread)
I've now gotten my installer to work "properly" in XP, however I'm having some issues with Windows 7.
The installer seems to run all the way through, everything. I have two third party driver EXEs that run, files are copied, registry values seem to be added, etc, but then at the very end I get "rolling back"
I see error 1602 - "User Canceled"
and I also see
Note 1: 1708
Could this have something to do with my "custom actions" (which are basically running the third party EXE files I'm including on my install media)?
Thoughts?
Thank you so much!
[CODE]
...
Property(C): OutOfDiskSpace = 0
Property(C): OutOfNoRbDiskSpace = 0
Property(C): PrimaryVolumeSpaceAvailable = 0
Property(C): PrimaryVolumeSpaceRequired = 0
Property(C): PrimaryVolumeSpaceRemaining = 0
=== Logging stopped: 1/25/2010 12:34:59 ===
MSI (c) (DC:3C) [12:34:59:233]: Note: 1: 1708
MSI (c) (DC:3C) [12:34:59:233]: Product: Test Install -- Installation operation failed.
MSI (c) (DC:3C) [12:34:59:248]: Windows Installer installed the product. Product Name: Test Install. Product Version: 2.0.2. Product Language: 1033. Manufacturer: Test. Installation success or error status: 1602.
MSI (c) (DC:3C) [12:34:59:248]: Grabbed execution mutex.
MSI (c) (DC:3C) [12:34:59:248]: Cleaning up uninstalled install packages, if any exist
MSI (c) (DC:3C) [12:34:59:248]: MainEngineThread is returning 1602
=== Verbose logging stopped: 1/25/2010 12:34:59 ===
[/CODE]
I've now gotten my installer to work "properly" in XP, however I'm having some issues with Windows 7.
The installer seems to run all the way through, everything. I have two third party driver EXEs that run, files are copied, registry values seem to be added, etc, but then at the very end I get "rolling back"
I see error 1602 - "User Canceled"
and I also see
Note 1: 1708
Could this have something to do with my "custom actions" (which are basically running the third party EXE files I'm including on my install media)?
Thoughts?
Thank you so much!
[CODE]
...
Property(C): OutOfDiskSpace = 0
Property(C): OutOfNoRbDiskSpace = 0
Property(C): PrimaryVolumeSpaceAvailable = 0
Property(C): PrimaryVolumeSpaceRequired = 0
Property(C): PrimaryVolumeSpaceRemaining = 0
=== Logging stopped: 1/25/2010 12:34:59 ===
MSI (c) (DC:3C) [12:34:59:233]: Note: 1: 1708
MSI (c) (DC:3C) [12:34:59:233]: Product: Test Install -- Installation operation failed.
MSI (c) (DC:3C) [12:34:59:248]: Windows Installer installed the product. Product Name: Test Install. Product Version: 2.0.2. Product Language: 1033. Manufacturer: Test. Installation success or error status: 1602.
MSI (c) (DC:3C) [12:34:59:248]: Grabbed execution mutex.
MSI (c) (DC:3C) [12:34:59:248]: Cleaning up uninstalled install packages, if any exist
MSI (c) (DC:3C) [12:34:59:248]: MainEngineThread is returning 1602
=== Verbose logging stopped: 1/25/2010 12:34:59 ===
[/CODE]
- Mark as New
- Subscribe
- Mute
- Permalink
- Report Inappropriate Content
‎Jan 27, 2010
11:14 AM
Just to update the thread, I figured out how to enable logging in Windows 7 and I got a better, more helpful log.
First, in the MSI Log Report build by install shield log analyzer, I've got two errors (I believe these are the "simplified" version):
And then there is this gem:
Now, the CALLOGDRIVER in the first entry is a "custom action" that is calling a Logitech driver install file (exe). The install completes successfully, at least on the front end. The other CALLDRIVER file is calling a second EXE that is installing a different driver. Again, this seems to complete successfully on the front end of things.
Now, in the actual log log (the un-filtered, raw log) here is what I'm seeing:
[code]
DIFXAPP: INFO: ENTER: DriverPackageInstallW
MSI (s) (2C!18) [16:27:13:328]: Closing MSIHANDLE (5743) of type 790531 for thread 2840
MSI (s) (2C!18) [16:27:13:468]: Creating MSIHANDLE (5744) of type 790531 for thread 2840
DIFXAPP: WARNING:DRIVER_PACKAGE_LEGACY_MODE flag set but not supported on Plug and Play driver on VISTA. Flag will be ignored.
MSI (s) (2C!18) [16:27:13:468]: Closing MSIHANDLE (5744) of type 790531 for thread 2840
MSI (s) (2C!18) [16:27:17:244]: Creating MSIHANDLE (5745) of type 790531 for thread 2840
DIFXAPP: ERROR: One or more files referenced by 'C:\Program Files\Test\Test App\lvPRO5v\lvPRO5v.inf' cannot be found in the package.
MSI (s) (2C!18) [16:27:17:244]: Closing MSIHANDLE (5745) of type 790531 for thread 2840
MSI (s) (2C!18) [16:27:17:244]: Creating MSIHANDLE (5746) of type 790531 for thread 2840
DIFXAPP: INFO: RETURN: DriverPackageInstallW (0xE0000303)
MSI (s) (2C!18) [16:27:17:244]: Closing MSIHANDLE (5746) of type 790531 for thread 2840
MSI (s) (2C!18) [16:27:17:244]: Creating MSIHANDLE (5747) of type 790531 for thread 2840
DIFXAPP: ERROR encountered while installing driver package C:\Program Files\Test\Test App\lvPRO5v\lvPRO5v.inf
[/code]
Again a few things:
1) This same install runs through totally fine on Windows XP. I've checked the log file on a windows XP machine and I don't get the "DIFXAPP: ERROR:" anywhere in the log. Only on the Windows 7 machine do I get this error.
2) In Windows 7, the installer seems to make it all the way through the setup process until the very end. Icons are created, registry keys are written, etc.
3) I do believe this has to do with the Logitech exe installer that I run. I'm jut not sure how.
Thanks for any help! Even if you don't know how to fix the problem, a possible idea for a solution, or a way to trouble shoot, etc, would be great!
First, in the MSI Log Report build by install shield log analyzer, I've got two errors (I believe these are the "simplified" version):
InstallWelcome 4:17:24 PM 4:17:42 PM 18 seconds 1 - Success
EvaluateLic 4:17:34 PM 4:17:40 PM 6 seconds 1 - Success
CALLLOGDRIVER 4:17:42 PM 4:18:12 PM 30 seconds 1 - Success
CALLDRIVER 4:18:12 PM 4:24:28 PM 376 seconds 1 - Success
SetupProgress 4:24:28 PM 4:24:29 PM 1 seconds 1 - Success
SetODBCPath.9CED35E4_C9E6_11D3_9833_00A0C9DA4FE9 4:24:29 PM 4:24:29 PM 0 seconds 1 - Success
ExecuteAction 4:24:29 PM 4:27:46 PM 197 seconds 3 - Fatal Error
SetupCompleteError 4:27:46 PM 4:27:51 PM 5 seconds 2 - User Cancelled
And then there is this gem:
MsiProcessDrivers 4:26:16 PM 4:26:17 PM 1 seconds 1 - Success
MsiRollbackInstall 4:26:16 PM 4:26:17 PM 1 seconds 1 - Success
MsiInstallDrivers 4:26:16 PM 4:26:17 PM 1 seconds 1 - Success
MsiPublishAssemblies 4:26:17 PM 4:26:17 PM 0 seconds 1 - Success
PublishFeatures 4:26:17 PM 4:26:17 PM 0 seconds 1 - Success
PublishProduct 4:26:17 PM 4:26:17 PM 0 seconds 1 - Success
WriteKeycodeToRegistry.E9DEA130_0DC6_4047_8C57_2A204727CB81 4:26:17 PM 4:26:17 PM 0 seconds 1 - Success
InstallFinalize 4:26:17 PM 4:27:17 PM 60 seconds 3 - Fatal Error
Now, the CALLOGDRIVER in the first entry is a "custom action" that is calling a Logitech driver install file (exe). The install completes successfully, at least on the front end. The other CALLDRIVER file is calling a second EXE that is installing a different driver. Again, this seems to complete successfully on the front end of things.
Now, in the actual log log (the un-filtered, raw log) here is what I'm seeing:
[code]
DIFXAPP: INFO: ENTER: DriverPackageInstallW
MSI (s) (2C!18) [16:27:13:328]: Closing MSIHANDLE (5743) of type 790531 for thread 2840
MSI (s) (2C!18) [16:27:13:468]: Creating MSIHANDLE (5744) of type 790531 for thread 2840
DIFXAPP: WARNING:DRIVER_PACKAGE_LEGACY_MODE flag set but not supported on Plug and Play driver on VISTA. Flag will be ignored.
MSI (s) (2C!18) [16:27:13:468]: Closing MSIHANDLE (5744) of type 790531 for thread 2840
MSI (s) (2C!18) [16:27:17:244]: Creating MSIHANDLE (5745) of type 790531 for thread 2840
DIFXAPP: ERROR: One or more files referenced by 'C:\Program Files\Test\Test App\lvPRO5v\lvPRO5v.inf' cannot be found in the package.
MSI (s) (2C!18) [16:27:17:244]: Closing MSIHANDLE (5745) of type 790531 for thread 2840
MSI (s) (2C!18) [16:27:17:244]: Creating MSIHANDLE (5746) of type 790531 for thread 2840
DIFXAPP: INFO: RETURN: DriverPackageInstallW (0xE0000303)
MSI (s) (2C!18) [16:27:17:244]: Closing MSIHANDLE (5746) of type 790531 for thread 2840
MSI (s) (2C!18) [16:27:17:244]: Creating MSIHANDLE (5747) of type 790531 for thread 2840
DIFXAPP: ERROR encountered while installing driver package C:\Program Files\Test\Test App\lvPRO5v\lvPRO5v.inf
[/code]
Again a few things:
1) This same install runs through totally fine on Windows XP. I've checked the log file on a windows XP machine and I don't get the "DIFXAPP: ERROR:" anywhere in the log. Only on the Windows 7 machine do I get this error.
2) In Windows 7, the installer seems to make it all the way through the setup process until the very end. Icons are created, registry keys are written, etc.
3) I do believe this has to do with the Logitech exe installer that I run. I'm jut not sure how.
Thanks for any help! Even if you don't know how to fix the problem, a possible idea for a solution, or a way to trouble shoot, etc, would be great!
