Category Archives: Dependency Injection

log4net PatternLayout and PatternConverter

I have the following scenario:

I’m using Unity dependency injection container and interception techniques to log some WCF operation calls. I need to log the input parameters and also the result of these operations so I’ve implemented a CallHandler that I can apply to whatever methods that I need to intercept.

In this CallHandler I’ve defined a class called LogEntry and I’m logging with log4net. Something like this:


LogEntry logEntry = new LogEntry();
....
// set some base properties
logEntry.MethodName = input.MethodBase.Name;
logEntry.TypeName = input.Target.GetType().FullName;
...
// set input parameters
logEntry.Input = ....;
...
// set return value
logEntry.ReturnValue = result.ReturnValue;
.....
// set total method duration
logEntry.CallTime = stopwatch.Elapsed.TotalMilliseconds;
.....

// use log4net logger to log this information
logger.Debug(logEntry);

So this LogEntry class has some properties that will hold the information that I want to log. Now I need to capture these properties and configure the log4net appenders properly.

I’m using log4net PatternLayout and PatternConverter features. Let’s start with PatternLayout


///<summary>
/// Extended version of <see cref="PatternLayout"/>
/// </summary>


public class ExtendedPatternLayout : PatternLayout
{
 ///<summary>
 /// Initializes a new instance of the <see cref="ExtendedPatternLayout"/> class.
 /// </summary>;


 public ExtendedPatternLayout()
 {
   this.AddConverter(new ConverterInfo()
   {
     Name = "logEntry",
     Type = typeof(LogEntryConverter),
   });
 }
}

This layout just adds a new Converter named “logEntry” implemented by the class LogEntryConverter. There is no reference to LogEntry class here. And the LogEntryConverter class is here:


 /// <summary>
 /// Custom <see cref="PatternConverter"/> to handle <see cref="LogEntry"/>
 /// </summary>
 public class LogEntryConverter : PatternConverter
 {
   /// <summary>
   /// Converts the specified writer.
   /// </summary>
   /// <param name="writer">The writer.</param>
   /// <param name="state">The state.</param>
   protected override void Convert(System.IO.TextWriter writer, object state)
   {
       var loggingEvent = state as LoggingEvent;
       var logEntry = loggingEvent.MessageObject as LogEntry;

       if (logEntry != null)
       {
          switch (this.Option.ToLower())
          {
             case "calltime":
               writer.Write(logEntry.CallTime.HasValue ? logEntry.CallTime.Value : 0);
               break;
             case "methodname":
               writer.Write(logEntry.MethodName);
               break;
             case "returnvalue":
               writer.Write(SerializationService.SerializeToJSON(logEntry.ReturnValue));
               break;
             ..........
             ..........
             default:
               writer.Write(string.Empty);
               break;
          }
       }
    }
 }

I’ve made the code smaller but you need to check for null references!

I’m using a JSON serialization technique to grab the representation of the method’s return value.

I need to override the Convert method and access state object that is a log4net LoggingEvent object. This object has my logged object from the CallHandler which is a LogEntry object. Based on the Option property of the converter I can choose which property to write.

And finally I can configure my log4net like this


<layout type="ExtendedPatternLayout">
  <conversionPattern value="%logEntry{CallTime}" />
</layout>

You can see the conversionPattern follows this syntax: %convertername{option}

Add WCF Message Id in every log4net message

I needed to have the WCF message identifier in every log message because I needed to correlate the log messages from a particular WCF call.

The best way to achieve this with log4net is to use context properties.

Since I’m already using Unity and Interception on my WCF Services, I’ve decided to implement a custom Call Hander


namespace CustomCallHandlers
{
 using System;
 using Microsoft.Practices.Unity.InterceptionExtension;

 /// <summary>
 /// Call Handler to setup wcf message id in log4net context
 /// </summary>
 public class ServiceCallHandler : ICallHandler
 {
 /// <summary>
 /// The message identifier
 /// </summary>
 private const string MessageIdKey = "MessageId";

 /// <summary>
 /// Initializes a new instance of the <see cref="ServiceCallHandler"/> class.
 /// </summary>
 /// <param name="order">The call handler's execution order.</param>
 public ServiceCallHandler(int order)
 {
  this.Order = order;
 }

 /// <summary>
 /// Gets or sets the order.
 /// </summary>
 public int Order { get; set; }

 /// <summary>
 /// Invokes the specified input.
 /// </summary>
 /// <param name="input">The input.</param>
 /// <param name="getNext">The get next.</param>
 /// <returns>The method return for the nexte invocation</returns>
 public IMethodReturn Invoke(IMethodInvocation input, GetNextHandlerDelegate getNext)
 {
  if ((System.ServiceModel.OperationContext.Current != null) &&
      (System.ServiceModel.OperationContext.Current.IncomingMessageHeaders != null))
  {
   if (System.ServiceModel.OperationContext.Current.IncomingMessageHeaders.MessageId != null)
   {
    string messageId = System.ServiceModel.OperationContext.Current.IncomingMessageHeaders.MessageId.ToString();
    log4net.ThreadContext.Properties[MessageIdKey] = messageId == "(null)" ? Guid.NewGuid().ToString() : messageId;
   }
  }

  IMethodReturn resultado = getNext()(input, getNext);

  // Cleaning
  log4net.ThreadContext.Properties[MessageIdKey] = null;

  return resultado;
  }
 }
}

If you want to see how to configure log4net appenders to write custom properties check this post.