The SQL Dude!

I was recently working on an interesting setup issue with one of our Premier customers. The scenario was this – they were trying to patch their SQL Server 2008 R2 instance with SP1 (KB 2528583) and it was failing, but the log files were not getting generated fully. In fact, the path C:\Program Files\Microsoft SQL Server\100\Setup Bootstrap\log\ did not even have a folder with the latest timestamp. Interestingly, the log files were getting created on the D: drive location D:\Program Files\Microsoft SQL Server\100\Setup Bootstrap\log\

From D:\Program Files\Microsoft SQL Server\100\Setup Bootstrap\log\ folder we could only find Summary.txt and Detail.txt

Summary.txt

Overall summary:
  Final result:                  The patch installer has failed to update the following instance: MSSQLSERVER. To determine the reason for failure, review the log files.
  Exit code (Decimal):           1513770790
  Exit message:                  The patch installer has failed to update the following instance: MSSQLSERVER. To determine the reason for failure, review the log files.
  Start time:                    2012-11-18 00:54:46
  End time:                      2012-11-18 01:21:23
  Requested action:              Patch

Requested action:              Patch
Log with failure:              C:\Program Files\Microsoft SQL Server\100\Setup Bootstrap\Log\20121118_005431\MSSQLSERVER\SQLSysClrTypes_Cpu64_1.log
Exception help link:           http://go.microsoft.com/fwlink?LinkId=20476&ProdName=Microsoft+SQL+Server&EvtSrc=setup.rll&EvtID=50000&ProdVer=10.50.2500.0

Note the highlighted link and that log file were not present at all!

Detail.txt

Every feature that was trying get patched logs this error –> MSI Error 1622. 1622 stands for ERROR_INSTALL_LOG_FAILURE, which means the setup program is not able to log setup messages to the log file and hence failed.

Reference: http://msdn.microsoft.com/en-us/library/windows/desktop/aa368542(v=vs.85).aspx

2012-11-18 00:56:46 Slp: Target package: "g:\c6d70a3c67aacef9d9eff6019ffaf3\1033_ENU_LP\x64\setup\sqlsupport_msi\SqlSupport.msi"
2012-11-18 00:56:46 Slp: InstallPackage: MsiInstallProduct returned the result code 1622.
2012-11-18 00:56:46 Slp: Watson Bucket 1

2012-11-18 01:03:00 Slp: Target package: "g:\c6d70a3c67aacef9d9eff6019ffaf3\1033_ENU_LP\x64\setup\x64\sqlncli.msi"
2012-11-18 01:03:00 Slp: InstallPackage: MsiInstallProduct returned the result code 1622.
2012-11-18 01:03:00 Slp: Watson Bucket 5

I search for the keyword “at microsoft” to find exception stack and I see this error was raised at the end

2012-11-18 01:21:19 Slp: Result error code: 1622
2012-11-18 01:21:19 Slp: Sco: Attempting to create base registry key HKEY_LOCAL_MACHINE, machine
2012-11-18 01:21:19 Slp: Sco: Attempting to open registry subkey
2012-11-18 01:21:19 Slp: Sco: Attempting to open registry subkey Software\Microsoft\PCHealth\ErrorReporting\DW\Installed
2012-11-18 01:21:19 Slp: Sco: Attempting to get registry value DW0201
2012-11-18 01:21:21 Slp: Received request to add the following file to Watson reporting: C:\Users\EGP00\AppData\Local\Temp\2\tmpC720.tmp
2012-11-18 01:21:21 Slp: The following is an exception stack listing the exceptions in outermost to innermost order
2012-11-18 01:21:21 Slp: Inner exceptions are being indented
2012-11-18 01:21:21 Slp:
2012-11-18 01:21:21 Slp: Exception type: System.IO.DirectoryNotFoundException
2012-11-18 01:21:21 Slp:     Message:
2012-11-18 01:21:21 Slp:         Could not find a part of the path ‘C:\Program Files\Microsoft SQL Server\100\Setup Bootstrap\Log\20121118_005431\MSSQLSERVER’.
2012-11-18 01:21:21 Slp:     Stack:
2012-11-18 01:21:21 Slp:         at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
2012-11-18 01:21:21 Slp:         at System.IO.Directory.InternalGetFileDirectoryNames(String path, String userPathOriginal, String searchPattern, Boolean includeFiles, Boolean includeDirs, SearchOption searchOption)
2012-11-18 01:21:21 Slp:         at System.IO.DirectoryInfo.GetFiles(String searchPattern, SearchOption searchOption)
2012-11-18 01:21:21 Slp:         at Microsoft.SqlServer.Chainer.Infrastructure.WatsonMsiBucket.ExecutePreCabTasks()
2012-11-18 01:21:21 Slp:         at Microsoft.SqlServer.Chainer.Infrastructure.WatsonService.ReportFailures()
2012-11-18 01:21:21 Slp:         at Microsoft.SqlServer.Chainer.Setup.Setup.Start()
2012-11-18 01:21:21 Slp:         at Microsoft.SqlServer.Chainer.Setup.Setup.Main()
2012-11-18 01:21:21 Slp: Watson Bucket 17

The above message is strange since the path clearly exists and some log files are getting created there, but no the one with the failure. From a admin perspective, while this error is being logged, if you look at the setup screen you will see it frozen at this stage (MsiTimingAction),

To make progress on this, I decided to troubleshoot the log file generation, and why the log files are created on the D: drive.

On a Windows system, the Program Files and Program Files (x86) paths are hard-coded and are set as part of the environment for each program. To open the current program files location, one can just go to Run and type in %programfiles% and hit enter. When I did this on my customer’s machine, it opened up the D:\Program Files path. Now, we’re getting somewhere.

These paths are also stored in the registry location HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion, as shown below.

On this machine it was pointing to the D: drive and hence the log files were going there. But some of the log files, were expecting this to always be the C:\ location and hence failing. This explains the log file location mystery.

The solution was fairly simple from here on, since the location of the ProgramFiles cannot be configured and changing it is not supported as per http://support.microsoft.com/kb/933700

I changed the location back to the default value by editing the registry under [HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion]

ProgramFilesDir         –> C:\Program Files
ProgramFilesDir (x86) –> C:\Program Files (x86)

You can also make this change for a specific user profile by adding a User Environment Variable called “ProgramFiles” and setting its value to the path of the program files dir.

After changing the registry key value, I rebooted for good measure (though I think a logoff and logon should suffice). Now, when I go to Run and do %programfiles% it takes me to the C: drive as expected.

Re-ran the SP1 for SQL Server and it completed fine without issues and the log files were also getting created in the default path

Just thought I’d share this issue since its an example of how system misconfiguration or issues outside of SQL can have an impact of setup and patching.