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
        /// <summary>
        /// Write the incoming stream content to the logs
        /// </summary>
        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
        /// <summary>
        /// Write the message in the stream to the log4net log
        /// </summary>
        private void WriteOutgoingToLog( SoapMessage Message, string Content ) {

            string outboundData = GetStreamText( StreamToLog );

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

        }
        #endregion

        #region CaptureError
        /// <summary>
        /// Insure the exception is logged
        /// </summary>
        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

posted @ Monday, February 15, 2010 10:42 AM

Print

Comments on this entry:

# re: Logging and Rewriting Service Calls

Left by Funka! at 4/5/2010 2:39 PM
Gravatar
Have you found a way to do this in WCF yet? There are some items I'd like to convert from ASMX and I, too, am wondering how (if) this might be possible.... Thx!

# re: Logging and Rewriting Service Calls

Left by journal des casinos en ligne at 4/22/2010 12:45 AM
Gravatar
No, it’s a justification. Just because W3C has only issued one binding, doesn’t mean that SOAP can’t run over MQ, JMS, MSMQ/COM+, etc. It does, and putting auth information into SOAP as opposed to its transport gives end-to-end identity, integrity, etc.....

# re: Logging and Rewriting Service Calls

Left by rob at 5/20/2010 7:57 PM
Gravatar
Funka,

I haven't found a good solution yet. I have gotten more into ASP.NET MVC, and to some degree, much of my "asmx service" stuff (page methods) are now controller actions with content types, so the need to dive deep into WCF has been averted.

I did learn that the topic at hand might be "IOperationBehavior" or "IDispatchMessageInspector". So far the configuration and supporting code don't seem like it's worth the move for the rest though. Propping up an asmx service is just drop-dead simple.

Rob

Your comment:



 (will not be displayed)


 
 
 
Please add 8 and 3 and type the answer here:
 

Live Comment Preview: