Logging WCF messages generically

I recently felt the need to log incoming and outgoing messages from WCF without cluttering my operation contract implementations. I believe that this type of “debug” logging in the early stages of a project should if possible be done generically and externally. First of all I started out with following Andreas Öhlund’s post about how to setup WCFusing StructureMap. With this as a ground to stand on it wasn’t too much problem adding the logging part. To begin with I have a “MessageBase” that all my messages inherit from. Any message that inherits from this class does automatically use override ToString() from it’s base class. ToString just used the Serialize method to get a valid xml document. I have a certain logger for this so that I can turn it on and off easily for debugging purposes. Since this is the entry point towards the clients and this communication cant be durable (more info here)  though the rest of the backend is this is a great resource for tracking down potential future problems and something I need myself during integration tests. Anyway enough of the small talk. Let’s get down to business.

public interface IMessageBase<T> where T : class
{
    String Serialize(T data);
    T Deserialize(string text);
}

public abstract class MessageBase<T> : IMessageBase<T> 
	where T : class
{
	public String Serialize(T data)
	{
		using (var stringWriter = new StringWriter())
		{
			var settings = new XmlWriterSettings
						   {
							   Encoding = Encoding.UTF8,
							   OmitXmlDeclaration = true
						   };
			using 
			(var writer = XmlWriter.Create(stringWriter, settings))
			{
				var xmlSerializer = new XmlSerializer(typeof (T));
				xmlSerializer.Serialize(writer, data);
			}

			return stringWriter.ToString();
		}
	}

	public T Deserialize(string text)
	{
		T data;

		var settings = new XmlReaderSettings
						   {
							   IgnoreWhitespace = true
						   };

		using (var reader = XmlReader.Create(
			new MemoryStream(
				Encoding.UTF8.GetBytes(text)), 
				settings))
		{
			var xmlSerializer = new XmlSerializer(typeof (T));
			data = (T) xmlSerializer.Deserialize(reader);
		}

		return data;
	}

	public override string ToString()
	{
		return Serialize(this as T);
	}
}

Since I already have a UnitOfWorkMessageInspector (thank you Andreas) adding another one for the logging is not a hard thing to do.

Let’s start with the MessageInspector, just like with the UoW one Andreas created we implement the interface IDispatchMessageInspector.

public class LoggingMessageInspector : IDispatchMessageInspector
{
	public object AfterReceiveRequest(ref Message request,
		IClientChannel channel,
		InstanceContext instanceContext)
	{
		LogMessage(ref request);

		return null;
	}

	public void BeforeSendReply(ref Message reply, 
		object correlationState)
	{
		LogMessage(ref reply);
	}

	private void LogMessage(ref Message message)
	{
		LogManager.GetLogger("Messages").Debug(message.ToString());
	}
}

Dead easy right? I have two concerns now:

1. I have no idea why message.ToString() gives me the actual xml string because Message is a WCF class. I suppose it wraps my MessageBase implementation and use that ToString() I actually didn’t check this yet.
2. This works very well for messages BUT I have a few scenarios when the message is a Stream and in these cases only …. Stream …. is logged to the text file.

To wire this up in StructureMap is not a big problem. What we need to do now is to replace “Use” (which sets the default instance to use) to “Add“ which adds instances to use in the order they are added to StructureMap.

For<IDispatchMessageInspector>()
	.AddInstances(x =>
			{
				x.Type(typeof (LoggingMessageInspector));
				x.Type(typeof (UnitOfWorkMessageInspector));
			});

It’s not complete yet as I mentioned I need to figure out how to log the stream parameter.