Logging and Rewriting Service Calls

I love web services.  I love how easy it is to wire up a JavaScript client either through jQuery or through a ServiceProxy.  I love how I can point a .net client at a service, and I get strongly typed command parameters.  And my latest love of asmx services in C# is the SoapExtension.  A SoapExtension is a class that allows you to inspect outgoing or incoming services to get at the data involved.  I use them for logging service calls (frequency, duration, errors), and for rewriting output (fixed a “double html encoded” bug, remove whitespace, rewrite SoapFaults, etc).

The technique is incredibly awesome, and I can’t claim original ownership, but I can claim excellent results.  A few simple steps:

  1. Create a class that derives from SoapExtension.

  2. Override ProcessMessage, handling the SoapMessage’s Stage that you’re interested in.

  3. Add either a web.config entry (to handle all inbound and outbound service calls), or put an attribute on each WebMethod you want to track.

Voila!  You’ve got a soap extension.

Here’s my ExampleSoapExtension (business logic replaced with TODO to keep it simple):

namespace ExampleNamespace {

    #region using
    using System;
    using System.Data.Linq;
    using System.IO;
    using System.Linq;
    using System.Text.RegularExpressions;
    using System.Threading;
    using System.Web;
    using System.Web.Services.Protocols;
    #endregion

    public class ExampleSoapExtension : SoapExtension {

        private Stream originalStream; // The original stream
        private Stream internalStream; // Our new stream we chained into place

        public ExampleSoapExtension() {
        }

        // Called the first time the Web service is used if configured with a config file
        public override object GetInitializer( Type t ) {
            return typeof( ExampleSoapExtension );
        }

        // Called the first time the Web service is used if configured with an attribute
        public override object GetInitializer( LogicalMethodInfo methodInfo, SoapExtensionAttribute attribute ) {
            return attribute;
        }

        // Called each time the Web service is used and gets passed the data from GetInitializer() method
        public override void Initialize( object initializer ) {
            // Get the attribute here and pull whatever you need off it.
            //ExampleSoapExtensionAttribute attr = initializer as ExampleSoapExtensionAttribute;
        }

        // The ChainStream() method gives us a chance to grab the SOAP messages as they go by
        public override Stream ChainStream( Stream stream ) {
            // Save the original stream
            originalStream = stream;
            // Create and return our own in its place
            internalStream = new MemoryStream();

            return internalStream;
        }

        // The ProcessMessage() method is called between each step in the server-side process
        public override void ProcessMessage( SoapMessage message ) {

            switch ( message.Stage ) {

                case SoapMessageStage.BeforeDeserialize:
                    // About to handle incoming SOAP request

                    string requestContent = StreamToText( this.originalStream, false );
                    WriteIncomingToLog( message, requestContent );
                    TextToStream( requestContent, this.internalStream, true );
                    break;

                case SoapMessageStage.AfterDeserialize:
                    // incoming SOAP request has been deserialized

                    WriteInputToLog( message );
                    break;

                case SoapMessageStage.BeforeSerialize:
                    // About to prepare outgoing SOAP Response

                    WriteOutputToLog( message );
                    break;

                case SoapMessageStage.AfterSerialize:
                    // outgoing SOAP response is ready to go

                    string responseContent = null;

                    if ( message.Exception != null ) {
                        // Rewrite soap fault as valid soap message with internal error code
                        // Though it might be nice to do this before serialization, we can't inject our own return value easily
                        responseContent = RewriteError( message );
                    } else {
                        responseContent = StreamToText( this.internalStream, true );
                    }

                    WriteOutgoingToLog( message, responseContent );
                    TextToStream( responseContent, this.originalStream, false );
                    break;

                default:
                    throw new Exception( “invalid stage” );
            }
        }

        private static string StreamToText( Stream stream, bool rewindBefore ) {
            if ( rewindBefore ) {
                stream.Position = 0;
            }
            TextReader reader = new StreamReader( stream );
            string content = reader.ReadToEnd();
            return content;
        }

        private static void TextToStream( String text, Stream stream, bool rewindAfter ) {
            TextWriter writer = new StreamWriter( stream );
            writer.Write( text );
            writer.Flush();
            if ( rewindAfter ) {
                stream.Position = 0;
            }
        }

        #region WriteIncomingToLog
        ///


        /// Write the incoming stream content to the logs
        ///
        private void WriteIncomingToLog( SoapMessage Message, string Content ) {

            HttpRequest req = HttpContext.Current.Request;

            // TODO: Log various parameters here including the incoming xml and start date

        }
        #endregion

        #region WriteInputToLog
        private void WriteInputToLog( SoapMessage Message ) {

            ServiceInputObject input = null;
            if ( Message.MethodInfo.InParameters.Length > 0 ) {
                try {
                    input = Message.GetInParameterValue( 0 ) as ServiceInputObject;
                } catch ( Exception /ex/ ) {
                    input = null;
                }
            }
            if ( input != null ) {

                // TODO: Log the message details

            }

        }
        #endregion

        #region WriteOutputToLog
        private void WriteOutputToLog( SoapMessage Message ) {

            if ( Message.Exception != null ) {
                // The return object doesn't exist because an exception was thrown
                // RewriteError will create one
                return;
            }

            ServiceOutputObject output = null;
            if ( Message.MethodInfo != null && Message.MethodInfo.ReturnType != null && Message.MethodInfo.ReturnType.FullName != “System.Void” ) {
                output = Message.GetReturnValue() as ServiceOutputObject;
            } else {
                output = null;
            }
            if ( output != null ) {

                // TODO: Log the output details

            }

        }
        #endregion

        #region WriteOutgoingToLog
        ///

        /// Write the message in the stream to the log4net log
        ///
        private void WriteOutgoingToLog( SoapMessage Message, string Content ) {

            string outboundData = GetStreamText( StreamToLog );

            // TODO: Log the outgoing xml string and end date

        }
        #endregion

        #region CaptureError
        ///

        /// Insure the exception is logged
        ///
        private Stream CaptureError( SoapMessage Message, Stream stream ) {

            // Log the exception
            Exception ex = Message.Exception;
            while ( ex != null && ex.InnerException != null && ex.GetType() == typeof( SoapException ) ) {
                ex = ex.InnerException;
            }

            // TODO: Log the exception

            // TODO: Form the output reply and serialize it
            string soapMessage = null;

            // Now send this as the out stream instead of the soap:Fault stream we had before
            MemoryStream outStream = new MemoryStream();
            TextWriter writer = new StreamWriter( outStream );
            writer.WriteLine( soapMessage );
            writer.Flush();
            outStream.Position = 0;

            // And send the 200 status instead of 400
            //HttpContext.Current.Response.StatusCode = 200;

            // Here's the content to send instead of what ever you had
            return outStream;
        }
        #endregion

    }

    [AttributeUsage( AttributeTargets.Method )]
    public class ExampleSoapExtensionAttribute : SoapExtensionAttribute {

        public ExampleSoapExtensionAttribute() {
            this.Priority = 1;
        }

        public override int Priority { get; set; }

        // Specifies the class of the SOAP Extension to use with this method
        public override Type ExtensionType {
            get { return typeof( ExampleSoapExtension ); }
        }

    }

}

My current quest: how do I do this in WCF?  Is there such a thing as a “message watcher” or “handler” or “pipeline interceptor”?  All these terms on Google come up blank.  With WCF’s new configuration-less services and MS’s desire to move on past asmx, WCF seems a foregone conclusion.  For me, this is the last hurdle.

Rob