Logging in modern .NET applications

Background - A common evolution to logging

Recently we needed to implement a decent logging solution for a new application. The application (like so many) had evolved from a proof of concept (P.O.C) code base. 5 weeks after the cut over from P.O.C to code that was intended to ship, we had a plethora of Debug.WriteLine, Console.WriteLine and Trace.WriteLines sprinkled through the code base. Most of the *.WriteLine code was to help debug

1. code that implemented 3rd party code
2. code that had no tests (booo!) and F5 testing seemed to be "good enough"

After a couple of preliminary builds were sent to the client for initial evaluation, several un-handled exceptions had crept through. To be fair to the team, most of these were related to some undocumented features of the 3rd party system and few were my fault where maybe I was pushing WPF a bit to far for the clients machines. The result of these exceptions were a custom popup window on the WPF application, stating that a fatal exception had occurred and would shut down now. We would also email the exception as a quick way to notify the dev team of any errors.
At this point in time the team had decided we had several real problems here:

1. We had various "debugging" systems (Console, debug and trace)
2. We had hard coded our implementations of "logging". If logging a specific piece of functionality is a requirement we really should test that we are logging the correct thing!
3. As the WPF guy I am interested in any WPF binding errors (in the VS output window), but the service/agent guy were flooding the console screen with their pub/sub debug messages. How could I filter out their messages, and how could they filter out mine?
4. We were catching the un-handled exception at the dispatcher, not at the point it was thrown. This mean we had a huge stack trace (noise) pointing back to the problem and we also were missing some useful data to debug the exception such as the inputs to the method that threw the exception.

Setting the requirements

From the problems we have above the team decided that our requirements for the logging system were:

• Testable
• Provide different levels(severity) of logging. Trace, Debug and Exception.
• Filter on logging level
• Log to various targets. Email, File and Console.
• Provide different areas or categories to log as. e.g. Presentation, Agent, Services...
• Filter on logging Category (so I don't see the agent debug messages and agent developers don't see my presentation guff)

The requirements for the implementation of the logging system are:

• Log un-handled exceptions so we can analyse then when they occur on live
• Log the inputs to the method that threw the exception so we can identify it it is data related
• Replace console/debug/trace calls with new logger.

Journey to a solution

Logging System

First thing I will tackle is the testability. I will create my own interface called ILogger that will do my logging for me

public interface ILogger
{
  void Write(string message);
}

Well that was easy! Next, Provide different levels of logging. I am going to do that by replacing my Write method with level specific methods:

public interface ILogger
{
    void Trace(string message);
    void Debug(string message);
    void Error(string message);
}

To now add Categories. Here I will add a category parameter to each of the methods. I would advise against using enums for your categories, especially if your logger becomes a shared API. Enums can not be extended and really tie you down.

public interface ILogger
{
    void Trace(string category, string message);
    void Debug(string category, string message);
    void Error(string category, string message);
}

Hmmm. It now looks like the write we are making a mess for the poor developer who has to implement this interface. I think I may have been on the right track with the write method in the first place. I am going to change that back a Write method that takes 3 parameters. I will offer extension methods to give users the ability to make calls like the one above (a little bit more work for me but less work for everyone else). See here for more info on extending interfaces with Extension methods.

public interface ILogger
{
    void Write(LogLevel level, string category, string message);
}

Some may be thinking that "Hang on. Strings are bad! Surely a category Enum has to be better?". To answer this I would recommend using an internal class like this

class Category
{
    public const string Agent = "Agent";
    public const string Presentation = "Presentation";
    public const string Agent = "Service";
}

If you want to expose categories at your public API, create a public version of this class that consumers can use an even inherit from to add their own categories too. If you are thinking "shouldnt they be public static readonly?", I will cover that later.
Checking off aginst our requirements list we can cross somethings off

