Tracking SOAP Messages | Comprehensive VB .NET Debugging

Once you start developing Web services and have overcome the initial knowledge hurdles, it's easy to become seduced by the ease with which it all works. Most of the details are hidden from you, which is great until something stops working. So now that you've seen the basic information transfer mechanism used by Web services (see Figure 8-4), it's time to dig into some of the messy details behind this mechanism. To really debug interactions between a Web service and its clients , you need to be able to see the underlying SOAP messages that implement Web service requests and responses. This is especially true when you have to understand whether a communication problem is caused by a wrongly formatted SOAP message or by incorrect application information passed to or from the Web service.

Building the SoapMonitor SOAP Extension

To see the underlying SOAP stream from within a Web service, you need to write a custom SOAP extension. SOAP extensions allow you to intercept the process shown in Figure 8-4, so that you can process the SOAP message before it's sent and after it's received. Listing 8-9 shows a minimum custom SOAP extension called SoapMonitor that will later be developed to form a SOAP message logger.

Listing 8-9. The Bare-bones SoapMonitor Custom SOAP Extension

 Option Strict On Imports System.Web.Services.Protocols Public Class SoapMonitor : Inherits SoapExtension     Public Overloads Overrides Function GetInitializer _                            (ByVal serviceType As System.Type) As Object     End Function     Public Overloads Overrides Function GetInitializer _                            (ByVal methodInfo As LogicalMethodInfo, _                            ByVal attribute As SoapExtensionAttribute) _                            As Object     End Function     Public Overrides Sub Initialize(ByVal initializer As Object)     End Sub     Public Overrides Sub ProcessMessage(ByVal Message As SoapMessage)         'Major SOAP message processing will go here     End Sub End Class

The overloaded GetInitializer and Initialize methods have to be overridden but can be left blank for this purpose. The major work will need to be done in the ProcessMessage method, where you have access to the SOAP message. This method is actually called four times during processing of a SOAP request and response. You can tell which stage is happening by looking at the Stage member of the Message argument. The message stage has the following four possible values at the Web service end of the message transfer:

BeforeDeserialize : At this point, you have access to the SOAP request before it's been translated into a .NET call. This is where you want access to the SOAP request message.
AfterDeserialize : At this stage, the SOAP request has been read and translated, but it's now empty.
BeforeSerialize : At this stage, the SOAP response hasn't yet been created, so it isn't accessible at all.
AfterSerialize : Now the SOAP response has been created, but unfortunately it can't be read, although it can be written. This is where you want access to the SOAP response message.

So the ProcessMessage method allows you to read the SOAP request directly, but not the SOAP response. To do this, you need to override the ChainStream method, so that you can have direct access to the memory buffer containing the SOAP message. You need to be careful here because when you access the memory buffer directly in this way, you have to retrieve and pass on the memory stream. Listing 8-10 shows a typical pattern that you can use to set up safe access to the SOAP stream.

Listing 8-10. Setting Up Access to the SOAP Stream Memory Buffer

 Option Strict On Imports System.Web.Services.Protocols Public Class SoapMonitor : Inherits SoapExtension     Private OldStream As Stream     Private NewStream As Stream     Public Overrides Function ChainStream(ByVal stream As System.IO.Stream) _                                                        As System.IO.Stream         OldStream = stream         NewStream = New MemoryStream         Return NewStream     End Function End Class

The code inside the ChainStream method saves a reference (in class member variables ) to both the stream coming into the method and the stream being returned by the method. Now you're ready to create the logic within the

ProcessMessage method for logging the SOAP request and response messages. Listing 8-11 shows all of the SoapMonitor code you have seen so far and adds the ProcessMessage logic to save the SOAP request and response at the BeforeDeserialize and AfterSerialize stages, respectively.

