Log SOAP messages from a console application

Question

I'm trying to log the requests and responses (the raw XML SOAP envelope) between a console application developed by me and a specific third party remote SOAP web service to database for audit purposes, and I can't find a way to do it.

Ideally what I'd like to do is getting the request

<soapenv:Envelope xmlns:soapenv="http://schemas.xmlsoap.org/soap/envelope/" xmlns:tem="http://tempuri.org/">
   <soapenv:Header/>
   <soapenv:Body>
      <tem:SayHello>
         <tem:name>Albireo</tem:name>
      </tem:SayHello>
   </soapenv:Body>
</soapenv:Envelope>

and the response

<s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
   <s:Body>
      <SayHelloResponse xmlns="http://tempuri.org/">
         <SayHelloResult>Hello, Albireo.</SayHelloResult>
      </SayHelloResponse>
   </s:Body>
</s:Envelope>

and save them in the database.

So far every tutorial on the net I found boils down to two approaches, the SoapExtension method and the tracing method.

The SoapExtension method

The SoapExtension method is based on the SOAP Message Modification Using SOAP Extensions guide, in this method you create a class inheriting from SoapExtension and hook it in the application's configuration, the class' ProcessMessage method will allow you to intercept the SOAP messages.

This is an example of the class inherited from SoapExtension:

namespace Playground.Client
{
    using System;
    using System.Web.Services.Protocols;

    public class SoapLogger : SoapExtension
    {
        public override object GetInitializer(System.Type serviceType)
        {
            throw new NotImplementedException();
        }

        public override object GetInitializer(LogicalMethodInfo methodInfo, SoapExtensionAttribute attribute)
        {
            throw new NotImplementedException();
        }

        public override void Initialize(object initializer)
        {
            throw new NotImplementedException();
        }

        public override void ProcessMessage(SoapMessage message)
        {
            throw new NotImplementedException();
        }
    }
}

And this is how it is wired in the configuration:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
    <startup>
        <supportedRuntime version="v4.0"
                          sku=".NETFramework,Version=v4.5" />
    </startup>
    <system.serviceModel>
        <bindings>
            <basicHttpBinding>
                <binding name="BasicHttpBinding_IGreeterService" />
            </basicHttpBinding>
        </bindings>
        <client>
            <endpoint address="http://localhost:8080/greeter"
                      binding="basicHttpBinding"
                      bindingConfiguration="BasicHttpBinding_IGreeterService"
                      contract="Services.IGreeterService"
                      name="BasicHttpBinding_IGreeterService" />
        </client>
    </system.serviceModel>
    <system.web>
        <webServices>
            <soapExtensionTypes>
                <add group="0"
                     priority="1"
                     type="Playground.Client.SoapLogger" />
            </soapExtensionTypes>
        </webServices>
    </system.web>
</configuration>

The problem with this method is it seems to work only for web applications, trying to implement it in a console application yield no result.

The tracing method

The tracing method is based upon the Configuring Message Logging guide, in this method you enable .NET's tracing for every SOAP/WCF communication in the application and dump the log somewhere (more information on the configuration can be found in Recommended Settings for Tracing and Message Logging).

This is an example of the tracing configuration:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
    <startup>
        <supportedRuntime version="v4.0"
                          sku=".NETFramework,Version=v4.5" />
    </startup>
    <system.diagnostics>
        <sources>
            <source name="System.ServiceModel"
                    propagateActivity="true"
                    switchValue="Verbose, ActivityTracing">
                <listeners>
                    <add initializeData="ServiceModel.svclog"
                         name="ServiceModel"
                         type="System.Diagnostics.XmlWriterTraceListener" />
                </listeners>
            </source>
            <source name="System.ServiceModel.MessageLogging">
                <listeners>
                    <add initializeData="MessageLogging.svclog"
                         name="MessageLogging"
                         type="System.Diagnostics.XmlWriterTraceListener" />
                </listeners>
            </source>
        </sources>
    </system.diagnostics>
    <system.serviceModel>
        <bindings>
            <basicHttpBinding>
                <binding name="BasicHttpBinding_IGreeterService" />
            </basicHttpBinding>
        </bindings>
        <client>
            <endpoint address="http://localhost:8080/greeter"
                      binding="basicHttpBinding"
                      bindingConfiguration="BasicHttpBinding_IGreeterService"
                      contract="Services.IGreeterService"
                      name="BasicHttpBinding_IGreeterService" />
        </client>
        <diagnostics>
            <endToEndTracing activityTracing="true"
                             messageFlowTracing="true"
                             propagateActivity="true" />
            <messageLogging logEntireMessage="true"
                            logKnownPii="true"
                            logMalformedMessages="true"
                            logMessagesAtServiceLevel="true"
                            logMessagesAtTransportLevel="true" />
        </diagnostics>
    </system.serviceModel>
