The end-user just called you and stated that no matter how many times he keeps trying, the result is pretty much the same.

Ok, so it seems that the suggestion is not good enough. What can you do if all you have is this error message and a complaining user? Well, there is often a log file of some kind which you should be able to open up and correlate the error occurrences with some kind of a timestamp. Looking at the Event Viewer events is also a good first stop in case some relevant message is logged for that matter.

As a troubleshooter, though, you do not want to rely upon the unpredictability of those sources of data as far as your problem is concerned. You should be able to open your bag of tools and start digging in until you find the root cause. Depending on the nature of applications and technologies under your scope, this bag of tools may vary a lot. Let me describe my approach for this particular issue.

After figuring out that no additional information was being logged anywhere, I used the good ol’ Process Monitor and asked the user to reproduce the issue, as it happened every time.

Let’s follow the trace and try figuring out what was happening:

Rel. Time

Proc. Name

Operation

Path

Result

01.9671915

w3wp.exe

CreateFile

C:\WINDOWS\Help\iisHelp\common\401-1.htm

SUCCESS

01.9678824

w3wp.exe

QueryInformationVolume

C:\WINDOWS\Help\iisHelp\common\401-1.htm

SUCCESS

01.9679407

w3wp.exe

QueryAllInformationFile

C:\WINDOWS\Help\iisHelp\common\401-1.htm

BUFFER OVERFLOW

01.9682644

w3wp.exe

QueryStandardInformationFile

C:\WINDOWS\Help\iisHelp\common\401-1.htm

SUCCESS

01.9683613

w3wp.exe

ReadFile

C:\WINDOWS\Help\iisHelp\common\401-1.htm

SUCCESS

01.9697481

w3wp.exe

CloseFile

C:\WINDOWS\Help\iisHelp\common\401-1.htm

SUCCESS

At this stage, the worker process was loading this 401-1.htm file, so this was probably during the security handshake in which there is a credentials challenge and response process. No harm done here, eventually the credentials are accepted and the request proceeds.

Rel. Time

Proc. Name

Operation

Path

Result

02.0237073

w3wp.exe

RegOpenKey

HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo

SUCCESS

02.0238711

w3wp.exe

RegQueryValue

HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo\SRV09

NAME NOT FOUND

02.0239593

w3wp.exe

RegCloseKey

HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\ConnectTo

SUCCESS

02.0247650

w3wp.exe

RegOpenKey

HKLM\SOFTWARE\Microsoft\MSSQLServer\Client

SUCCESS

02.0248472

w3wp.exe

RegQueryValue

HKLM\SOFTWARE\Microsoft\MSSQLServer\Client\SharedMemoryOn

SUCCESS

02.0249054

w3wp.exe

RegCloseKey

HKLM\SOFTWARE\Microsoft\MSSQLServer\Client

SUCCESS

There you go, the request is being processed. Apparently, the worker process is now trying to connect to a SQL Server instance in a server named SRV09. If you’re not acquainted with the solution architecture, this is a good clue of where the data is being stored and retrieved from.

Next I had to scroll down a bit as there were tons of MUI-related events which do not add much. And then, I found these 3 lines:

Rel. Time

Proc. Name

Operation

Path

Result

02.0526899

w3wp.exe

CreateFile

C:\Program Files\Common Files\Microsoft Shared\web server extensions\60\BIN\2070

SUCCESS

02.0538345

w3wp.exe

QueryDirectory

C:\Program Files\Common Files\Microsoft Shared\web server extensions\60\BIN\2070\fpext.msg

SUCCESS

02.0539189

w3wp.exe

CloseFile

C:\Program Files\Common Files\Microsoft Shared\web server extensions\60\BIN\2070

SUCCESS

Something must have gone wrong within those 30 milliseconds.

Let’s see what follows:

Rel. Time

Proc. Name

Operation

Path

Result

02.0771572

w3wp.exe

RegQueryKey

HKU\S-1-5-21-1715567821-1682526488-682003330-3472_CLASSES

SUCCESS

02.0772552

w3wp.exe

RegOpenKey

HKU\S-1-5-21-1715567821-1682526488-682003330-3472_CLASSES\CLSID\{0C7FF16C-38E3-11D0-97AB-00C04FC2AD98}\ExtendedErrors

NAME NOT FOUND

02.0773562

w3wp.exe

RegOpenKey

HKCR\CLSID\{0C7FF16C-38E3-11D0-97AB-00C04FC2AD98}\ExtendedErrors

SUCCESS

02.0775303

w3wp.exe

RegQueryKey

HKCR\CLSID\{0C7FF16C-38E3-11d0-97AB-00C04FC2AD98}\ExtendedErrors

SUCCESS

02.0776561

w3wp.exe

RegOpenKey

HKCU\Software\Classes\CLSID\{0C7FF16C-38E3-11d0-97AB-00C04FC2AD98}\ExtendedErrors

NAME NOT FOUND

02.0777314

w3wp.exe

RegEnumKey

HKCR\CLSID\{0C7FF16C-38E3-11d0-97AB-00C04FC2AD98}\ExtendedErrors

SUCCESS

02.0779244

w3wp.exe

RegCloseKey

HKCR\CLSID\{0C7FF16C-38E3-11d0-97AB-00C04FC2AD98}\ExtendedErrors

SUCCESS

Indeed, something has gone wrong... Where? Well, this HKCR\CLSID\{0C7FF16C-38E3-11d0-97AB-00C04FC2AD98} is the SQLOLEDB CLSID, meaning that we can move on to SQL Server and figure out what is going on there.

By moving on to SQL Server, I mean starting a SQL Server trace on this SRV09, ensuring that OLEDB Errors is selected, as well as those basic events you’ll find in the usual templates concerning the SQL Statements execution.

Weird: according to http://technet.microsoft.com/en-us/library/cc917589.aspx, this exception stands for Too many arguments were supplied for procedure %. *ls, something we would not expect to happen in a Windows SharePoint Services/SQL Server environment. Anyway, by checking the statement which starts before the exception and gets completed immediately after it, we saw that the call did not really match the Stored Procedure signature.

In particular, the SP was expecting fewer parameters, thus the exception above. Given this mismatch, I suspected of an incomplete WSS patching or update, a plausible reason for this, as the code might have been changed along with the database schema and Stored Procedure implementation. Bulls-eye!! A few weeks before, this particular WSS server had been applied the latest Service Pack, and apparently that did not succeed, but no one noticed until this user tried to add a new field to a list.

See? No logs, no events, no hands on the steering wheel, just valuable information popping out of these great tools...

Regards,

Manuel Oliveira