Craig Box's journeys, stories and notes...

Archive for December, 2007

Debugging w3wp.exe and IIS application pools

Saturday, December 29th, 2007

Problem: after hitting "Login" on an ASP.NET web application on IIS6, w3wp.exe races to high CPU usage, and about 70MB of memory. CPU usage falls off, but memory usage increases a few KB every second. No indication is made that the application has crashed or hung, no output.

The first utility I installed to check this out was IISTracer. Ignore the horrible web site - this is a nice little utility which lets you see what requests IIS is currently serving. In this instance the default.aspx page calls a dashboard.aspx, which was timing out indefinitely without returning a response to the client.

There are a number of utilities you can use to debug IIS faults. David Wang's guide on how to understand and diagnose an application pool crash gives some insight into how it should be done - attach a debugger and wait for the fault, then look at the stack trace. His suggestions include IISState, an IIS resource kit utility, which will give you an output of the current state of an IIS process; and DebugDiag, a much nicer and newer interactive debugger for IIS.

I spent a couple of days playing with DebugDiag, and unfortunately, due to the nature of my problem, I couldn't get anything useful. It seems that the application wasn't ever actually crashing or hanging - states that DebugDiag should be able to deal with easily. IISState, on the other hand, suggested I was regularly getting first chance exceptions thrown. A first chance exception means an exception has been raised - if the application handles it, then nothing more is mentioned, else it becomes a second chance exception, and the debugger or system exception handler is called). So, more digging was required.

WinDbg, the Windows DebuggerEnter the Windows debug tools, and specifically WinDbg. This is what the professionals use, and as such, it's ultimately powerful and incredibly scary. It's updated regularly, except for the interface, which is nicest described as "circa-1990".

There are a number of blogs that mention running WinDbg, but none that actually put together all the pieces on how to debug this kind of problem. So here's my story for you.

First, attach the debugger to your w3wp.exe process. I found it's process ID in Task Manager - you need to add the PID column. At this point, I get a breakpoint hit - you might not, so use Debug/Break or Ctrl-Break to stop the program.

Debugging symbols let you see not just the memory location of a failure, but the name of the function that it is in. They are not normally included with release software as they make it a lot larger, but can be downloaded separately in this case. DebugDiag is friendly and will automatically download appropriate debugging symbols for you from Microsoft's symbol server, and put them in c:\symcache\. WinDbg is less friendly and requires you set this up yourself. I used the same path, as I already had some symbols downloaded - I told WinDbg to look at the local symbols first, and look at the online symbol server if they're not already cached there. Do this like so:

.sympath SRV*c:\symcache*http://msdl.microsoft.com/download/symbols

Now, we need to load the SOS debugger helper, which lets you debug managed code in WinDbg (Nerd note: SOS stands for Son of Strike, which is a Microsoft in-joke.) If you started the process inside the debugger, you can apparently do this:

0:033> .loadby mscorlib sos
Unable to find module 'sos'

I couldn't, so I'll do this:

0:033> .load C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\SOS.dll

If you're running .NET 1.1, you can .load clr10\sos.dll for the version shipped with the debugger.

Now, we instruct it to break whenever there is an exception thrown:

0:033> sxe CLR

And hit Debug/Go, type 'g and hit Enter, or hit F5 to resume the program.

No sooner than I hit 'g', we get results!

0:033> g
(a78.8b4): CLR exception - code e0434f4d (first chance)
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
eax=0230ec7c ebx=000d9c50 ecx=00000000 edx=00000024 esi=0230ed08 edi=e0434f4d
eip=77e4bee7 esp=0230ec78 ebp=0230eccc iopl=0         nv up ei pl nz na po nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00200202
kernel32!RaiseException+0x3c:
77e4bee7 5e              pop     esi

I don't speak assembly and really have no desire to. Thankfully the SOS extension lets us look at the exception, and the call stack (the list of functions that we called to get where we are). Type !pe to print the exception, and !clrstack to see the call stack.

0:012> !pe
Exception object: 048f8a4c
Exception type: System.Data.SqlClient.SqlException
Message: Cannot open database requested in login 'R622P1Sy1'. Login fails.
Login failed for user 'admin'.
InnerException: <none>
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 80131904
0:012> !clrstack
OS Thread Id: 0x8b4 (12)
ESP       EIP
0230ed54 77e4bee7 [HelperMethodFrame: 0230ed54]
0230edf8 6539bf14 System.Data.SqlClient.SqlInternalConnection.OnError(System.Data.SqlClient.SqlException, Boolean)
0230ee0c 652f695d System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(System.Data.SqlClient.TdsParserStateObject)
0230ee3c 652f79e5 System.Data.SqlClient.TdsParser.Run(System.Data.SqlClient.RunBehavior, System.Data.SqlClient.SqlCommand, System.Data.SqlClient.SqlDataReader, System.Data.SqlClient.BulkCopySimpleResultSet, System.Data.SqlClient.TdsParserStateObject)
0230ee90 652e932a System.Data.SqlClient.SqlInternalConnectionTds.CompleteLogin(Boolean)