Listing 8-11. Complete SoapMonitor Custom SOAP Extension

 Option Strict On Imports System.Web.Services.Protocols Imports System.IO Public Class SoapMonitor : Inherits SoapExtension     Private OldStream As Stream     Private NewStream As Stream     Public Overloads Overrides Function GetInitializer _                            (ByVal serviceType As System.Type) As Object     End Function     Public Overloads Overrides Function GetInitializer _                            (ByVal methodInfo As LogicalMethodInfo, _                            ByVal attribute As SoapExtensionAttribute) _                            As Object     End Function     Public Overrides Sub Initialize(ByVal initializer As Object)     End Sub     Public Overrides Sub ProcessMessage(ByVal Message As SoapMessage)     Dim Logfile As New FileStream("C:\test\test.log", _ FileMode.Append, _ FileAccess.Write)     Dim LogfileWriter As New StreamWriter(Logfile)     Select Case Message.Stage        Case SoapMessageStage.BeforeDeserialize            'Write header details            With LogfileWriter                .WriteLine("*************************************************")                .WriteLine("Web service: " & Message.Url)                .WriteLine("Web method: " & Message.Action)                .WriteLine("Called at " & DateTime.Now)                .Write("Message stage: SOAP REQUEST")                .WriteLine(" (" & Message.Stage.ToString & ")")                .WriteLine()                .Flush()        End With        'Write incoming SOAP request message        CopyStream(OldStream, NewStream)        NewStream.Position = 0        CopyStream(NewStream, Logfile)        NewStream.Position = 0        'Blank separating line        LogfileWriter.WriteLine()   Case SoapMessageStage.AfterSerialize        'Write header details        With LogfileWriter            .WriteLine("*************************************************")            .WriteLine("Web service: " & Message.Url)            .WriteLine("Web method: " & Message.Action)            .WriteLine("Called at " & DateTime.Now)            .Write("Message stage: SOAP RESPONSE")            .WriteLine(" (" & Message.Stage.ToString & ")")            .Write("Exception thrown? ")            If Message.Exception Is Nothing Then                 .WriteLine("No")             Else                 .WriteLine("Yes")             End If             .WriteLine()             .Flush()         End With         'Write outgoing SOAP response message         NewStream.Position = 0         CopyStream(NewStream, Logfile)         NewStream.Position = 0         CopyStream(NewStream, OldStream)         'Blank separating line         LogfileWriter.WriteLine() End Select         Logfile.Flush()         Logfile.Close()     End Sub    Public Overrides Function ChainStream(ByVal stream As System.IO.Stream) _                                                        As System.IO.Stream         OldStream = stream         NewStream = New MemoryStream         Return NewStream     End Function     Private Sub CopyStream(ByVal FromStream As Stream, ByVal ToStream As Stream)         Dim FromReader As TextReader = New StreamReader(FromStream)         Dim ToWriter As TextWriter = New StreamWriter(ToStream)         ToWriter.WriteLine(FromReader.ReadToEnd)         ToWriter.Flush()     End Sub End Class

This SOAP extension writes the SOAP request and response messages to a hard-coded log file (in this case, C:\test\test.log). It also logs the Web method that was called, the date and time of the call, and whether the Web service threw an exception in response to the client call. Later you'll see an example of a log file produced by this code, but I still need to demonstrate how to hook up this SOAP extension to one or more Web methods so that it's invoked automatically when the Web method is called.

Building the SoapMonitor Attribute

In order to bind a custom SOAP extension to a Web method, you need to build a corresponding custom SOAP extension attribute. To do this, you inherit from the SoapExtensionAttribute type. This allows you to identify your SOAP extension. Listing 8-12 shows how to create the SoapMonitorAttribute custom attribute that you can use for binding the SoapMonitor extension. This custom attribute overrides the ExtensionType property to return the type of the SoapMonitor extension and it also overrides the Priority property to define the SOAP extension's priority relative to other extensions. The lines highlighted in bold are the ones that you'll need to modify when creating your own SoapExtensionAttribute .

