My Initial Postsharp Setup — Logging at Assembly Granularity

PostSharp and Log4Net

I tweeted a bit about this, and now I’m going to post about my initial experience with it. This comes from the perspective of someone new at this particular setup but familiar with the concepts in general. So, what are PostSharp and log4net?

First up, log4net. This is extremely easy to understand, as it’s a logging framework for .NET. It was ported to .NET from Java and the product log4j a long time ago. It’s a tried and true way to instrument your applications for logging. I’m not going to go into a lot of detail on it (here’s a Pluralsight course by Jim Christopher), but you can install it for your project with Nuget and get started pretty quickly and easily.

PostSharp is a little more complex to explain (there’s also a Pluralsight course on this, by Donald Belcham). It’s a tool for a technique called “aspect-oriented programming” (AOP) which addresses what are known as cross cutting concerns. These are things that are intrinsically non-localized in an application. What I mean is, you might have a module that processes EDI feeds and another one that stores data to a local file, and these modules may be completely isolated from one another in your system. These concerns are localized in a nicely modular architecture. Something like, oh, I dunno, logging, is not. You do that everywhere. Logging is said to be an aspect of your system. Security is another stock example of an aspect.

PostSharp employs a technique called “IL Weaving” to address AOP in clean and remarkably decoupled way. If you’re a .NET programmer, whether you code in VB, C#, F#, etc., all of your code gets compiled down to what’s known as intermediate language (IL). Then, when the code is actually being executed, this IL is translated on the fly into machine/executable code. So there are two stages of compiling, in essence. In theory, you can write IL code directly. PostSharp takes advantage of this fact, and when you’re building your C# code into IL code, it interposes and injects a bit of its own stuff into the resultant IL. The upshot of all this is that you can have logging in every method in your code base without writing a single call to Logger.Log(something) in any method, anywhere. Let me be clear — you can get all of the benefits of comprehensive logging with none of the boilerplate, clutter, and intensely high coupling that typically comes with implementing an aspect.

Great, But How?

Due to a lack of time in general, I’ve sort of gotten away from detailed how-to posts, for the most part, with screenshots and steps. It’s really time consuming to make posts like that. What I’ll do instead is describe the process and, if anyone has questions, perhaps clarify with an addendum or links or something. Trying to get more agile everywhere and avoid gold-plating 🙂

And really, getting these things into your project is quite simple. In both cases, I just added a nuget package to a project. For log4net, this is trivial to do. For PostSharp, this actually triggers an install of PostSharp as a Visual Studio plugin. PostSharp offers a few different license types. When you install it in VS, it will prompt you to enter a license key or do a 45 day trial. You can sign up for an express version on their site, and you’ll get a license key that you can plug in. From there, it gets installed, and it’s actually really polished. It even gives you a window in Studio that keeps track of progress in some tutorials they offer for getting started.

With that in place, you’re ready to write your first aspect. These are generally implemented as attributes that you can use to decorate methods, types, and assemblies so that you can be as granular with the aspects as you like. If you implement an attribute that inherits from OnMethodBoundaryAspect, you get a hook in to having code executed on events in the application like “Method Enter,” “Method Leave,” and “Exception.” So you can write C# code that will get executed upon entry to every method.

Here’s a look at an example with some method details elided:

[Serializable]
[AttributeUsage(AttributeTargets.Assembly)]
public sealed class LogAttribute : OnMethodBoundaryAspect
{
    private static readonly ILog _logger;

    static LogAttribute()
    {
        SetupLogger();
        _logger = LogManager.GetLogger(typeof(LogAttribute));
    }