And there's the problem. A first-class exception is handled trying to connect to a database with incorrect login details, so it continues, probably never freeing the memory from the last connection. This particular exception doesn't get logged and doesn't get displayed on screen (probably because it's being loaded in the background) and causes an infinite timeout. Oops!

Armed with a little knowledge about the debugging tools, it's easy to see what's going on inside your code, even if it's running in IIS.

Tags: , , ,
Posted in Technical, Work | 3 Comments »

Niagara Falls

Monday, December 24th, 2007

Winter really isn't the time to visit, although I was advised it was worthwhile because you'd still see the mist.  It takes a fairly long and determined walk to get to it from the car park.

Niagara Falls - In The Dark

The shiny building is in the US of A, who really got shafted by the river.  The falls can really only be seen from the Canadian side.

Retrospectively, it might have been a bad weekend to go...

img_3214-small.jpg

I believe this used to be a thriving butterfly conservatory. Not today.

Oh well. We had a nice stay at the Sheraton Fallsview (with a great view of the mist) and can tick it off the list until summer, where it will require renewed attention.

We also stopped off at the thriving metropolis of Hamilton, Ontario, on the (very slow) drive home. This is the central mall on the Sunday afternoon - but I guess you can expect it to be quiet. After all, it's only 9 days until Christmas...

Hamilton, a mecca of industry.

Tags:
Posted in Personal | No Comments »

Parsing quotes in cmd.exe

Monday, December 24th, 2007

The Microsoft world can be horribly inconsistent. Take escaping a quote character:

  • "" in VB and SQL Server
  • \" in C++/C#
  • Unless you use a @ symbol first, in which case you have to use "" as \ won't be interpreted as an escape character

It never seemed at all you could escape characters on a command line. Until, of course, you go to do something like this:

rem xcopy is old, let's not use it any more
rem the backslash on the end of bar tells xcopy
rem that it's a directory, not a file, it's copying to
rem
rem xcopy /e "C:\foo\" "C:\bar\"
robocopy "C:\foo" "C:\bar\" /e /x "Extra Options"

Whereupon the much newer program parses the output as follows:

source=C:\foo
destination=C:\bar" /e /x "Extra Options"

This is a problem with anything that uses the .NET framework also. Watch your trailing slashes!

Tags: ,
Posted in Technical, Work | No Comments »

C#: How to tell if an IIS metabase property is inherited

Monday, December 24th, 2007

How can you tell, using managed code, if an IIS metabase property is inherited?

Scenario: I am using System.DirectoryServices to manage the IIS configuration (known as the "metabase", and stored in an XML file). I want to remove a property on a metabase node, but only if it is explicitly set here. This allows me to inherit the correct value from up the tree.

First attempt:

if (dirEntry.Properties["AnonymousUserName"].Count > 0) {
    dirEntry.Properties["AnonymousUserName"].Clear();
    Console.WriteLine("Log: Local value found for AnonymousUserName, removing");
}

My assumption was that this would remove the entry the first time, if it exists, and ignore it every time afterwards. However, every time it runs, Count is 1 and the property appears set.

It turns out that the Properties method on a DirectoryEntry object shows all the properties, including ones that are set on parent items in the tree.

How can we see only items that are defined on this particular node? This problem shows up all over the Internet with no solution. However, Microsoft's David Wang isn't one to leave a newsgroup question unanswered:

Never tried it in .Net, but with ADSI you can determine this.
Set objNode = GetObject( "IIS://foo/W3SVC" & "/" & "AppPools/AnAppPool" )
Set objNodeAttribute = objNode.GetPropertyAttribObj( "WamUserName" )
If ( objNodeAttribute.IsInherit = true ) Then
End If

I just needed a way to run GetPropertyAttribObj from C#, which was a much easier problem to solve. There were only a couple of relevant hits, the best one being some abandoned Pastebin code in Google's cache.

We now have an answer:

/// <summary>
/// Establish if a metabase property is set explicitly on this node.
/// </summary>
/// <param name="iisNode">Metabase node</param>
/// <param name="propertyName">Property name</param>
/// <returns>True if the property is defined on this node explicitly; false if the property is not defined at all, or is inherited.</returns>
private static bool PropertyDefinedExplicitly(DirectoryEntry iisNode, String propertyName)
{

    // check 1. this node has a valid key-type, and 2. it contains the required property
    if (iisNode.Properties.Contains("KeyType") &&
    iisNode.Properties["KeyType"].Value.ToString().Length > 0 &&
    iisNode.Properties.Contains(propertyName))
    {

        // call ADSI GetPropertyAttribObject method directly
        Object propertyAttributes = iisNode.Invoke("GetPropertyAttribObj",
        new String[] { propertyName });
        IISOle.IISPropertyAttribute attributes =
        (IISOle.IISPropertyAttribute)propertyAttributes;

        // Isinherit will be set if the property is inherited
        if (attributes.Isinherit)
        {
            return false; // property was inherited
        }
        else
        {
            return true; // property explicitly defined on this node
        }

    }
    else
    {
        return false; // not a valid IIsObject node, or property not found
    }
}

