I’m far from a Web Services guru. I do however enjoy the benefits of using VS.NET and developing web services the .NET way. I’m currently working on a project that is building a webservice and another vendor is writing the client. Recently, the other vendor started reporting that webmethods were returning HTTP 500 errors sporadically. So we started investigating.
In our VB code, we have Try/Catches which call logging functions that update the Event log, but these were showing no errors. The IIS logs did support the other vendor’s statements but we couldn’t figure what was happening. So, I started emailing my “Smart People” network. And I got all sorts of advice. “Add logging to your Application_Error event because you’re probably missed a Catch block somewhere”. “Try using the CustomErrors mechanism which allows you to redirect 500’s to a specific page”. I tried all of that but to no avail – there was no exception being thrown from our code. I did learn that errors bubble in ASP.NET – from the code, to the Application_Error event, and then to the Web.Config (i.e. the CustomErrors configuration).
There are several ways that ASP.NET will report HTTP 500 errors. By accident, we found that if a client proxy is out of sync with the actual webservice definition, then HTTP 500 errors appear. However, it doesn’t generate an exception in our code. It is very easy to simulate this. 1) Create a web service that has a method called Method1 which does some form of error logging logic. 2) Create a client that has a web reference for the web service and calls Method1. 3) Go back to the server and comment out Method1. 4) Run the client and it gets a SOAP extension. However, there is no error on the server.
Another thing that I did along with looking at the Application_Error event was to add Trace statements to all of the Application events that are exposed by VS.NET. My hope was that I could determine when the status started turned to the negative and log the scenario. In these Trace statements, I made calls to the HttpContext.Current.Response.StatusCode. Below is the result.
|
Trace Information |
|
Category |
Message |
From First(s) |
From Last(s) |
|
|
|
|
|
|
|
|
APP_BeginRequest: 200 |
|
|
|
|
|
|
|
|
|
|
APP_AuthenticateRequest: 200 |
0.000403 |
0.000403 |
|
|
|
|
|
|
|
|
APP_AuthRequest: 200 |
0.024753 |
0.024350 |
|
|
|
|
|
|
|
|
APP_AuthorizeRequest: 200 |
0.026872 |
0.002118 |
|
|
|
|
|
|
|
|
APP_ResolveRequestCache: 200 |
0.052401 |
0.025530 |
|
|
|
|
|
|
|
|
APP_AcquireRequestState: 500 |
1.520145 |
0.037620 |
|
|
|
|
|
|
|
|
APP_PreRequestHandlerExecute: 500 |
1.520446 |
0.000301 |
|
|
|
|
|
|
|
|
APP_PostRequestHandlerExecute: 500 |
1.521431 |
0.000986 |
|
|
|
|
|
|
|
|
APP_ReleaseRequestState: 500 |
1.521696 |
0.000265 |
|
|
|
|
|
|
|
|
APP_UpdateRequestCache: 500 |
1.526000 |
0.004303 |
|
|
|
|
|
|
|
|
APP_EndRequest: 500 |
1.532099 |
0.006100 |
|
|
|
|
|
|
Based on this, I could see that between ResolveRequestCache and AcquireRequestState event is where ASP.NET determined that something was wrong with the incoming request. At least, I was seeing that there was a problem, but I could not yet report what the problem was or what was going on in between those two events.
Finally, Dan Fox said that I should take a look at Soap Extensions. After doing a google on the topic, I ran across a MSDN article titled Altering the SOAP Message Using SOAP Extensions.
The article does a great job of explaining the topic and comes with VB and C# code that logs incoming and outgoing SOAP calls to a text file. The short version is that you build a class that inherits from the System.Web.Services.Protocols.SoapExtension class. Upon registering in the Web.Config, the class will be called during the Web Service deserialization/serialization process (as shown in the picture above – each of the blue boxes represent an opportunity to see the data via a SoapExtension).
Then, I found information on another sample at Gerrard Lindsay’s Pick A Bar blog. Gerrard is a Microsoft employee so the stuff has to be good, right? Although he’s a Mets fan <g>, the code works great. His sample is exactly what we need as it a SoapExtension that supports being a listener if configured to do so. After installing this to see if it could help us, our testing showed that a SoapExtension allows us to see the messages through the different states in a XML format. Below is a response after sending a bad request (I’ve removed some things for readability).
<?xml version="1.0" encoding="utf-8"?>
<soap:Envelope >
<soap:Body>
<soap:Fault>
<faultcode>soap:Client</faultcode>
<faultstring>System.Web.Services.Protocols.SoapException: Server did not recognize the value of HTTP Header</faultstring>
<detail />
</soap:Fault>
</soap:Body>
</soap:Envelope>
Remember, I couldn’t see this before. This is great! So I converted the class to VB.NET, added some code to detect when the text includes “<soap:Fault>” and if so record the client’s SOAP request and the server’s response in the event log.
The only outstanding curiosity now is how performance will be affected having this extra layer of code. Time will tell.
