From a design perspective, what are the best practices for logging?

Question

I want to add logging to an application I'm currently working on. I've added logging before, that's not an issue here.

But from a design perspective in an object-oriented language, what are the best practices for logging that follow OOP and patterns?

Note: I'm currently doing this in C#, so examples in C# are obviously welcome. I would also like to see examples in Java and Ruby.

---

Edit: I'm using log4net. I just don't know what's the best way to plug it in.

Answer 1

The best practice that I would recommend is to use log4j rather than rolling your own. (Which has been ported from Java to both C# and Ruby, so it applies to all 3 languages that you are interested in.)

If you read through that manual page you will discover several other best practices. Such as being lightweight, configurable outside of your application, being able to turn up and down logging for different parts of your application independently, and so on.

Answer 2

Where I work we write a lot of .NET desktop apps. We normally implement 2 events in our components, one for logging information and the other for logging exceptions (although we often let the exceptions bubble up instead of raising the separate event. It depends upon the situation). Using this architecture, none of our libraries need to know how logging is implemented or how the information is used, stored or treated. We then have the application handle the logging events in a manner that is appropriate to that app. A number of years ago this architecture made our switch from using MS Enterprise Library logging to BitFactory's logging component a very simple transition.

Answer 3

Since you are doing this in C#, I would recommend you looking at NLog and ElMAH. They can be VERY easily installed using NUGET. I've put some links to those below so you can get more info.

• Elmah: http://code.google.com/p/elmah/
• NLog: http://nlog-project.org/
• Nuget: http://nuget.codeplex.com/

Answer 4

Personally, I take the logging framework of choice (in my case, Entlib because I work with .NET) and write an AOP aspect for logging.

You can then attribute any methods/properties/classes/namespaces and add logging to them without cluttering up the source.

Answer 5

The system I'm currently working on uses an event driven architecture and messaging, so that most actions in our system are the result of a command and they result in events (as DTO classes that are dispatched, rather than a standard delegate event). We attach event handlers whose sole purpose is to handle logging. This design helps us not repeat ourselves, and also not have to modify existing code to add/change functionality.

Here's an example of one such logging class, that handles all events to be logged from a narrow section of our application (those regarding one particular content source we import from).

I won't necessarily say this is hands down best practice, as I seem to change my mind on what and how to log often - and every time I need to use a log to diagnose an issue I inevitably find ways to make improvements to the information I record.

I will say, though, that recording the pertinent information (especially in a Ctrl-F/find searchable way) is the most important part.

The second most important part is getting the logging code away from your main logic - it can make a method ugly and long and convoluted very quickly.

public class MctLogger :
    IEventHandler<StoryImported>,
    IEventHandler<StoryScanned>,
    IEventHandler<SourceDirectoryMissing>,
    IEventHandler<SourceDirectoryAccessError>,
    IEventHandler<CannotCreateScannedStoryDirectory>,
    IEventHandler<CannotReadStoryDocument>,
    IEventHandler<StorySkippedPastCutoff>,
    IEventHandler<StorySkippedDuplicateUniqueId>,
    IEventHandler<StorySkippedByFilter>
{

    public void Observe(StoryImported e)
    {
        var log = Slf.LoggerService.GetLogger("RoboChef.Content.Mct.StoryImported");
        log.Info("Story Unique ID: {Story.UniqueId}, Content ID: {ContentId}, Title: {Story.Headline}".SmartFormat(e));
    }

    public void Observe(StoryScanned e)
    {
        var log = Slf.LoggerService.GetLogger("RoboChef.Content.Mct.StoryScanned");
        log.Info("Story Unique ID: {Story.UniqueId}, File: {FilePath}, Title: {Story.Headline}".SmartFormat(e));
    }

    public void Observe(SourceDirectoryMissing e)
    {
        var log = Slf.LoggerService.GetLogger("RoboChef.Content.Mct.SourceDirectoryMissing");
        log.Error("Directory: " + e.Directory);
    }

    public void Observe(SourceDirectoryAccessError e)
    {
        var log = Slf.LoggerService.GetLogger("RoboChef.Content.Mct.SourceDirectoryAccessError");
        log.Error(e.Exception, "Exception: " + e.Exception.Message);
    }

    public void Observe(CannotCreateScannedStoryDirectory e)
    {
        var log = Slf.LoggerService.GetLogger("RoboChef.Content.Mct.CannotCreateScannedStoryDirectory");
        log.Error(e.Exception, "Directory: {Directory}, Exception: {Exception.Message}".SmartFormat(e));
    }

    public void Observe(CannotReadStoryDocument e)
    {
        var log = Slf.LoggerService.GetLogger("RoboChef.Content.Mct.CannotReadStoryDocument");
        if (e.Exception == null) {
            log.Warn("File: {FilePath}".SmartFormat(e));
        }
        else {
            log.Warn(e.Exception, "File: {FilePath}, Exception: {Exception.Message}".SmartFormat(e));
        }
    }

    public void Observe(StorySkippedPastCutoff e)
    {
        var log = Slf.LoggerService.GetLogger("RoboChef.Content.Mct.StorySkippedPastCutoff");
        log.Warn("Story Unique ID: {Story.UniqueId}, File: {FilePath}, Title: {Story.Headline}".SmartFormat(e));
    }

    public void Observe(StorySkippedDuplicateUniqueId e)
    {
        var log = Slf.LoggerService.GetLogger("RoboChef.Content.Mct.StorySkippedDuplicateUniqueId");
        log.Warn("Story Unique ID: {Story.UniqueId}, File: {FilePath}, Title: {Story.Headline}".SmartFormat(e));
    }

    public void Observe(StorySkippedByFilter e)
    {
        var log = Slf.LoggerService.GetLogger("RoboChef.Content.Mct.StorySkippedByFilter");
        log.Warn("Story Unique ID: {Story.UniqueId}, Reason: {Reason}, File: {FilePath}, Title: {Story.Headline}".SmartFormat(e));
    }
}

Answer 6

As others have said, use log4j or log4net or some other well-built logging framework.

I tend to really dislike logging code getting in the way of the business logic. That's why I use Log4PostSharp. That means I can use Aspect Oriented Programming to annotate methods like this:

[Log(LogLevel.Info, "Counting characters.")]
int CountCharacters(string arg) 
{
    return arg.Length;
}

Or every method in an assembly like this:

[assembly: Log(AttributeTargetTypes = "*", 
 EntryLevel = LogLevel.Debug, ExitLevel = LogLevel.Debug, 
 ExceptionLevel = LogLevel.Error)]

Answer 7

I am not sure if any framework does this, but from a design perspective, I would model the information need to be logged into mainly three categories:

1. method level tracing
2. exception logging
3. extra run-time information developers believe that is vital for investigating in case of a run-time failure (or any behavior related to run-time only situation).

For the first two categories, my ideal logging framework should handle them as a post build process and transparent to developers. It would be nice to declaratively add logging to assemblies, something like the following:

Trace YourNamespace.* [public methods|constructors]
{  # options
   ignore trivial methods,
   format: "{time stamp}: {method name}({parameter list})",
   condition: "{Context.Instance.UserID in (12432,23432)}",
}

Exception YourNamespace.Program.Main [unhandled exceptions]
{
  format: "{time stamp}: {Context.Instance.UserId} {exception}",
  action: die,  # options are throw, swallow,
}

For the 3rd category, programmers can just create one or more dedicated "logging" methods and leverage the tracing for the first category. The logging methods do nothing more than serving a stub point to which tracing rules can be applied.