Logging SOAP request and response on server side

Question

I'm trying to create a logging service for all SOAP method calls to my ASP.NET webservice. I've been looking at Log SOAP messages from a console application and the walkthrough for SOAP extensions at MSDN (http://msdn.microsoft.com/en-us/library/s25h0swd%28v=vs.100%29.aspx) but they don't seem to cover it completely.

I don't want to alter the SOAP message, just log it to a database table. What I'm trying to do is read the SOAP message stream, parse it as an XML, log the XML and the let the call be on its merry way. But when I read the stream it is spent/disposed. I've tried copying the stream contents to not interrupt the flow.

According to the walkthrough the ProcessMessage method should look something like this:

public override void ProcessMessage(SoapMessage message) 
{
   switch (message.Stage) 
   {
   case SoapMessageStage.BeforeSerialize:
       break;
   case SoapMessageStage.AfterSerialize:
       // Write the SOAP message out to a file.
       WriteOutput( message );
       break;
   case SoapMessageStage.BeforeDeserialize:
       // Write the SOAP message out to a file.
       WriteInput( message );
       break;
   case SoapMessageStage.AfterDeserialize:
       break;
   default:
       throw new Exception("invalid stage");
   }
}

I've managed to parse the stream without problems during the BeforeDeserialize stage, but then ProcessMessage is called again in the AfterSerialize stage and by then the stream is used and no longer contains any data.

According to SOAP Message Modification Using SOAP Extensions (http://msdn.microsoft.com/en-us/library/esw638yk%28v=vs.100%29.aspx) the SOAP call goes through the following steps:

Server Side Receives a Request Message and Prepares a Response

1. ASP.NET on the Web server receives the SOAP message.
2. A new instance of the SOAP extension is created on the Web server.
3. On the Web server, if this is the first time this SOAP extension has executed with this Web service on the server side, the GetInitializer method is invoked on the SOAP extension running on the server.
4. The Initialize method is invoked.
5. The ChainStream method is invoked.
6. The ProcessMessage method is invoked with SoapMessageStage set to BeforeDeserialize.
7. ASP.NET deserializes the arguments within the XML.
8. The ProcessMessage method is invoked with SoapMessageStage set to AfterDeserialize.
9. ASP.NET creates a new instance of the class implementing the Web service and invokes the Web service method, passing in the deserialized arguments. This object resides on the same computer as the Web server.
10. The Web service method executes its code, eventually setting the return value and any out parameters.
11. The ProcessMessage method is invoked with SoapMessageStage set to BeforeSerialize.
12. ASP.NET on the Web server serializes the return value and out parameters into XML.
13. The ProcessMessage method is invoked with SoapMessageStage set to AfterSerialize.
14. ASP.NET sends the SOAP response message over the network back to the Web service client.

Step 6 is performed correctly and the SOAP XML is logged. Then it shouldn't do anything more until after the server has processed the call, done what it needs (step 10), and returned a response (step 13). Instead it immediately calls ProcessMessage again in the AfterSerialize stage, but this time the stream is already spent and throws an exception when I try to log it.

According to the walkthrough I should use the ChainStream method, and it should be run in step 5 above. When I make the call it is run twice, once before BeforeDeserialize and once before AfterSerialize.

I've tried copying the message stream to a separate stream and use that for the logging, also to set some kind of status if BeforeDeserialize already have run, but problem still persists.

I still need the code in AfterSerialize to handle the response that is sent back to the client. But if I try to remove my code in AfterSerialize and only run the code in BeforeDeserialize' I get aHTTP 400: Bad Request`.

This all happens before the actual method call, so I never even get to the code inside the method (step 10).

Answer 1

My solution is based on the one by mikebridge, but I had to make a few alterations. The initializers had to be included, and exceptions were thrown if you tried to access soap message information in a stage where it wasn't available.

public class SoapLoggingExtension : SoapExtension
{
    private Stream _originalStream;
    private Stream _workingStream;
    private static String _initialMethodName;
    private static string _methodName;
    private static String _xmlResponse;

    /// <summary>
    /// Side effects: saves the incoming stream to
    /// _originalStream, creates a new MemoryStream
    /// in _workingStream and returns it.  
    /// Later, _workingStream will have to be created
    /// </summary>
    /// <param name="stream"></param>
    /// <returns></returns>
    public override Stream ChainStream(Stream stream)
    {

        _originalStream = stream;
        _workingStream = new MemoryStream();
        return _workingStream;
    }

    /// <summary>
    /// Process soap message
    /// </summary>
    /// <param name="message"></param>
    public override void ProcessMessage(SoapMessage message)
    {
        switch (message.Stage)
        {
            case SoapMessageStage.BeforeSerialize:
                break;

            case SoapMessageStage.AfterSerialize:
                //Get soap call as a xml string
                var xmlRequest = GetSoapEnvelope(_workingStream);
                //Save the inbound method name
                _methodName = message.MethodInfo.Name;
                CopyStream(_workingStream, _originalStream);
                //Log call
                LogSoapRequest(xmlRequest, _methodName, LogObject.Direction.OutPut);
                break;

            case SoapMessageStage.BeforeDeserialize:
                CopyStream(_originalStream, _workingStream);
                //Get xml string from stream before it is used
                _xmlResponse = GetSoapEnvelope(_workingStream);
                break;

            case SoapMessageStage.AfterDeserialize:
                //Method name is only available after deserialize
                _methodName = message.MethodInfo.Name;
                LogSoapRequest(_xmlResponse, _methodName, LogObject.Direction.InPut);
                break;
        }
    }

    /// <summary>
    /// Returns the XML representation of the Soap Envelope in the supplied stream.
    /// Resets the position of stream to zero.
    /// </summary>
    private String GetSoapEnvelope(Stream stream)
    {
        stream.Position = 0;
        StreamReader reader = new StreamReader(stream);
        String data = reader.ReadToEnd();
        stream.Position = 0;
        return data;
    }

    private void CopyStream(Stream from, Stream to)
    {
        TextReader reader = new StreamReader(from);
        TextWriter writer = new StreamWriter(to);
        writer.WriteLine(reader.ReadToEnd());
        writer.Flush();
    }

    public override object GetInitializer(Type serviceType)
    {
        return serviceType.FullName;
    }

    //Never needed to use this initializer, but it has to be implemented
    public override object GetInitializer(LogicalMethodInfo methodInfo, SoapExtensionAttribute attribute)
    {
        throw new NotImplementedException();
        //return ((TraceExtensionAttribute)attribute).Filename;
    }

    public override void Initialize(object initializer)
    {
        if (String.IsNullOrEmpty(_methodName))
        {
            _initialMethodName = _methodName;
            _waitForResponse = false;
        }
    }

    private void LogSoapRequest(String xml, String methodName, LogObject.Direction direction)
    {

        String connectionString = String.Empty;
        String callerIpAddress = String.Empty;
        String ipAddress = String.Empty;

        try
        {
            //Only log outbound for the response to the original call
            if (_waitForResponse && xml.IndexOf("<" + _initialMethodName + "Response") < 0)
            {
                return;
            }

            if (direction == LogObject.Direction.InPut) {
                _waitForResponse = true;
                _initialMethodName = methodName;
            }

            connectionString = GetSqlConnectionString();
            callerIpAddress = GetClientIp();
            ipAddress = GetClientIp(HttpContext.Current.Request.UserHostAddress);

            //Log call here

            if (!String.IsNullOrEmpty(_methodName) && xml.IndexOf("<" + _initialMethodName + "Response") > 0)
            {
                //Reset static values to initial
                _methodName = String.Empty;
                _initialMethodName = String.Empty;
                _waitForResponse = false;
            }
        }
        catch (Exception ex)
        {
            //Error handling here
        }
    }
    private static string GetClientIp(string ip = null)
    {
        if (String.IsNullOrEmpty(ip))
        {
            ip = HttpContext.Current.Request.ServerVariables["HTTP_X_FORWARDED_FOR"];
        }
        if (String.IsNullOrEmpty(ip) || ip.Equals("unknown", StringComparison.OrdinalIgnoreCase))
        {
            ip = HttpContext.Current.Request.ServerVariables["REMOTE_ADDR"];
        }
        if (ip == "::1")
            ip = "127.0.0.1";
        return ip;
    }
}

The methodName variable is used to determine for which inbound call we are waiting for a response. This is of course optional, but in my solution I make a few calls to other webservices, but I want to log just the response to the first call.

The second part is that you need to add the right lines to your web.config. Apparently it is sensitive to not including the whole class type definition (in this example only the class name is defined, which didn't work. The class was never initialized.):

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
<system.web>
    <webServices>
        <soapExtensionTypes>
            <add group="High" priority="1" type="WsNs.SoapLoggingExtension, WsNs, Version=1.0.0.0, Culture=neutral" />
        </soapExtensionTypes>
    </webServices>
</system.web>
</configuration>

Answer 2

Here's my first shot at this, inspired by this and this.

The SoapExtension has all sorts of side-effects and hidden temporal dependencies when dealing with the stream and when variables are initialized or uninitialized, so this is brittle code. I found that the key is to copy the original stream into the Memory stream and then back again at exactly the right moments.

public class SoapLoggingExtension : SoapExtension
{

    private Stream _originalStream;
    private Stream _workingStream;
    private string _methodName;
    private List<KeyValuePair<string, string>> _parameters;
    private XmlDocument _xmlResponse;
    private string _url;

    /// <summary>
    /// Side effects: saves the incoming stream to
    /// _originalStream, creates a new MemoryStream
    /// in _workingStream and returns it.  
    /// Later, _workingStream will have to be created
    /// </summary>
    /// <param name="stream"></param>
    /// <returns></returns>
    public override Stream ChainStream(Stream stream)
    {

        _originalStream = stream;
        _workingStream = new MemoryStream();
        return _workingStream;
    }

    /// <summary>
    /// AUGH, A TEMPLATE METHOD WITH A SWITCH ?!?
    /// Side-effects: everywhere
    /// </summary>
    /// <param name="message"></param>
    public override void ProcessMessage(SoapMessage message)
    {
        switch (message.Stage)
        {
            case SoapMessageStage.BeforeSerialize:
                break;

            case SoapMessageStage.AfterSerialize:

                var xmlRequest = GetSoapEnvelope(_workingStream);
                CopyStream(_workingStream, _originalStream);
                LogResponse(xmlRequest, GetIpAddress(), _methodName, _parameters); // final step
                break;

            case SoapMessageStage.BeforeDeserialize:

                CopyStream(_originalStream, _workingStream);
                _xmlResponse = GetSoapEnvelope(_workingStream);
                _url = message.Url;
                break;

            case SoapMessageStage.AfterDeserialize:

                SaveCallInfo(message);                    
                break;
        }
    }

    private void SaveCallInfo(SoapMessage message)
    {
        _methodName = message.MethodInfo.Name;

        // the parameter value is converted to a string for logging, 
        // but this may not be suitable for all applications.
        ParameterInfo[] parminfo = message.MethodInfo.InParameters;
        _parameters = parminfo.Select((t, i) => new KeyValuePair<string, String>(
                t.Name, Convert.ToString(message.GetInParameterValue(i)))).ToList();

    }

    private void LogResponse(
        XmlDocument xmlResponse,
        String ipaddress,
        string methodName, 
        IEnumerable<KeyValuePair<string, string>> parameters)
    {
        // SEND TO LOGGER HERE!
    }

    /// <summary>
    /// Returns the XML representation of the Soap Envelope in the supplied stream.
    /// Resets the position of stream to zero.
    /// </summary>
    private XmlDocument GetSoapEnvelope(Stream stream)
    {
        XmlDocument xml = new XmlDocument();
        stream.Position = 0;
        StreamReader reader = new StreamReader(stream);
        xml.LoadXml(reader.ReadToEnd());
        stream.Position = 0;
        return xml;
    }

    private void CopyStream(Stream from, Stream to)
    {
        TextReader reader = new StreamReader(from);
        TextWriter writer = new StreamWriter(to);
        writer.WriteLine(reader.ReadToEnd());
        writer.Flush();
    }

    // GLOBAL VARIABLE DEPENDENCIES HERE!!
    private String GetIpAddress()
    {
        try
        {
            return HttpContext.Current.Request.UserHostAddress;
        }
        catch (Exception)
        {
            // ignore error;
            return "";
        }
    }