Logging code blocks, inspiration from ASP.NET MVC Html.BeginForm and IDisposable
Many times I've had to log entry and exit of a method, either to track down a bug, for timing purposes, or other informational needs. I'm using log4net here as an example but you can insert your own logging framework here. Initially I took the direct approach which is very straightforward:
public class MyClass()
{
private static readonly ILog log = LogManager.GetLogger(typeof(MyClass));
void myMethod()
{
log.Info("Entering myMethod");
...
log.Info("Leaving myMethod");
}
}
This works great for a while, but there are a couple of issues:
- Although its not much code, it's tedious. Why should I have to write these statements all over the place
- There is a high probability for error. Using this method, I end up copypasta'ing log statements all over the place. Inevitably, I either forget to do the matching pair of entering/leaving statements, or I forget to rename the contents of the text string to update. Which leads to ultra confusing log files days or weeks later.
The first solution is to create an attribute to decorate each method that wraps the function call with logging statements
[LogMethod(log, "myMethod")]
void myMethod() { ... }
This works OK as well, I could even clean it up a little and infer the method name using reflection, rather than adding it to the attribute constructor. Now I can safely decorate this all over the place and it'll write entering and leaving statements for me. The downside is that by using an attribute, I am entering the strange world of reflection based programming and I don't really like to muck around in there. Also, sometimes I just want to wrap a hot block of code and not an entire method.
There's a nice method in ASP.NET MVC called Html.BeginForm which implements IDisposable. You are meant to use it in a using statement, the constructor emits the start of an HTML form, and the dispose method emits the end of the form. In this manner you don't forget any tags and it's a cool way of using IDisposable to wrap things. I decided to use the same pattern for wrapping logging statements around code.
I created a LogWrapper class which implements IDisposable and logs an enter statement in the constructor and logs a leaving statement in the dispose method. I have the constructor take the logging object as well as a name to use (e.g. the method name or the name of a specific code block. Whatever you want). I also created an extension method for log4net's ILog interface to make it prettier to use my LogWrapper. Here's the code below:
public class LogWrapper : IDisposable
{
private ILog _log;
private string _name;
public LogWrapper(ILog log, string name)
{
_log = log;
_name = name;
_log.Info("Entering " + _name);
}
public void Dispose()
{
_log.Info("Leaving " + _name);
}
}
public static class LogEx
{
public static IDisposable WrapCodeBlock(this ILog log, string name)
{
return new LogWrapper(log, name);
}
}
Nifty. Now to use it I just wrap my significant code blocks in a using statement
using (log.WrapCodeBlock("foo"))
{
// do my stuff
}
The code is logically encapsulated in a using statement and makes it easier to read. It also ensures that I don't forget the matching "leaving" log, and that I don't forget to change the name because I will be using far less copypasta. And it makes me happy :)
