PDA

View Full Version : Two errors in logfile: MsiProcessDrivers and ExecuteAction



kmitchell
01-20-2010, 03:47 PM
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...


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

kmitchell
01-20-2010, 04:38 PM
I just looked through the actual logfile (as apposed to the report that IS2008 gives) and this is what I found:



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.

Cary R
01-20-2010, 06: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).

kmitchell
01-21-2010, 08: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?



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

kmitchell
01-21-2010, 09:59 AM
<edit> oops, I didn't realize messages were moderated so long, I double posted. </edit>

Cary R
01-21-2010, 12:26 PM
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.

kmitchell
01-25-2010, 12:24 PM
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.

kmitchell
01-25-2010, 02: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!



...
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 ===

kmitchell
01-27-2010, 12:14 PM
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):


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:



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



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!