    public override void OnException(MethodExecutionArgs args)
    {
        if(_logger != null)
            _logger.Error("An exception occurred: ", args.Exception); 
    }
...

Leaving aside the logging implementation details, what I’ve done here is define an attribute. Any type or method decorated with this attribute will automatically log any exception that occurred without the code of that method being altered in the slightest. The “MethodExecutionArgs” parameter gives you information that lets you inspect various relevant details about the method in question: its name, its parameters, its return value, etc.

Getting Modular

Okay, so great. We can apply this at various levels. I decided that I wanted to apply it per assembly. I’m currently working at times in a legacy code base where a series of Winforms and Webforms applications make use of a common assembly called “Library.” This code had previously been duplicated, but I made it common and unified it as a step toward architecture improvement. This is where I put my aspect attribute for reference, and I decided to apply this at the assembly level. Initially, I want some assemblies logging exceptions, but not others. To achieve this, I put the following in the AssemblyInfo.cs in the assemblies for which I wanted logging.

[assembly: Log()]

This is awesome because even though PostSharp and the Aspect are heavily coupled to the assemblies on the whole (every assembly uses Library, and Library depends on Postsharp, so every assembly depends on PostSharp) it isn’t coupled in the actual code. In fact, I could just remove that line of code and the library dependency, and not touch a single other thing (except, of course, the references to library utilities).

But now another interesting problem arises, which is naming the log files generated. I want them to go in AppData, but I want them named after the respective deliverable in this code base.

And then, in the library project, I have this method inside of the LogAttribute class:

private static string GetLogFileFullPath()
{
    string friendlyName = AppDomain.CurrentDomain.FriendlyName;
    string executableName = friendlyName.Replace(".vshost", string.Empty);
    string appdataPath = Environment.GetFolderPath(Environment.SpecialFolder.ApplicationData);
    string logPath = Path.Combine(appdataPath, "{CompanyNameHere}");
    return Path.Combine(logPath, String.Format("{0}.log", executableName));
}

I’ve made use of the Monostate Pattern to ensure that a single logger instance is configured and initialized and then used by the attribute instances. This is an implementation that I’ll probably refine over time, but it’s alright for a skunkworks. So, what happens is that when the application fires up, I figure out the name of the entry executable and use it to name the log file that’s created/appended in AppData under the company name folder.

This was great until I noticed weird files getting created in that folder. Turns out that NCrunch and other plugins are triggering the code to be invoked in this way, meaning that unit test runners, realtime and on-demand are generating logging. Duh. Oops. And… yikes!

My first thought was that I’d see if I was being run from a unit test and no-op out of logging if that were the case. I found this stack overflow post where Jon Skeet suggested an approach and mentioned that he “[held his] nose” while doing it because it was a pragmatic solution to his problem. Well, since I wasn’t in a pinch, I decided against that.

Maybe it would make sense, instead of figuring out whether I was in a unit test assembly and what other sorts of things I didn’t want to have the logging turned on for, to take a whitelist approach. That way, I have to turn logging on explicitly if I want it to happen. I liked that, but it seemed a little clunky. I thought about what I’d do to enable it on another one of the projects in the solution, and that would be to go into the assembly file and add the attribute for the assembly, and then go into the logger to add the assembly to the whitelist. But why do two steps when I could do one?

private static bool IsAspectLoggingEnabled()
{
    try
    {
        return Assembly.GetEntryAssembly() != null && Attribute.GetCustomAttributes(typeof(LogAttribute), false).Any();
    }
    catch
    { return false; }
}

I added this method that actually figures out whether the attribute has been declared for the assembly and, I only enable the logger if it has. I’ve tested this out and it works pretty well, though I’ve only been living with it for a couple of days, so it’s likely to continue evolving. But the spurious log files are gone, and MS Test runner no longer randomly bombs out because the “friendly name” sometimes has a colon in it. This is almost certainly not the most elegant approach to my situation, but it’s iteratively more elegant, and that’s really I’m ever going for.

Ideas/suggestions/shared experience is welcome. And here’s the code for the aspect in its entirety right now:

[Serializable]
[AttributeUsage(AttributeTargets.Assembly)]
public sealed class LogAttribute : OnMethodBoundaryAspect
{
    private static readonly ILog _logger;

    static LogAttribute()
    {
        if (IsAspectLoggingEnabled())
        {
            SetupLogger();
            _logger = LogManager.GetLogger(typeof(LogAttribute));
        }
    }

    public override void OnException(MethodExecutionArgs args)
    {
        if(_logger != null)
            _logger.Error("An exception occurred: ", args.Exception); 
    }


    private static bool IsAspectLoggingEnabled()
    {
        try
        {
            return Assembly.GetEntryAssembly() != null && Attribute.GetCustomAttributes(typeof(LogAttribute), false).Any();
        }
        catch
        { return false; }
    }

    private static void SetupLogger()
    {
        var appender = BuildAppender();

        var hierarchy = (Hierarchy)LogManager.GetRepository();
        hierarchy.Root.AddAppender(appender);

        hierarchy.Configured = true;
        BasicConfigurator.Configure(appender);
    }

    private static FileAppender BuildAppender()
    {
        var appender = new RollingFileAppender()
        {
            File = GetLogFileFullPath(),
            AppendToFile = true,
            Layout = new PatternLayout() { ConversionPattern = "%m%n" }
        };
        appender.ActivateOptions();
        return appender;
    }

    private static string GetLogFileFullPath()
    {
        string friendlyName = AppDomain.CurrentDomain.FriendlyName;
        string executableName = friendlyName.Replace(".vshost", string.Empty);
        string appdataPath = Environment.GetFolderPath(Environment.SpecialFolder.ApplicationData);
        string logPath = Path.Combine(appdataPath, "{CompanyNameHere}");
        return Path.Combine(logPath, String.Format("{0}.log", executableName));
    }
}