Logging with PostSharp and NLog

For my first article I will cover the inanely boring aspect of logging and show you how to build an easily configurable and somewhat invisible logging component that is virtually set and forget for any application. By the end off this article you will have Trace level logging enabled for every method in you project, and only one existing class needs to be modified. Sounds good? Yeah it is.

This article will be using Microsoft’s .Net framework with its C# language. In addition, we will be using the third party logging tool NLog and the AOP/IL Weaver libraries from Post Sharp.

First and foremost we will deal with logging. Logging is an important part of software development but often neglected as it is a non functional deliverable and often only really used in later stages of the application lifecycle when bugs are to be investigated. Personally I prefer to set up logging early on in the project, if possible in the first iteration with other non functional deliverables. Having a logging component ready to go can make this process a lot easier, hence the reason for writing this article. One of the major problems with logging is that is creeps into all aspects and layers of the applications code. This phenomenon makes it a “cross cutting concern” and it means it is not so easily separated from the application, it instead roots itself into the application, making it very hard to make wholesale changes to the way you interact with your logging framework.

For this reason I will be using an AOP-like framework called PostSharp. PostSharp give you the ability to weave coding logic into the application at build time, meaning cleaner code that deals with the business problem at hand and is not littered with logging statements.


So let’s get started. Firstly we will download the NLog assemblies to be used in the application. At the time of writing this article the latest version is 1.0 and can be downloaded via the NLog site.

Next download the Postsharp assemblies. At the time of writing this article the latest version is RC 1.0 and can be downloaded via the PostSharp site.

Create a new class library project in Visual Studio (or whatever IDE you are using). I have called mine ArtemisWest.Logging. Include references to NLog, Postshapr.Laos & PostSharp.Public. These should have been GAC’ed on installing them. If not, locate the folder where these DLL’s where downloaded to.

Add a C# file to the project and call the class TraceLoggingAttribute. As you may guess we will be write an attribute class that will be used to decorate other assemblies (or classes or methods). The code for the class is below:

using System;
using NLog;
using PostSharp.Laos;
namespace ArtemisWest.Logging
{
/// <summary>
/// AOP based logging attribute to enable trace logging on entry and exit of any sub component of the
/// component marked with the attribute.
/// For example marking an assembly with the this attribute will allow trace debugging on all methods
/// of all classes with in that assembly.
/// </summary>
 [Serializable]
public sealed class TraceLoggingAttribute : OnMethodBoundaryAspect
{
#region Private Variables
/// <summary>
/// The NLog static logging componet that will beused to write the logging messages
/// </summary>
 private static Logger logger = LogManager.GetCurrentClassLogger();
/// <summary>
/// The name of the assembly we are logging on
/// </summary>
 private readonly string assembly;
#endregion

#region Constructor
/// <summary>
/// Initializes a new instance of the <see cref="TraceLoggingAttribute"/> class.
/// </summary>
/// <param name="assembly">The assembly.</param>
public TraceLoggingAttribute( string assembly)
{
this.assembly = assembly;
}
#endregion
#region Read Only Properties
/// <summary>
/// Gets the assembly.
/// </summary>
/// <value>The assembly.</value>
public string Assembly { get { return assembly; } }
#endregion

#region Overriden OnMethodBoundaryAspect Events /// <summary>
/// The code to be woven into the start of the method. This will be run before any of the other visible code in the method
/// This will specifically tell us when the method has begun along with
///     Assembly, Class and Method name,
///     Method Parameters
///     and the Reference to this specific instance of the method.
/// </summary>
/// <param name="eventArgs"></param>
/// <inheritdoc/>
public override void OnEntry(MethodExecutionEventArgs eventArgs)
{
Guid reference = Guid.NewGuid();
logger.Trace(string.Format("\r\nEntering Assembly: {0}\r\n\t{1}.{2}. \r\n\tMethod reference: {3}",
this.Assembly,
eventArgs.Method.DeclaringType.Name,
eventArgs.Method.Name,
reference.ToString()),
eventArgs.GetArguments());
eventArgs.MethodExecutionTag = reference;
}
/// <summary>
/// The code to be woven into the end of the method. This will be run before exiting the method.
/// This will specifically tell us when the method has completed along with
///   Assembly, Class and Method name,
///   Method Parameters,
///   Return Value
///   and the Reference to this specific instance of the method.
/// </summary>
/// <param name="eventArgs"></param>
/// <inheritdoc/>
public override void OnExit(MethodExecutionEventArgs eventArgs)
{
string returnValue = (eventArgs.ReturnValue != null ?
eventArgs.ReturnValue.ToString() :
"null/nothing");

logger.Trace(string.Format("\r\nExiting Assembly: {0}\r\n\t{2}.{3}. \r\n\tReturning value {1}\r\n\tMethod reference: {4}",
this.Assembly,
returnValue,
eventArgs.Method.DeclaringType.Name,
eventArgs.Method.Name,
eventArgs.MethodExecutionTag.ToString()),
eventArgs.GetArguments());
}

/// <summary>
/// Ensure any unhandled exceptions are logged also.
/// </summary>
/// <param name="eventArgs"></param>
/// <inheritdoc/>
public override void OnException(MethodExecutionEventArgs eventArgs)
{
base.OnException(eventArgs);
logger.ErrorException(string.Format("Assembly: {0}\r\nException at {1}.{2}. Method reference: {3}",
this.Assembly,
eventArgs.Method.DeclaringType.Name,
eventArgs.Method.Name,
eventArgs.MethodExecutionTag.ToString()),
eventArgs.Exception);
}

#endregion }
}

We now have a vanilla trace logging attribute that can be applied to an assembly to log the entry, exit and exceptions for any method with in that assembly.

Key aspects of this class are:

  • The using statements. We need to reference PostSharp and NLog so we can implement their functionality.
  • The Serializable Attribute on the class. This is required by PostSharp.
  • The inheritance of OnMethodBoundaryAspect. This is so we can override the OnEntry and OnExit events so we can weave the logging into the methods.
  • The assignment of the logger from the NLog LogManger
  • The overridden events. We have chosen to put logging into these events, however other cross cutting concerns like caching or security could also be added is a similar fashion.

Now we need to add this attribute to an assembly. Let’s assume we are writing an ASP.Net application. In my mind the best place to put the attribute in this instance would be in the AssemblyInfo.cs class as this will be the easiest (and most intuitive) place to find the attribute later on.

 

using ArtemisWest.Logging;
[assembly: TraceLogging("ArtemisWest.Web")]

 

Before this will work we need to add to this project a reference to ArtemisWest.Logging, Postshapr.Laos & PostSharp.Public.

Logging is now enabled for the whole assembly.

Unfortunately the logging framework has no idea what to do when we ask it to log for us. We need to add some config setting to application. As we are writing an ASP.Net application we will need to modify the web.config. In the configuration we need to add a section reference: 

<configuration>
  <configSections>
    <section name="nhibernateSettings"
      type="C4.Programme.Library.CommonOpenSessionInViewSection, C4.Programme.Library.Common" />
    <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog" />
  </configSections>
  <!—Config continues below… -->
Then we need to define what the logger is to do: 
  <nlog xmlns=" http://www.nlog-project.org/schemas/NLog.xsd"   xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" throwExceptions="true" internalLogFile=" Nlog.txt">
    <targets>
      <target name="file" xsi:type="File"
              layout="${longdate} ${level} ${message} ${exception:format=tostring}"
              fileName="${basedir}/${shortdate}.txt"/>
    </targets>
    <rules>
      <logger name="*" minlevel="Trace" writeTo="file" />
    </rules>
  </nlog>
</configuration>

This specific configuration will log to a file with the current date as the file name, in the base directory of the application and will log anything above the trace level (ie everything). This will also log and internal NLog exceptions to the Nlog.txt file (normally NLog exceptions are ignored).

What have we achieved?

  • We have a reusable logging attribute that can be used on any.net assembly to enable assembly wide trace logging.
  • We have kept our original code that contains our business logic clean and free of unwanted logging calls. We have only modified the web.config file and ONE class file!
  • We have a fully configurable logging framework that can log what we want, to where we want it and how we what logged!

Drawbacks

  • Build time is slower. As the IL weave happens at build time, the build time will be increased. This may be a further incentive to keep your projects to a sane and manageable size ;)
  • The Logging appears to be “magic”. As you can not see the code that is doing to logging (due to its AOP like nature), it should be clearly communicated to the dev team what is happening behind the scenes

These code snippets should give you a relative cut and paste logging framework to get you started. The code can be replicated to provide, for instance Information debugging statements, by following the same guideline and creating a InformationLoggingAttribute with the logger calling the Info method instead.

For more information about these two very handy open source projects check out the web sites.

http://www.nlog-project.org/
http://www.postsharp.org/

NOTE:
Personally I prefer a more pluggable & loosely coupled approach, however for ease of understanding and writing of this article, the NLog components are directly referenced. This could be further abstracted out by using IoC to inject the Logging facade in to the Logging attribute class and again anywhere in the application using something like the Windsor Container or Spring.net