• Testable (Interfaces make things testable)
• Provide different levels(severity) of logging. Trace, Debug and Exception.
• Filter on logging level
• Log to various targets. Email, File and Console.
• Provide different areas or categories to log as. eg Presentation, Agent, Services...
• Filter on logging Category (so I don’t see the agent debug messages and agent developers don't see my presentation guff)

So that is a good start. Now we need to add filtering and targeting various outputs. Well luckily there are plenty of 3rd party logging tools out there that do all of this for us. As our project is using Enterprise Library already we will just use their logging application block. Look to the example at the end of the post for complete example.
Great! Thanks to the 3rd party logging system we have ticked off all of our system requirements, now for our implementation requirements.

Implementation of Logging

Now that we have an interface to code against, let us now look at how we would use it.
Ed- This is completely back to front. You should normally look at how you would use it first and then create the implementation. TDD is a great methodology for this. We are approaching it back-to-front in this post because I think it is easier to consume for the reader.
So the main pain point we have is logging exceptions that occur at the agents (the classes that get data from services and map them to client side entities). This is due to poor 3rd party documentation, Live being slightly different to Dev and QA and integration testing being harder to perform than unit testing.
Prior to our new Logging system some agent code might look like this:

public void AmendPortfolio(PortfolioAmmendment portfolio)
{
    Console.WriteLine("AmendPortfolio {0}", portfolio.Id);
    var data = portfolio.MapToServiceData();    //Mapper extension method.
    _service.AmendBasket(_session, data, true);    //Call to 3rd party system
    Console.WriteLine("AmendPortfolio complete");
}

Now if we swapped out the console calls with out logger and then put in some exception logging it may look like this

public void AmendPortfolio(PortfolioAmmendment portfolio)
{
    _logger.Debug(Category.Agent, "AmendPortfolio {0}", portfolio.Id);
    try
    {
        var data = portfolio.MapToServiceData();    //Mapper extension method.
        _service.AmendBasket(_session, data, true);    //Call to 3rd party system
    }
    catch(Exception ex)
    {
        _logger.Error(Category.Agent, ex.ToString);
        throw;
    }
    _logger.Debug(Category.Agent, "AmendPortfolio complete");
}

Oh dear. We now have more code that does logging than code that does real work. While we have satisfied our requirements, we have doubled our work load. Not good. Back to the drawing board.

AOP

Some will have heard of Aspect Orientated Programming. It seemed like 5 years ago it was going to change everything. Well it mainly just changed logging. AOP is a style of programming that allows code to be injected at a given interception point. In our case the interception point would be the start of our agent method, the end of the agent method and when the method throws and exception (which is really the same as the end of the method). As far as I know there are 2 popular ways to achieve this

1. at run time using a tool like Castle Windsor or Microsoft Unity
2. at compile time using a tool like PostSharp

I have had some experience with PostSharp as I used it prior to Unity having the ability to add interceptors. So for our solution we went with PostSharp. I believe to switch between any of these options would not be a huge amount of work.
First a quick introduction on how I have previously done AOP logging with PostSharp. I would create an Attribute that I would apply to classes or methods that I wanted to be logged. The attribute would satisfy the requirements of PostSharp so that code would be injected at compile time to do my logging.
code like this

[Logged]
public void AmendPortfolio(PortfolioAmmendment portfolio)
{
    var data = portfolio.MapToServiceData();    //Mapper extension method.
    _service.AmendBasket(_session, data, true);    //Call to 3rd party system
}

which at compile time would alter the IL to represent something more like this:

public void AmendPortfolio(PortfolioAmmendment portfolio)
{
    Logger.Debug("AmendPortfolio({0})", portfolio.Id);
    try
    {
        var data = portfolio.MapToServiceData();    //Mapper extension method.
        _service.AmendBasket(_session, data, true);    //Call to 3rd party system
    }
    catch(Exception ex)
    {
        Logger.Error(ex.ToString);
        throw;
    }
    Logger.Debug("AmendPortfolio complete");
}

Well that looks perfect doesn't it? Not really. We don’t have a category specified and we have a hard coded reference the static class Logger from Enterprise Library Logging. It no longer points to our _logger member variable which was of type ILogger. This makes our testing harder to do. If testing your logger is not really something you care about (which is fine) then this AOP solution might be for you. If you do want to be more specific about logging then we need to find a way of getting hold of the instance of ILogger. As PostSharp is a compile time AOP framework, it is a touch harder to integrate than if we used Unity or Windsor. The main problem is how do we get a handle on the Logger? A solution we came up with was to create an ILogged interface

public interface ILogged
{
    ILogger Logger { get; }
}

By doing this we expose the Logger so we can use it in the Aspect/Attribute. Now if we look at out method that we are trying to log in the greater context of the class it resides in we can see what the implementation may now look like.

[Logged]
public class PortfolioAgent : IPortfolioAgent, ILogged
{
    private readonly ILogger _logger;
    private readonly ISomeService _service;
    public PortfolioAgent(ILogger logger, ISomeService _service)
    {
        _logger = logger;
        _service = service;
    }
    public void AmendPortfolio(PortfolioAmmendment portfolio)
    {
        var data = portfolio.MapToServiceData();    //Mapper extension method.
        _service.AmendBasket(_session, data, true);    //Call to 3rd party system
    }
}

That looks kinda cool to me. One thing my colleagues made a note of is that they would prefer if in this scenario we used property injection for the logger. This is fine with me as long as it is easy to use and we can still test it. The ILogged interface does not preclude using property injection, it is just not my preference. Another thing to note is the lack of Category. Easy fix there is to add a property to our LoggedAttribute of string Category.

[Logged(Category=Category.Agent)]
public class PortfolioAgent : IPortfolioAgent, ILogged
{
...
}

If you remember earlier that I mentioned public const vs public static readonly. This is the reason why I choose to use const types so that they could be used in the attribute.

I am pretty happy with this now. I think we tick off all of our requirements and have not added a lot of complexity to our code. The one last thing that bugs me is that I have to use the LoggedAttribute and the ILogged interface as a couple. If I forget to use one without the other, I either will get no logging, a nasty runtime exception or if I code a aspect correctly I can get a compile time error (the most desirable). At first I coded the attribute to do the latter (compile time error), but then realised that all of my agents were in one project and all used the same Category. To make life a little bit easier I moved the attribute to the AssemblyInfo and had the Aspect apply itself automatically to any class the implemented ILogged. This maybe a step too far towards black magic for some teams, so do what fits best.

Have a look at the sample code here. Both styles are shown in the example so take your pick of which suits you best.

Success, Motivation and Management

I just watched an interesting presentation from Dan Pink on The surprising science of motivation. Here he discusses the conventional ways to get productivity out of employees via carrot and stick mentality. Watch the video first (18min) so I don't take the wind from his sails.

What I found interesting especially on refection of my earlier post Projects – Measuring success and providing boundaries, was how he related the 20th century management style to prescriptive roles. Prescriptive roles are roles where you can give very clear guidance on how to perform a task and boundaries of the role. Boundaries normally define measurable tasks with reward/punishment (carrot/stick) attached to the tasks. These can anything from simple things such as

• If you work late the company will pay for pizza delivery
• if the project comes in on time you get a bonus
• if you meet your KPIs you get all of your bonus. Pessimistically viewed as: miss any of your KPIs and we will dock your pay.

However the interesting thing about prescriptive roles is that in the 21st century the game has changed. Any task that can be completed without a level of creativity, abstract thought or reasoning generally can be done:

• cheaper by outsourced labour
• faster by automation (mechanical or computer)

This affects the software industry massively. Outsourcing burst on to the scene at the turn of the century and appeared to be the Holy Grail for accountants across western civilisation. This also scared the hell out of any "computer guy" as how was he going to make the payments on his new sports car? Outsourcing was not all that is was cracked up to be with stories of low quality product and communication failures. Outsourcing seems to be making a small come back and I think that we will see this see-saw rock a little bit more before outsourcing becomes part of our day to day life. See the 4 hour working week for some great ideas on outsourcing your life.

Dan Pink discusses that the 20th Century style of carrot/stick management worked well with prescriptive roles. But we are in the 21st century now and I would like to think that any one reading this is not performing a prescriptive role. I would even argue that our role is to eliminate or automate what we can. Normally these things that can be eliminated or automated are prescriptive processes. Roles that add real value to any company do require creativity, problem solving, communication skills, building relationships etc. These things cannot (yet) be automated.

So moving from the production line 20th century to the service orientated 21st century we are seeing a shift from the role of management being one based around compliance (carrot/stick) to self managing, autonomous teams/employees. This is in line with what agile and lean concepts are trying to achieve. Creating a culture where

1. autonomy
2. mastery
3. purpose

are values that are held dear, creates an amazing shift positivity of the team. Instead prescribing exactly what is to be done and creating a drone army (which could be replaced by outsourcing or automation), try setting clear expectations of the outcomes you want achieved and let the team go for it. This will give the team a sense of worth as you are touching on Maslow's Hierarchy of Needs by giving them a channel for creativity and problem solving, but probably more importantly a sense of respect and belonging. Obviously it doesn't have to be a free-for-all, which would no doubt result in total failure, but simple things like burn down charts, daily stand-up's can give 'management' visibility of progress.

So what can you do if you are not management?

I believe that people are attracted to like people. If you value and exercise principles like mastery, purpose, independence, interdependence then I think you will attract to companies where that is the culture. Easiest thing to do is trying for mastery. In the information age it is simple to learn new skills. Simple is not the same as Easy however. Finding the information on a subject is not the same as mastering it, so you have to jump in feet first and make mistakes. Ideally this is not on mission critical projects. I do a lot of mini projects at home to learn a new skill. Some companies like Google are now offering time at work to do this stuff. If your company does not offer this time, then you may want to consider your priorities and see if you can make time for self development. 30 minutes on the way to work, you can read 10 pages of a book. That should allow you around 1 book per month. If you drive/cycle to work, then maybe audio books or podcasts are for you. This is only one part of the path to mastery. You then need to distil the information you are collecting. At the end of a chapter, jot down some notes in your own words of what you just learnt. The act of distilling the information will help you understand it better. To further improve your understanding, actually do something that requires your new skill. Lastly to really see if you understand the skill, try teaching someone else the skill. This really shows you where you are weak still.

Next, start automating the prescriptive parts of your role. For C# guys this mainly done for us with tools like automated build servers and Resharper. If have not worn out our tab key then as a C# code you probably don't use snippets/live templates enough. If you don't have a little keyboard short cut for getting latest, building, running tests and checking in then automate it! If part of your role can't be automated, try outsourcing it. It is amazing what people will do if you ask them nicely - "Excuse me Tony you don't mind taking this mail to the mail room for me?"

Once you are on the track for mastery by creating some sort of self development routine*, you have automated or outsourced the prescriptive parts to your role, you can now concentrate on delivering value from your role. This is where purpose comes in. Ideally as you develop more skills, reduce drone work and start delivering more value from your role management may feel that you can have a level of autonomy. From their perspective giving you autonomy now is really just reducing their work load. If you constantly deliver value, management will naturally move away from compliance management to engagement.

S.M.A.R.T. goals

Projects – Measuring success and providing boundaries

*I try to read a minimum one book per month. I also try to keep up with my blog subscriptions but constantly have hundreds of unread post. As a guide apparently Bill Gates reads 3 books a weekend!