Listing 8-12. The SoapMonitorAttribute Custom SOAP Attribute

 Option Strict On Imports System.Web.Services.Protocols Public Class SoapMonitorAttribute : Inherits SoapExtensionAttribute     'Add this custom attribute to any web method where you want     'to monitor the SOAP request and response messages     Public Overrides ReadOnly Property ExtensionType() As System.Type         Get  Return GetType(SoapMonitor)  End Get     End Property     Public Overrides Property Priority() As Integer         Get  Return 0  End Get         Set(ByVal Value As Integer)         End Set     End Property End Class

Having created the SoapMonitorAttribute attribute, Listing 8-13 shows you how to bind a custom attribute's extension to a Web method, in this case the ThrowExceptionCustom method. The line highlighted in bold applies the attribute to the method. Notice how you can omit the final part of the attribute's name (Attribute) when you specify it.

Listing 8-13. Binding the SoapMonitor Extension to a Web Method

  <WebMethod(), SoapMonitor()> _  Public Sub ThrowExceptionCustom()     'This method throws a customized exception     Try         Dim Test As Object         Test.ToString()     Catch Exc As Exception         Throw CustomException(Exc)     End Try End Sub

At this point, any SOAP call to the ThrowExceptionCustom Web method will result in the SoapMonitor.ProcessMessage method being called four times, once for each stage of the SOAP message serialization process.

Putting It All Together

This is the log file produced when the ThrowExceptionCustom Web method is given the SoapMonitorAttribute attribute and then called by a SOAP client:

 ************************************************* Web service: http://localhost/TimeServer/TimeService.asmx Web method: http://debugvb .net/TimeServer/TimeService/ThrowExceptionCustom Called at 09/11/2002 16:24:31 Message stage: SOAP REQUEST (BeforeDeserialize) <?xml version="1.0" encoding="utf-8"?> <soap:Envelope xmlns:soap=http://schemas.xmlsoap.org/soap/envelope/  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema">   <soap:Body>     <ThrowExceptionCustom xmlns="http://debugvb .net/TimeServer/TimeService" />   </soap:Body> </soap:Envelope> ************************************************* Web service: http://localhost/TimeServer/TimeService.asmx Web method: http://debugvb .net/TimeServer/TimeService/ThrowExceptionCustom Called at 09/11/2002 16:24:31 Message stage: SOAP RESPONSE (AfterSerialize) Exception thrown? Yes <?xml version="1.0" encoding="utf-8"?> <soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema">   <soap:Body>      <soap:Fault>        <faultcode>soap:Server</faultcode>        <faultstring>System.Web.Services.Protocols.SoapException      at TimeServer.TimeService.ThrowExceptionCustom() in c:\inetpub\wwwroot\TimeServer\TimeService.asmx.vb:line 66</faultstring>       <faultactor>http://localhost/TimeServer/TimeService.asmx</faultactor>       <detail>          <ExceptionType>System.NullReferenceException</ExceptionType>          <ExceptionMessage>Object reference not set to an instance of an object.          </ExceptionMessage>          <ExceptionTrace> at TimeServer.TimeService.ThrowExceptionCustom()  in c:\inetpub\wwwroot\TimeServer\TimeService.asmx.vb:line 64</ExceptionTrace>       </detail>     </soap:Fault>   </soap:Body> </soap:Envelope>

Armed with this kind of low-level information, it's much easier to determine whether a Web service communication problem is an application error or a SOAP formatting issue. Among other things, you can use this SOAP extension to log every exception that occurs within your Web service.

Bear in mind that there is a performance penalty to be paid when you use SOAP extensions and attributes to do SOAP logging in this manner. You have to make a tradeoff here, so you might want to log messages only when your Web service is in its beta phase, and perhaps log only exceptions when you go into production.

SOAP Logging at the Client

What happens when you need to read the SOAP messages going back and forth between your client and a third-party Web service, where you don't have access to the source code of the Web service? In this case, there's no way of adding your custom SoapMonitor extension at the Web service end. Instead, you can create a very similar custom SOAP extension at the client end and then attach this extension to the proxy class methods that you want to monitor or debug.