</configuration>

The content of ServiceModel.svclog and MessageLogging.svclog can be found in a GitHub's Gist as it's too big to fit here.

The problem with this method is it logs every SOAP/WCF message in the application and it seems the generated logs are not really useful, they contains loads of informations and I can't understand if and how filter only what I'm interested in, the only practical way to read them seems to be Microsoft's Service Trace Viewer.

I've tried to add a custom TraceListener too:

namespace Playground.Client
{
    using System;
    using System.Diagnostics;
    using System.IO;
    using System.Text;
    using System.Xml;
    using System.Xml.Linq;

    public class CustomTraceListener : TraceListener
    {
        public override void Write(string message)
        {
            File.AppendAllLines("CustomTraceListener.txt", new[] { message });
        }

        public override void WriteLine(string message)
        {
            message = this.FormatXml(message);

            File.AppendAllLines("CustomTraceListener.txt", new[] { message });
        }

        private string FormatXml(string message)
        {
            using (var stringWriter = new StringWriter())
            {
                var xmlWriterSettings = new XmlWriterSettings();
                xmlWriterSettings.Encoding = Encoding.UTF8;
                xmlWriterSettings.Indent = true;
                xmlWriterSettings.OmitXmlDeclaration = true;

                using (var xmlTextWriter = XmlWriter.Create(stringWriter, xmlWriterSettings))
                {
                    XDocument.Parse(message).Save(xmlTextWriter);
                }

                return Convert.ToString(stringWriter);
            }
        }
    }
}

But even though it allows me to intercept the messages, it doesn't save any metadata:

<MessageLogTraceRecord Time="2013-07-16T10:50:04.5396082+02:00" Source="ServiceLevelSendRequest" Type="System.ServiceModel.Channels.BodyWriterMessage" xmlns="http://schemas.microsoft.com/2004/06/ServiceModel/Management/MessageTrace">
  <HttpRequest>
    <Method>POST</Method>
    <QueryString></QueryString>
    <WebHeaders>
      <VsDebuggerCausalityData>uIDPo4bOsuSXlSVEkmfof4AP2psAAAAAlEIoNto3KEWKgCnIGryjp9f3wbRlp+ROhY9Oy6bed/cACQAA</VsDebuggerCausalityData>
    </WebHeaders>
  </HttpRequest>
  <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
    <s:Header>
      <Action s:mustUnderstand="1" xmlns="http://schemas.microsoft.com/ws/2005/05/addressing/none">http://tempuri.org/IGreeterService/SayHello</Action>
      <ActivityId CorrelationId="964a7c4f-3b18-4b5d-8085-e00ae03b58d1" xmlns="http://schemas.microsoft.com/2004/09/ServiceModel/Diagnostics">80101cc1-dfb5-4c8e-8d19-ec848ab69100</ActivityId>
    </s:Header>
    <s:Body>
      <SayHello xmlns="http://tempuri.org/">
        <name>Albireo</name>
      </SayHello>
    </s:Body>
  </s:Envelope>
</MessageLogTraceRecord>
<MessageLogTraceRecord Time="2013-07-16T10:50:04.6176897+02:00" Source="TransportSend" Type="System.ServiceModel.Channels.BodyWriterMessage" xmlns="http://schemas.microsoft.com/2004/06/ServiceModel/Management/MessageTrace">
  <Addressing>
    <Action>http://tempuri.org/IGreeterService/SayHello</Action>
    <To>http://localhost:8080/greeter</To>
  </Addressing>
  <HttpRequest>
    <Method>POST</Method>
    <QueryString></QueryString>
    <WebHeaders>
      <VsDebuggerCausalityData>uIDPo4bOsuSXlSVEkmfof4AP2psAAAAAlEIoNto3KEWKgCnIGryjp9f3wbRlp+ROhY9Oy6bed/cACQAA</VsDebuggerCausalityData>
    </WebHeaders>
  </HttpRequest>
  <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
    <s:Header>
      <ActivityId CorrelationId="964a7c4f-3b18-4b5d-8085-e00ae03b58d1" xmlns="http://schemas.microsoft.com/2004/09/ServiceModel/Diagnostics">80101cc1-dfb5-4c8e-8d19-ec848ab69100</ActivityId>
    </s:Header>
    <s:Body>
      <SayHello xmlns="http://tempuri.org/">
        <name>Albireo</name>
      </SayHello>
    </s:Body>
  </s:Envelope>
