Read a Deployment Tool MSI Log
Every time that the Deployment Tool runs a Microsoft Windows Installer (MSI) either to install or uninstall a component, it always generates a log file and stores it in the ConfigShare\Log directory. The file name is in the following format:
<MSIName> on <ServerName> <Date>_<Time>.log
The log file is generated by using the MSIExec command-line switch /l*v! which approximately translates everything to log. This results in very long log files that are difficult to read. This section describes how to read Deployment Tool generated MSI logs.
Start by scrolling to the very bottom to find a summary of the MSI running log. The summary can help you determine what you are looking at, as shown in the following example:
... === Logging stopped: 2/24/2006 12:44:33 === MSI (s) (74:A8) [12:44:33:444]: Note: 1: 1708 MSI (s) (74:A8) [12:44:33:484]: Product: Microsoft Provisioning Framework Enterprise Edition -- Installation operation failed. MSI (s) (74:A8) [12:44:33:825]: Cleaning up uninstalled install packages, if any exist MSI (s) (74:A8) [12:44:33:875]: MainEngineThread is returning 1603 MSI (s) (74:D8) [12:44:33:935]: Destroying RemoteAPI object. MSI (s) (74:AC) [12:44:33:965]: Custom Action Manager thread ending. MSI ©) (1C:B8) [12:44:34:025]: Decrementing counter to disable shutdown. If counter >= 0, shutdown will be denied. Counter after decrement: -1 MSI ©) (1C:B8) [12:44:34:065]: MainEngineThread is returning 1603 === Verbose logging stopped: 2/24/2006 12:44:34 ===All this really tells that the installation of the Microsoft Provisioning Framework Enterprise Edition failed. To determine more, we must find the actual point of failure in the log.
Directly above this summary is a long list of Property(S). These are rarely helpful in determining what is wrong, so we have to look to the lines directly above this list of Property(S). In the sample below, we can see that the installation Action ended with a Return value 3.
... Action ended 12:44:21: INSTALL. Return value 3. Property(S): ProductName = Microsoft Provisioning Framework Enterprise Edition Property(S): ProductVersion = 13.3.0609.0005 Property(S): Manufacturer = Microsoft Corporation ... Property(S): MPF_CONTOLRAPI_ACCESS_ACL = D:(A;;0x0100;;;S-1-5-21-1862170175-426256359-1674568132-1119) ... === Logging stopped: 2/24/2006 12:44:33 ===This Return value is important and will be used later. The lines directly above the return value are related to a rollback operation (the failed installation is being rolled back), as shown in the following sample:
MSI (s) (74:A8) [12:44:18:703]: Executing op: FolderRemove(Folder=C:\Program Files\Microsoft Provisioning\Tools\Admin\,Foreign=0) MSI (s) (74:A8) [12:44:18:753]: Executing op: FolderRemove(Folder=C:\Program Files\Microsoft Provisioning\Core\,Foreign=0) ... MSI (s) (74:A8) [12:44:19:354]: Executing op: RegRemoveValue(Name=C:\WINDOWS\system32\msvcp60.dll,Value=#+,) ... MSI (s) (74:A8) [12:44:21:367]: Executing op: ComponentUnregister(ComponentId={C0CB73DE-ACE6-4A6F-97E0-A514BFE0A199},ProductKey={450F69CF-9A86-494E-949A-B5C18DE5D46D},BinaryType=0,) MSI (s) (74:A8) [12:44:21:407]: Executing op: End(Checksum=0,ProgressTotalHDWord=0,ProgressTotalLDWord=0) MSI (s) (74:A8) [12:44:21:447]: Error in rollback skipped. Return: 5 MSI (s) (74:A8) [12:44:21:507]: No System Restore sequence number for this installation. MSI (s) (74:A8) [12:44:21:547]: Unlocking Server MSI (s) (74:A8) [12:44:21:588]: PROPERTY CHANGE: Deleting UpdateStarted property. Its current value is '1'. Action ended 12:44:21: INSTALL. Return value 3.Search up the log for any other instances of the string "Return value 3". Almost 500 lines above the "Action ended..." line, we find the following:
Action start 12:43:41: MapsRunSQLScripts. MSI (s) (74:9C) [12:43:41:751]: Invoking remote custom action. DLL: C:\WINDOWS\Installer\MSI7ED.tmp, Entrypoint: MapsRunSQLScripts Entering CustomAction MapsRunSQLScripts ((INFO)) RunSQLScript: Precondition: (&MapsTranLogFeature=2) AND (MPF_IS_VALID_CONFIGDB<>"0") failed (SQL script #1). Skip to next SQL script. ((INFO)) RunSQLScript: Precondition: (&MapsAuditFeature=2) AND (MPF_IS_VALID_CONFIGDB<>"0") failed (SQL script #2). Skip to next SQL script. ((INFO)) RunSQLScript: Precondition: (&MapsConfigFeature=3) AND (&MapsConfigDirsFeature=3) failed (SQL script #100). Skip to next SQL script. ((INFO)) RunSQLScript: Running SQL script #101 ((INFO)) RunSQLScript: Precondition: (&MapsConfigFeature=3) AND (UPGRADE=2) failed (SQL script #102). Skip to next SQL script. ((INFO)) RunSQLScript: Running SQL script #103 ((INFO)) RunSQLScript: Running SQL script #104 ((INFO)) RunSQLScript: Running SQL script #106 ((INFO)) RunSQLScript: Precondition: (&MapsTranLogFeature=3) AND (&MapsTranLogDirsFeature=3) failed (SQL script #110). Skip to next SQL script. ((INFO)) RunSQLScript: Running SQL script #111 ((INFO)) RunSQLScript: Precondition: (&MapsTranLogFeature=3) AND (UPGRADE=2) failed (SQL script #112). Skip to next SQL script. ((INFO)) RunSQLScript: Running SQL script #113 ((INFO)) DumpErrorInfo: HRESULT: 80040e14 ((INFO)) DumpErrorInfo: SQLSTATE: 42000 Native Error: 215 ((INFO)) DumpErrorInfo: Error state: 1 Severity: 16 ((INFO)) DumpErrorInfo: Source: Microsoft OLE DB Provider for SQL Server ((INFO)) DumpErrorInfo: Error message: Parameters supplied for object 'BM_ParentBatches' which is not a function. If the parameters are intended as a table hint, a WITH keyword is required. ((INFO)) DumpErrorInfo: HRESULT: 80040e14 ((INFO)) DumpErrorInfo: SQLSTATE: 42S22 Native Error: 207 ((INFO)) DumpErrorInfo: Error state: 1 Severity: 16 ((INFO)) DumpErrorInfo: Source: Microsoft OLE DB Provider for SQL Server ((INFO)) DumpErrorInfo: Error message: Invalid column name 'updlock'. ((INFO)) DumpErrorInfo: HRESULT: 80040e14 ((INFO)) DumpErrorInfo: SQLSTATE: 42S22 Native Error: 207 ((INFO)) DumpErrorInfo: Error state: 1 Severity: 16 ((INFO)) DumpErrorInfo: Source: Microsoft OLE DB Provider for SQL Server ((INFO)) DumpErrorInfo: Error message: Invalid column name 'rowlock'. ((ERROR)) ExecTSQLCommand: There was an error executing the command, hr=0x80040e14 MSI (s) (74!44) [12:44:01:028]: Product: Microsoft Provisioning Framework Enterprise Edition -- ((ERROR)) ExecTSQLCommand: There was an error executing the command, hr=0x80040e14 ((INFO)) GetAdditionalErrorInfo: No additional error information ((ERROR)) FixApplySQLScript: Error executing SQL command, hr=0x80040e14 MSI (s) (74!44) [12:44:01:148]: Product: Microsoft Provisioning Framework Enterprise Edition -- ((ERROR)) FixApplySQLScript: Error executing SQL command, hr=0x80040e14 ((ERROR)) RunSQLScript: ApplySQLScript #113 failed., hr=0x80040e14 MSI (s) (74!44) [12:44:01:419]: Product: Microsoft Provisioning Framework Enterprise Edition -- ((ERROR)) RunSQLScript: ApplySQLScript #113 failed., hr=0x80040e14 ((INFO)) GetAdditionalErrorInfo: No additional error information ((ERROR)) MapsRunSQLScripts: MapsRunSQLScripts failed., hr=0x80040e14 MSI (s) (74!44) [12:44:01:509]: Product: Microsoft Provisioning Framework Enterprise Edition -- ((ERROR)) MapsRunSQLScripts: MapsRunSQLScripts failed., hr=0x80040e14 ((ERROR)) MapsRunSQLScripts: FAILED, hr=0x80040e14 MSI (s) (74!44) [12:44:01:599]: Product: Microsoft Provisioning Framework Enterprise Edition -- ((ERROR)) MapsRunSQLScripts: FAILED, hr=0x80040e14 Action ended 12:44:01: MapsRunSQLScripts. Return value 3.Here we will find the real source of the problem which in this case was related to trying to install the MPF Databases on to a server running SQL 2005. This will fail for any build of MPF earlier than version 2.2. This is indicated by the syntax errors running the SQL Scripts.
Another line in the MSI log that is sometimes of value is the Command Line. In the previous example, the lines that the command line passed to MSIExec looked as follows:
MSI (s) (74:A8) [12:41:59:184]: Command Line: UNATTENDED=1 MPF_IMPERSONATE=1 MPFRMLOG=1 LISTENER_IS_DEPENDENT_ON_SQL=no RM_SERVER=SQL01-RAD MPF_AUDIT_SERVER=SQL01-RAD MPFAUDIT=1 MPFCONFIG=1 MPFSVCPASSWORD=********** MPF_TRANLOG_SERVER=SQL01-RAD MPF_CONFIG_SERVER=SQL01-RAD DEPLOY_PDB=0 MPF_DOMAIN_INSTALL=1 MPFTRANLOG=1 MPF_LISTENER_SERVER=SQL01-RAD MPFADMIN=1 BATCH_IS_DEPENDENT_ON_SQL=no CURRENTDIRECTORY=C:\WINDOWS\system32 CLIENTUILEVEL=3 CLIENTPROCESSID=3868