The client SoapMonitor extension will be almost identical to the one created at the Web service end. The only change comes in the client extension's ProcessMessage method, as shown in Listing 8-14. If you compare this with the equivalent Web service ProcessMessage shown in Listing 8-11, the differences between the two listings are highlighted in bold.

Listing 8-14. The ProcessMessage Method on a Client-Based SOAP Extension

 Public Overrides Sub ProcessMessage(ByVal Message As SoapMessage)           Dim Logfile As New FileStream("C:\test\test.log", _ FileMode.Append, _ FileAccess.Write)         Dim LogfileWriter As New StreamWriter(Logfile)         Select Case Message.Stage  Case SoapMessageStage.AfterSerialize  'Write header details                  With LogfileWriter                       .WriteLine("*************************************************")                       .WriteLine("Web service: " & Message.Url)                       .WriteLine("Web method: " & Message.Action)                       .WriteLine("Called at " & DateTime.Now)                       .Write("Message stage: SOAP REQUEST")                       .WriteLine(" (" & Message.Stage.ToString & ")")                       .WriteLine()                       .Flush()                   End With                   'Write incoming SOAP request message                   CopyStream(OldStream, NewStream)                   NewStream.Position = 0                   CopyStream(NewStream, Logfile)                   NewStream.Position = 0                   'Blank separating line                   LogfileWriter.WriteLine()            Case SoapMessageStage.BeforeDeserialize                'Write header details                With LogfileWriter                     .WriteLine("*************************************************")                     .WriteLine("Web service: " & Message.Url)                     .WriteLine("Web method: " & Message.Action)                     .WriteLine("Called at " & DateTime.Now)                     .Write("Message stage: SOAP RESPONSE")                     .WriteLine(" (" & Message.Stage.ToString & ")")                     .Write("Exception thrown? ")                     If Message.Exception Is Nothing Then                     .WriteLine("No")                 Else                     .WriteLine("Yes")                 End If                 .WriteLine()                 .Flush()             End With             'Write outgoing SOAP response message             NewStream.Position = 0             CopyStream(NewStream, Logfile)             NewStream.Position = 0             CopyStream(NewStream, OldStream)             'Blank separating line             LogfileWriter.WriteLine()     End Select     Logfile.Flush()     Logfile.Close() End Sub

On the server-based ProcessMessage , the BeforeDeserialize message stage was used to read the SOAP request and the AfterSerialize stage to read the SOAP response. At the client end, these stages are, of course, swapped around because the client initiates the whole response/request cycle. So the message stages at the client end look like this:

BeforeSerialize : Before the .NET call has been translated into a SOAP request
AfterSerialize : After the SOAP request has been created and is about to be passed over the network to the Web service
BeforeDeserialize : After the SOAP response has been received, but before it's been translated back into a .NET result
AfterDeserialize : After the SOAP response has been translated back into a .NET result

Finally, you need to bind the SOAP extension to one or more client proxy methods. Listing 8-15 shows the SoapMonitor extension bound to the Current-Time proxy method.

Listing 8-15. Binding the SoapMonitor Extension to a Web Method

 <System.Web.Services.Protocols.SoapDocumentMethodAttribute _         ("http://debugvb .net/TimeServer/TimeService/CurrentTime", _         RequestNamespace:="http://debugvb .net/TimeServer/TimeService", _         ResponseNamespace:="http://debugvb .net/TimeServer/TimeService", _         Use:=System.Web.Services.Description.SoapBindingUse.Literal, _         ParameterStyle:=System.Web.Services.Protocols.SoapParameterStyle.Wrapped), _  SoapMonitor()> _  Public Function CurrentTime() As String     Dim results() As Object = Me.Invoke("CurrentTime", New Object(-1) {})     Return CType(results(0),String) End Function

As I stated before, you need to be aware that updating the Web service reference automatically regenerates the client proxy class, so you'll need to reattribute the appropriate proxy methods when this happens.