Nice input parameter logging in WCF

Let’s say you have a WCF service, for use by you ore some customer. Here is a really simple client, which uses a random number generator service:

Press the button, and you get a random number. Check the box, and there will be a server-side exception to fake a bug in the server-side execution.
What will the user of this really useful service say when, instead of a nice random number, he gets the following response:

He will say: Well, mister, you got a bug in your service, and you’ll need to fix that, or we won’t pay you.
Uh-oh. No money. Your company will be broke, and you will lose your job. Unless you can trace and fix the bug real quick. You do have proper exception logging, right?
No, you probably don’t. Or perhaps you do, but it really clutters your business logic in the service implementation


Let’s say the service contract looks like this:

    [ServiceContract]
    public interface IRandomNumberGenerator
    {
        [OperationContract]
        int GenerateRandomNumber(string whoIsAsking, bool generateBug);
    }

Proper logging is absolutely crucial when it comes to identifying and fixing bugs. This is especially true in a commercial application, where it just won’t do to not know what’s going on when things start failing. Your company will lose money, you might lose your job.

Unfortunately, a lot of detailed error-logging will clutter your code, wrapping it in a general exception logging block, for every service method and taking focus from the business logic at hand, like this:

int IRandomNumberGenerator.GenerateRandomNumber(string whoIsAsking, bool generateBug)
        {
            try
            {
                //// The business logic, which should be the real focus in this code
                return 0;
            }
            catch (Exception exc)
            {
                //// Some meaningful exception logging 
                Console.WriteLine("Error in method GenerateRandomNumber");
                Console.WriteLine("arg0: ", whoIsAsking);
                Console.WriteLine("arg1: ", generateBug);
                Console.WriteLine("exception: ", exc);
                throw;
            }
        }

Of course the real logging should not write output to console, but you get the point.

What to do to avoid this cluttering, and repetitive writing of logging code? A colleague of mine started writing some static methods to wrap execution in a general error-logging code block. But that still clutters the code, and you cannot log the input parameters. Oh, by the way. Static classes and methods are a really bad idea, as you cannot do proper testing with such things involved.

So we would like to do some kind of aspect-oriented programming to completely remove the exception logging from the business logic. You could use an aspect-orient framework like PostSharp. Or you could tap into the hooks already provided by the WCF framework

Here comes the IOperationInvoker interface! What it does is it lets you customize the calling of your service. This happens after the message has been decoded by the framework, so you have access to all the parameters also. Perfect!

All you have to do is write a class which implements the interface:

public class CustomOperationInvoker : IOperationInvoker
    {
        private readonly IOperationInvoker innerOperationInvoker;
        private readonly string name;

        public CustomOperationInvoker(
            string name,
            IOperationInvoker innerOperationInvoker)
        {
            this.innerOperationInvoker = innerOperationInvoker;
            this.name = name;
        }

        object IOperationInvoker.Invoke(
            object instance,
            object[] inputs,
            out object[] outputs)
        {
            try
            {
                return this.innerOperationInvoker.Invoke(instance, inputs, out outputs);
            }
            catch (Exception exc)
            {
                Console.WriteLine("Error in method:");
                int paramNo = 0;
                Console.WriteLine(this.name);
                foreach (var input in inputs)
                {
                    Console.WriteLine("arg{0}: {1}", paramNo, input);
                    paramNo++;
                }

                Console.WriteLine("exception:");
                Console.WriteLine(exc.ToString());

                throw;
            }
        }

You can see that this not only manages to log all exceptions of all services, but that it also writes out all the input arguments, which is extremely useful, if not crucial, when tracking down bugs.

To hook into WCF with your custom code, you need to tell WCF to use your code. You can do it by static compile-time attributes, or you can do it using configuration. I genereally don’t like static things, so I go for the configuration setup, as it allows you to change things in run-time.

This case is a bit special, where we want all operations on your endpoint to use this logging (=implement IEndpointBehavior), but you need data only available when implementing IOperationBehavior. This also needs to be able to be injected in configuration, thus it needs to inherit BehaviorExtensionElement:

class OperationInvokerExtensionElement 
        : BehaviorExtensionElement,
        IEndpointBehavior,
        IOperationBehavior
    {
        public override Type BehaviorType
        {
            get { return typeof(OperationInvokerExtensionElement); }
        }

        protected override object CreateBehavior()
        {
            return new OperationInvokerExtensionElement();
        }

        void IEndpointBehavior.ApplyDispatchBehavior(
            ServiceEndpoint endpoint,
            EndpointDispatcher endpointDispatcher)
        {
            foreach (var op in endpoint.Contract.Operations)
            {
                op.Behaviors.Add(this);
            }
        }

        void IOperationBehavior.ApplyDispatchBehavior(
            OperationDescription operationDescription, 
            DispatchOperation dispatchOperation)
        {
            dispatchOperation.Invoker = new CustomOperationInvoker(
                dispatchOperation.Name,
                dispatchOperation.Invoker);
        }

Using this class, your configuration may look like:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <system.serviceModel>
    <extensions>
      <behaviorExtensions>        <add name="operationInspectionBehaviour"
            type="ServiceImplementation.OperationInvokerExtensionElement, ServiceImplementation"/>
      </behaviorExtensions>
    </extensions>

    <behaviors>
      <endpointBehaviors>
        <behavior name="inspectionBehavior">          <operationInspectionBehaviour/>
        </behavior>
      </endpointBehaviors>
    </behaviors>

    <bindings>
      <basicHttpBinding>
        <binding name="httpBinding" >
        </binding>
      </basicHttpBinding>
    </bindings>
    <services>
      <service name="ServiceImplementation.RandomNumberGeneratorService">
        <endpoint address="http://localhost:16667/RandomNumberGeneratorService"
          binding="basicHttpBinding" bindingConfiguration="httpBinding"
          name="serverHost" contract="Contracts.IRandomNumberGenerator" behaviorConfiguration="inspectionBehavior" />      </service>
    </services>
  </system.serviceModel>
</configuration>

All pieces together, you will get the following server-side log:

Error in method:
GenerateRandomNumber
arg0: Nicke
arg1: True
exception:
System.Exception: There is a bug in the code
   at ServiceImplementation.RandomNumberGeneratorService.Contracts.IRandomNumberGenerator.GenerateRandomNumber(String whoIsAsking, Boolean generateBug) in c:\Users\niklas\Documents\Visual Studio 2012\Projects\MessageInspectorTesting\ServiceImplementation\RandomNumberGeneratorService.cs:line 18
   at SyncInvokeGenerateRandomNumber(Object , Object[] , Object[] )
   at System.ServiceModel.Dispatcher.SyncMethodInvoker.Invoke(Object instance, Object[] inputs, Object[]& outputs)
   at ServiceImplementation.CustomOperationInvoker.System.ServiceModel.Dispatcher.IOperationInvoker.Invoke(Object instance, Object[] inputs, Object[]& outputs)
in c:\Users\niklas\Documents\Visual Studio 2012\Projects\MessageInspectorTesting\ServiceImplementation\CustomOperationInvoker.cs:line 29

So not only do you see the exception and the stack trace, you also see the input parameters which made the service throw an exception. looking at the code, and at “arg1”, you see that the customer has called your service incorrectly, telling the service to create a fake bug! Oh, doesn’t feel good the times when the error is not in the code, but that the customer is using it wrong!

Disclaimer: No production code should look like this, all code here is just for illustrative purposes, written with a bit of sarcasic humor. And remember that the customer is always right, he’s the one who pays your salary!