</MessageLogTraceRecord>

With this information it's impossible to rebuild the request/response flow as all the messages are mixed together.

Compare them to the *.svclog generated by the native XmlWriterTraceListener:

<E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">
    <System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">
        <EventID>0</EventID>
        <Type>3</Type>
        <SubType Name="Information">0</SubType>
        <Level>8</Level>
        <TimeCreated SystemTime="2013-07-16T08:50:04.6176897Z" />
        <Source Name="System.ServiceModel.MessageLogging" />
        <Correlation ActivityID="{80101cc1-dfb5-4c8e-8d19-ec848ab69100}" />
        <Execution ProcessName="Playground.Client" ProcessID="4348" ThreadID="1" />
        <Channel />
        <Computer>ESP-DEV-9</Computer>
    </System>
    <ApplicationData>
        <TraceData>
            <DataItem>
                <MessageLogTraceRecord Time="2013-07-16T10:50:04.6176897+02:00" Source="TransportSend" Type="System.ServiceModel.Channels.BodyWriterMessage" xmlns="http://schemas.microsoft.com/2004/06/ServiceModel/Management/MessageTrace">
                    <Addressing>
                        <Action>http://tempuri.org/IGreeterService/SayHello</Action>
                        <To>http://localhost:8080/greeter</To>
                    </Addressing>
                    <HttpRequest>
                        <Method>POST</Method>
                        <QueryString></QueryString>
                        <WebHeaders>
                            <VsDebuggerCausalityData>uIDPo4bOsuSXlSVEkmfof4AP2psAAAAAlEIoNto3KEWKgCnIGryjp9f3wbRlp+ROhY9Oy6bed/cACQAA</VsDebuggerCausalityData>
                        </WebHeaders>
                    </HttpRequest>
                    <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
                        <s:Header>
                            <ActivityId CorrelationId="964a7c4f-3b18-4b5d-8085-e00ae03b58d1" xmlns="http://schemas.microsoft.com/2004/09/ServiceModel/Diagnostics">80101cc1-dfb5-4c8e-8d19-ec848ab69100</ActivityId>
                        </s:Header>
                        <s:Body>
                            <SayHello xmlns="http://tempuri.org/">
                                <name>Albireo</name>
                            </SayHello>
                        </s:Body>
                    </s:Envelope>
                </MessageLogTraceRecord>
            </DataItem>
        </TraceData>
    </ApplicationData>
</E2ETraceEvent>
<E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">
    <System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">
        <EventID>0</EventID>
        <Type>3</Type>
        <SubType Name="Information">0</SubType>
        <Level>8</Level>
        <TimeCreated SystemTime="2013-07-16T08:50:04.6957712Z" />
        <Source Name="System.ServiceModel.MessageLogging" />
        <Correlation ActivityID="{80101cc1-dfb5-4c8e-8d19-ec848ab69100}" />
        <Execution ProcessName="Playground.Client" ProcessID="4348" ThreadID="1" />
        <Channel />
        <Computer>ESP-DEV-9</Computer>
    </System>
    <ApplicationData>
        <TraceData>
            <DataItem>
                <MessageLogTraceRecord Time="2013-07-16T10:50:04.6801549+02:00" Source="TransportReceive" Type="System.ServiceModel.Channels.BufferedMessage" xmlns="http://schemas.microsoft.com/2004/06/ServiceModel/Management/MessageTrace">
                    <HttpResponse>
                        <StatusCode>OK</StatusCode>
                        <StatusDescription>OK</StatusDescription>
                        <WebHeaders>
                            <Content-Length>207</Content-Length>
                            <Content-Type>text/xml; charset=utf-8</Content-Type>
                            <Date>Tue, 16 Jul 2013 08:50:04 GMT</Date>
                            <Server>Microsoft-HTTPAPI/2.0</Server>
                        </WebHeaders>
                    </HttpResponse>
                    <s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/">
                        <s:Header></s:Header>
                        <s:Body>
                            <SayHelloResponse xmlns="http://tempuri.org/">
                                <SayHelloResult>Hello, Albireo.</SayHelloResult>
                            </SayHelloResponse>
                        </s:Body>
                    </s:Envelope>
                </MessageLogTraceRecord>
            </DataItem>
        </TraceData>
    </ApplicationData>
</E2ETraceEvent>

