IEndpointBehavior life cycle / logging service calls

Question

I'm trying to log all outbound requests that go to service references, including the full request and response body. I thought I had a solution using behaviorExtensions but, after deploying, it became clear that the extension was shared between multiple requests.

Here's my current code:

public class LoggingBehaviorExtender : BehaviorExtensionElement
{
    public override Type BehaviorType => typeof(LoggingRequestExtender);
    protected override object CreateBehavior() { return new LoggingRequestExtender(); }
}

public class LoggingRequestExtender : IClientMessageInspector, IEndpointBehavior
{
    public string Request { get; private set; }
    public string Response { get; private set; }

    #region IClientMessageInspector

    public virtual object BeforeSendRequest(ref System.ServiceModel.Channels.Message request, System.ServiceModel.IClientChannel channel)
    {
        Request = request.ToString();
        Response = null;
        return null;
    }
    public virtual void AfterReceiveReply(ref System.ServiceModel.Channels.Message reply, object correlationState)
    {
        Response = reply.ToString();
    }

    #endregion

    #region IEndpointBehavior

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

    public void ApplyClientBehavior(ServiceEndpoint endpoint, ClientRuntime clientRuntime)
    {
        clientRuntime.MessageInspectors.Add(this);
    }

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

    public void Validate(ServiceEndpoint endpoint) { }

    #endregion
}

Then, when I reach the point to log, I extract the behavior...

var lre = client.Endpoint.Behaviors.OfType<LoggingRequestExtender>().FirstOrDefault();
var req = lre?.Request;
var resp = lre?.Response;

Adding debugging logging to the LoggingRequestExtender, I found it was only instantiated once for multiple requests.

Is there a way to make sure this behavior class is instantiated fresh for each thread? Or is there a better way of getting the full request / response body when making service calls?

Edit / Partial answer:

Since writing this I have discovered that the value returned by BeforeSendRequest is passed into AfterReceiveReply as the correlationState so I can connect the request and response using a guid:

public virtual object BeforeSendRequest(ref System.ServiceModel.Channels.Message request, System.ServiceModel.IClientChannel channel)
{
    var guid = Guid.NewGuid();
    WebServiceLog.LogCallStart(guid, channel.RemoteAddress.ToString(), request.ToString());
    return guid;
}

public virtual void AfterReceiveReply(ref System.ServiceModel.Channels.Message reply, object correlationState)
{
    Guid guid = (Guid)correlationState;
    WebServiceLog.LogCallEnd(guid, reply.ToString());
}

I see two flaws to this approach. One, which is livable, is that this requires a log insert and then update rather than a single insert.

The second is more of an issue: In the case of an exception (e.g. timeout), we never hit AfterRecieveSupply so the log doesn't know what happened. I can separately log the exception...

try
{
    response = client.SomeFunction(request);
}
catch (Exception ex)
{
    AppLog.Error("Some function failed", ex);
}

... but I can't see a way of accessing the guid outside of BeforeSendRequest / AfterReceiveReply so I have nothing to tie the exception log to the service request log.

Answer 1

There are several approaches to this.

1, The situation you have described with having to log calls separately doesn't have to be like that. If your WCF service is in a non load balanced server just add the request to a MemoryCache using the Guid as a key. When the request comes in then pull off the request and log in one go. To capture the timed out calls you could run a process on a thread that would check the MemoryCache every x minutes to pull out and log (using an adequate lock to ensure thread saftey).

If the WCF service is in a load balanced environment then all you do is the same as above but store to a no sql type data store.

2, Is the code that makes the outbound calls within your scope for change? If so, you can forgo creating a behavior extension and create a bespoke message logger instead. Using a class that implements IDisposable you can write nice code like this..

RequestMessage request = new RequestMessage();  
ResponseMessage response = null;

using (_messageLogger.LogMessage(request, () => response, CallContextHelper.GetContextId(), enabled))
{
  response = _outboundService.DoSomething(request);  
}

This will then not need another process to capture any timed out threads which will be handled in the dispose method.

If you need more clarity then let me know, hopefully this helps you...