We then rewrite the original function like so:

if (PropertyDefinedExplicitly(dirEntry, "AnonymousUserName")) {
    dirEntry.Properties["AnonymousUserName"].Clear();
    Console.WriteLine("Log: Local value found for AnonymousUserName, removing");
}

There is a lesson to learn here for Windows programmers: Microsoft support is in the newsgroups. Don't fear Usenet because it's older than you are!

With useful tips like this, I'll win the NZ .NET blog of the year for sure!

Tags: , ,
Posted in Technical, Work | No Comments »

Querying the status of a Windows service

Friday, December 7th, 2007

An interesting puzzle presented itself to me at work yesterday. We have some code called from an ASP.NET application, which queries the status of a service. This works fine when you run the application pool as NetworkService, but if you run it as the IWAM_SERVERNAME user that is created for running IIS processes, it would fail.

I wrote a console application with exactly the same code that the ASP.NET application used, and it worked fine.

Interesting aside: you can find the password for the IWAM_SERVERNAME user by using the Metabase Explorer from the IIS 6 Resource Kit. It's under the Server/LM/W3SVC node as WAMUserPass, and you have to enable "View/Secure Data" to see it. Then, use runas /user:iwam_servername cmd.exe, and enter in the password from the metabase.

Why? Well, surely it must just be some kind of permissions issue, not the Winter Madness.

What can't be done with subinacl isn't worth doing, so I pulled it out and had a look at the service. Here's the important part:

/pace =interactive      ACCESS_ALLOWED_ACE_TYPE-0x0
        SERVICE_QUERY_CONFIG-0x1           SERVICE_QUERY_STATUS-0x4           SERVICE_ENUMERATE_DEPEND-0x8
        SERVICE_INTERROGATE-0x80           READ_CONTROL-0x20000               SERVICE_USER_DEFINED_CONTROL-0x0100

(People finding this useful post via search will want to read the full subinacl output.)

Turns out an interactive user can query a server status, but IIS doesn't run interactively. Assigning permission to the IWAM account is the only way to do this:

subinacl /service Service1 /grant=IIS_WPG=s

Problem solved for the web app.

Always one for complete proof, I tested removing interactive access (subinacl /service Service1 /deny=interactive=s). Result as requested - the console app now throws the same exception the web application does.

But wait...

C:\Program Files\Windows Resource Kits\Tools\>subinacl /service Service1 /revoke=interactiveService1
- OpenService Error : 5 Access is denied.

Oops. Big oops. Nothing I can do now seems to be able to let me fix this, because I've lost access to query the status of the server myself.

Some searching led me to an answer: use the sc.exe utility, which lets you control services from the command line. It also lets you set their security descriptors!

C:\Program Files\Windows Resource Kits\Tools\>sc sdshow Service1 
D:(D;;LC;;;IU)(A;;CCLCSWRPWPDTLOCRRC;;;SY)(A;;CCDCLCSWRPWPDTLOCRSDRCWDWO;;;BA)(A;;CCLCSWLOCRRC;;;SU)(A;;CR;;;AU)(A;;CCLCSWRPWPDTLOCRRC;;;PU)S:(AU;FA;CCDCLCSWRPWPDTLOCRSDRCWDWO;;;WD)

C:\Program Files\Windows Resource Kits\Tools\>sc sdshow Service2
D:(A;;CCLCSWRPWPDTLOCRRC;;;SY)(A;;CCDCLCSWRPWPDTLOCRSDRCWDWO;;;BA)(A;;CCLCSWLOCRRC;;;IU)(A;;CCLCSWLOCRRC;;;SU)(A;;CR;;;AU)(A;;CCLCSWRPWPDTLOCRRC;;;PU)S:(AU;FA;CCDCLCSWRPWPDTLOCRSDRCWDWO;;;WD)

C:\Program Files\Windows Resource Kits\Tools\>sc sdset Service1 D:(A;;CCLCSWRPWPDTLOCRRC;;;SY)(A;;CCDCLCSWRPWPDTLOCRSDRCWDWO;;;BA)(A;;CCLCSWLOCRRC;;;IU)(A;;CCLCSWLOCRRC;;;SU)(A;;CR;;;AU)(A;;CCLCSWRPWPDTLOCRRC;;;PU)S:(AU;FA;CCDCLCSWRPWPDTLOCRSDRCWDWO;;;WD)
[SC] SetServiceObjectSecurity SUCCESS

C:\Program Files\Windows Resource Kits\Tools\>subinacl /service Service1
=========================
+Service Service1
=========================
<snip>

Whew. See how the SDs differ between the two services? Ignore the gobbledy-gook that is SDDL, and just copy an example from another similar service.

I suspect I could have granted access using with sc instead of subinacl, but the IWAM_SERVERNAME account and IIS_WPG group don't have well-known SIDs, so I would have had to find out the SID using another utility anyway.

(Hi Mum. This is what I do all day.)

Tags: ,
Posted in Technical, Work | 6 Comments »