Here the <Correlation ActivityID="{80101cc1-dfb5-4c8e-8d19-ec848ab69100}" /> tag establishes a relation between each request and response, allowing a developer to rebuild the whole session.

Is there a way to accomplish what I'm trying to do?

Answer 1

If the service is registered as a WCF web-service (not as an old-school ASMX web-service) it's possible to do it through IClientMessageInspector and IEndpointBehavior.

First you have to create a class inheriting from IClientMessageInspector that will handle the logging of both the requests and the replies.

namespace Playground.Sandbox
{
    using System.ServiceModel;
    using System.ServiceModel.Channels;
    using System.ServiceModel.Dispatcher;

    public class MyClientMessageInspector : IClientMessageInspector
    {
        public object BeforeSendRequest(
            ref Message request,
            IClientChannel channel)
        {
            // TODO: log the request.

            // If you return something here, it will be available in the 
            // correlationState parameter when AfterReceiveReply is called.
            return null;
        }

        public void AfterReceiveReply(
            ref Message reply,
            object correlationState)
        {
            // TODO: log the reply.

            // If you returned something in BeforeSendRequest
            // it will be available in the correlationState parameter.
        }
    }
}

Then you have to create a class inheriting from IEndpointBehavior that will register the inspector in the client.

namespace Playground.Sandbox
{
    using System.ServiceModel.Channels;
    using System.ServiceModel.Description;
    using System.ServiceModel.Dispatcher;

    public class MyEndpointBehavior : IEndpointBehavior
    {
        public void Validate(
            ServiceEndpoint endpoint)
        {
        }

        public void AddBindingParameters(
            ServiceEndpoint endpoint,
            BindingParameterCollection bindingParameters)
        {
        }

        public void ApplyDispatchBehavior(
            ServiceEndpoint endpoint,
            EndpointDispatcher endpointDispatcher)
        {
        }

        public void ApplyClientBehavior(
            ServiceEndpoint endpoint,
            ClientRuntime clientRuntime)
        {
            var myClientMessageInspector = new MyClientMessageInspector();

            clientRuntime.ClientMessageInspectors.Add(myClientMessageInspector);
        }
    }
}

Then when you want to use the behavior you can manually register it before using the service.

namespace Playground.Sandbox
{
    public static class Program
    {
        public static void Main()
        {
            using (var client = new MyWcfClient())
            {
                var myEndpointBehavior = new MyEndpointBehavior();

                client.Endpoint.Behaviors.Add(myEndpointBehavior);

                // TODO: your things with the client.
            }
        }
    }
}

If you don't want to register the behavior manually or you need it to be always active, you can register it in the configuration file.

First you need to create a class inheriting from BehaviorExtensionElement, this class will tell the .NET Framework which behavior will be applied and will create the instance when needed.

namespace Playground.Sandbox
{
    using System;
    using System.ServiceModel.Configuration;

    public class MyBehaviorExtensionElement : BehaviorExtensionElement
    {
        protected override object CreateBehavior()
        {
            var myEndpointBehavior = new MyEndpointBehavior();

            return myEndpointBehavior;
        }

        public override Type BehaviorType
        {
            get
            {
                return typeof(MyEndpointBehavior);
            }
        }
    }
}

Then you need to register the BehaviorExtensionElement in the configuration file (only the relevant part of the configuration file are shown).

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
    <startup>
        <supportedRuntime sku=".NETFramework,Version=v4.5"
                          version="v4.0" />
    </startup>
    <system.serviceModel>
        <behaviors>
            <endpointBehaviors>
                <behavior name="withMyBehaviorExtensionElement">
                    <myBehaviorExtensionElement />
                </behavior>
            </endpointBehaviors>
        </behaviors>
        <client>
            <endpoint address="..."
                      behaviorConfiguration="withMyBehaviorExtensionElement"
                      binding="..."
                      bindingConfiguration="..."
                      contract="..."
                      name="..." />
        </client>
        <extensions>
            <behaviorExtensions>
                <add name="myBehaviorExtensionElement"
                     type="Playground.Sandbox.MyBehaviorExtensionElement, Playground.Sandbox" />
            </behaviorExtensions>
        </extensions>
    </system.serviceModel>
</configuration>

Now you can use the service without manually registering the behavior each time:

namespace Playground.Sandbox
{
    public static class Program
    {
        public static void Main()
        {
            using (var client = new MyWcfService())
            {
                // TODO: your things with the client.
            }
        }
    }
}

You can find a guide on how to do this in the MSDN's Message Inspectors article.