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!

A multi-user physics simulation space-game in Silverlight and F#

I’ve been spending a lot of this year’s summer vacation on learning F# more deeply.
I truly believe in the concept learning by doing, and learning on demand, instead of learn everything first, then see if you can have any use of it.
So to learn F# I decided to create an online multiplayer game based on physics simulation, where you fly around in a spaceship and collect money and shoot other spaceships.
I will be writing more on the creation and development, but for now, Try it out.
The controls are zoom, steer and fire with the mouse, and throttle with space.
You have to press the "connect" button first

A lazy lazy program in f#

I was trying to learn a bit more on computation expressions, and wanted to write my own minimalistic expression builder. Just to get the feel for it.

I decided to give a shot at making an expression builder for the Lazy<’T> type. Sure, this wouldn’t give much benefit, just a more smooth way och combining lazies without constantly accessing the Value property.

Here is what I came up with:

open System

let bind (x : Lazy<'a>) (f : 'a -> Lazy<'b>) = lazy f(x.Value).Value

type LazyBuilder() =
    member this.Bind(x : Lazy<'a>, f : 'a -> Lazy<'b>) = bind x f
    member this.Return<'T> (x : 'T) : Lazy<'T> = Lazy.CreateFromValue x

let lz = LazyBuilder()

let readNumber() = lazy (
            Console.WriteLine "Enter a number:"
            let v = Console.ReadLine()
            Double.Parse v)

let l = lz{
    let! x = readNumber()
    let! y = readNumber()
    return x * y
    }

Console.WriteLine "before execution"
Console.WriteLine ("Result: " + l.Value.ToString())
Console.ReadKey() |> ignore

It yields output like this:

before execution
Enter a number:
67
Enter a number:
3
Result: 201
Press a key to quit

F# Discriminated Union WCF, and DataContract attribute

I am working on an online multiplayer game in F#, and using WCF as the framework for communication.

Wanting to include the extremely useful feature of discriminated unions as parameters in ServiceContract:s, I marked my discriminated union with the DataContractAttribute. And the problems started!

Looking around the net I found a solution, in that you need to add a KnownTypeAttribute to the union, according to an example found on stack overflow.

Using the code from the link, the only conceptual difference was that I used the DataContractAttribute. I wanted to do WCF, right? So my code looked like this:

open Microsoft.FSharp.Reflection
open System.Reflection
open System.Runtime.Serialization
open System.Xml

[<KnownType("KnownTypes")>]
[<DataContract>]
type Union21WithKnownTypes =
| Case1 of int * int
| Case2 of string
static member KnownTypes() =
typeof<Union21WithKnownTypes>.GetNestedTypes(
BindingFlags.Public
||| BindingFlags.NonPublic) |> Array.filter FSharpType.IsUnion

let dcs = new DataContractSerializer(typeof<Union21WithKnownTypes[]>)
let arr = [| Case1(1,1);Case2("2");|]
printfn "orig data: %A" arr
let sb = new System.Text.StringBuilder()
let xw = XmlWriter.Create(sb)
dcs.WriteObject(xw, arr)
xw.Close()
let s = sb.ToString()
printfn ""
printfn "encoded as: %s" s
printfn ""
let xr = XmlReader.Create(new System.IO.StringReader(s))
let o = dcs.ReadObject(xr)
printfn "final data: %A" o
System.Console.ReadKey() |> ignore

This example runs fine, the output looks like:

orig data: [|Case1 (1,1); Case2 "2"|]
encoded as: ...
final data: [|Case1 (1,1); Case2 "2"|]


However, use a discriminated union with only one case, and strange things start to happen. Chang the code according to:

[<KnownType("KnownTypes")>]
[<DataContract>]
type Union21WithKnownTypes =
| Case1 of int * int
static member KnownTypes() =
typeof<Union21WithKnownTypes>.GetNestedTypes(
BindingFlags.Public
||| BindingFlags.NonPublic) |> Array.filter FSharpType.IsUnion

let arr = [| Case1(1,1);|]

This yields the output

orig data: [|Case1 (1,1); Case1 (2,2)|]
encoded as: ...
final data: [|Case1 (0,0); Case1 (0,0)|]


Ok, so now the values are not serialized, and of course yields the wrong deserialized values.
By adding a dummy case to the union like this:

[<KnownType("KnownTypes")>]
[<DataContract>]
type Union21WithKnownTypes =
| Case1 of int * int
| Dummy
static member KnownTypes() =
typeof<Union21WithKnownTypes>.GetNestedTypes(
BindingFlags.Public
||| BindingFlags.NonPublic) |> Array.filter FSharpType.IsUnion

The serialization magically works again:

orig data: [|Case1 (1,1); Case1 (2,2)|]
encoded as: ...
final data: [|Case1 (1,1); Case1 (2,2)|]


You might of course have several cases in your unions, which is fine... Kind of...

[<KnownType("KnownTypes")>]
[<DataContract>]
type Union21WithKnownTypes =
| Case1 of int * int
| Dummy
static member KnownTypes() =
typeof<Union21WithKnownTypes>.GetNestedTypes(
BindingFlags.Public
||| BindingFlags.NonPublic) |> Array.filter FSharpType.IsUnion

let arr = [| Case1(1,1);Case2(2);Case3(3);|]

This works just fine as expected. However, just you dare to have more than three options like this:

[<KnownType("KnownTypes")>]
[<DataContract>]
type Union21WithKnownTypes =
| Case1 of int * int
| Case2 of int
| Case3 of int
| Case4 of int
static member KnownTypes() =
typeof<Union21WithKnownTypes>.GetNestedTypes(
BindingFlags.Public
||| BindingFlags.NonPublic) |> Array.filter FSharpType.IsUnion

And the deserialization will fail you in the following way:

orig data: [|Case1 (1,1); Case2 2; Case3 3|]
encoded as: ...
final data: Error: Object does not match target type.


I spent hours ripping my hair over this problem, but finally, finally realized the DataContract Attribute was to blame so simply remove the attribute, and serialization works like a charm, even for WCF.

[<KnownType("KnownTypes")>]
type Union21WithKnownTypes =
| Case1 of int * int
| Case2 of int
| Case3 of int
| Case4 of int
static member KnownTypes() =
typeof<Union21WithKnownTypes>.GetNestedTypes(
BindingFlags.Public
||| BindingFlags.NonPublic) |> Array.filter FSharpType.IsUnion

Hope that helps.