Logging without Code Bloat

Question

I was wondering if any of you know any best practices or design patterns so that I can have good logging in my programs without them looking messy or bloated.

I am currently using C# and NLog, however I guess any advice here would be language and tool agnostic.

The problem we have is that we want to have good logging, however we can't seem to find a way around having many lines which just log operations, which can turn a simple method like this:

void Foo()
{ 
    Bar bar = dbContext().Bars.First();
    bool someCondition = bar.DoSomething();
    if (someContition)
    {
        dbContext().FooBars.Add(new FooBar());
    }
}

Into something which looks like this:

void Foo()
{ 
    _logger.Info("Getting first bar from database...");

    Bar bar = dbContext().Bars.First();

    _logger.Info("First bar returned from database, id = {0}", bar.Id);

    _logger.Info("Doing something on bar with id = {0}", bar.Id);
    bool someCondition = bar.DoSomething();

    _logger.Info("Something done on bar with id = {0}, response = {1}", bar.Id, someCondition);

    if (someContition)
    {
        _logger.Warn("Adding new FooBar to database");
        dbContext().FooBars.Add(new FooBar());
        _logger.Warn("Added new FooBar to database successfully");
    }
}

Here we now have more logging lines than code lines.

However I am being told by operations that this level of logging is required, and at the moment is still too coarse.

Is there any way around this ugly manual logging, or am I stuck with it?

Answer 1

This kind of trace logging could conceivably be solved with an Aspect.

Aspect oriented programming allows you to add boilerplate-style code to your program without actually writing the boilerplate inline. You could, for example, add an aspect than logged a method name and parameters every time a program entered a method, and then logged the method name and return value every time a method returned.

Of course, you don't necessarily want to log every method. Instead, most aspect frameworks allow you to indicate which code you want the boilerplate added to.

I don't know enough about C# to recommend a specific aspect-oriented framework to use, or appropriate syntax for you. Sorry.

Answer 2

Looking at your code, I believe that your problem is not only that the logging lines are ugly but they are a risk in costing you more than helping you:

• Like comments, log line maintenance is often forgotten, and might break your code upon changes, or - worse - confuse you when trying to troubleshoot by reading the log files (think of a situation where you change Bar bar = dbContext().Bars.First();, to Bar bar = dbContext().Bars.Last();, but not changing the log files - the log will tell you that the first bar returned is X, and now you'll be scratching your head how did that happen?)
• The logs in your code, if at all needed, are definitely not for level Info, not to talk about level Warn - these are Debug logs. Filling your files with debug logs will make your log files huge, and unusable.
  • Warn logs should be logged only when something out of the expected behavior happens, so that troubleshooting production will be focused on that.
  • Info logs should be succinct, in linear proportion to the number of transactions, and convey valuable information.
  • Debug logs are usually added ad-hoc when you are trying to hunt down an elusive bug, and need more information inside specific code. In a production scenario, these logs should be turned off.

It is implied from your post that you received this requirement from the operations team. I have a hard time understanding why the operations team will give you a requirement to log internal code behavior... They might require you to have specific logs on the feature level, but having a fine-grained logging requirement seems counter-intuitive and not in their domain of responsibility.

Anyway, to solve the first bullet (and make your code cleaner), the best strategy AFAIK is using Aspect-Oriented Programming as @BillMichell has recommended.

Answer 3

As Bill Michell has pointed out aspect oriented programming is a good way of adding boilerplate logging code, however in this case I don't think its really necessary - I'd approach this problem with some good old fashioned refactoring.

In your example the Foo method does all the logging, but if it is importantly to log that you are about to do something (or that you have done something), the its probably best to instead log this in the method which is doing that thing instead of the calling method. By refactoring the database calls into separate methods (which should probably be on a different class anyway) and refactoring the logging calls its easy enough to make the Foo method just as readable as it was before.

void Foo()
{
    Bar bar = GetFirstBar();
    bool someCondition = bar.DoSomething();
    if (someContition)
    {
        AddFooBar();
    }
}

Bar GetFirstBar()
{
    _logger.Info("Getting first bar from database...");
    return dbContext().Bars.First();
    _logger.Info("First bar returned from database, id = {0}", bar.Id);
}

void AddFooBar()
{
    _logger.Warn("Adding new FooBar to database");
    dbContext().FooBars.Add(new FooBar());
    _logger.Warn("Added new FooBar to database successfully");
}

bool DoSomething(this Bar bar)
{
    _logger.Info("Doing something on bar with id = {0}", bar.Id);
    // Implementation goes here
    _logger.Info("Something done on bar with id = {0}, response = {1}", bar.
    Id, someCondition);
}

So in answer to the more general question "how do I add logging while keeping code readable?", I refactor my methods into smaller methods until each method is as readable as it needs to be.

Answer 4

Logging when you're about to do something or when something goes right are good for development code. During development, you want to know the finest details of what goes on.

In production code, you expect that everything will go fine. In fact, ideally you only want to be informed when something goes wrong: You get an exception from your code, a database call fails or a critical part of your code returns something unexpected. In those cases, you want to log what went wrong, and if possible log the variables you're working with to help reproduce the bug.

In the case above, you don't want to log every time you get Bar, or that you got Bar with ID X, or that you're doing something on Bar, or that you've successfully done something on bar. You expect those to work properly, so you only want to log when something went wrong there, and then write away the bar variables you use in doSomething() and the ID of Bar. If someCondition is true, you want to log that you added something, but you don't want to log that it succeeded, only if it went wrong.

If operations says that they really need those logging statements, they're viewing it wrong. They don't want those logging statements, they want THE INFORMATION those logging statements generate. They likely want statistics based on those logging statements, or something related to the logging statements. Discuss with Operations why they need those statements and provide them with what they need.

Answer 5

As others here have pointed out logging carries the same burden as comments - too much or too little does more harm than good.

One practical approach to logging is to put a log line in most key branches - some branches do minor things and aren't worth logging. The most critical branch to log is a catch(Exception x) - always log exceptions

As for the maintenance of logs I have somewhat of an unique approach: I've created addins for my favorite development environments (VS, Eclipse) that upon pressing a hotkey insert a short unique coded sequence of characters of predetermined length (10 letters, all caps) and I use these + runtime data instead of human-readable verbage.

I call these "debrix codes" and they have multiple advantages, some of which:

• no messy elaborate wording
• you can always find the place in the code that produced a specific log
• you can easily count instances of a specific message or other stats: I have LinqPad scripts that take a log file name and a debrix code to produce snapshots of the vicinity of each occurance
• By only using runtime data you can be sure your message is always up-to-date: if the object is refactored out you are forced to refactor the log message as well.
• unique debrix codes throughout a complex system with multiple platforms will still lead you to the one place that produced the log message, regardless if it's javascript, server-side, client side (OSX Spotlight is very handy)
• the code can be included with client-visible error messages for customer support. Along with a timestamp it's all but guaranteed to uniquely identify an event

This is how I would use this approach to log your code sample:

void Foo()
{ 
  try{
    log.I("[FFASREQEKT]"); 
    Bar bar = dbContext().Bars.First();

    bool someCondition = bar.DoSomething();

    if (someContition)
    {
        log.I("[FFGFAJNNBGB]"); 
        dbContext().FooBars.Add(new FooBar());
    }
  } catch (Exception x){
    // This catch is only for illustrative purpose. In real code it may be outside this method
    log.E("[FFGADJNANQ]", x);  
  }
}

This allows you to have full insight into which code path was taken with the least amount of messages.

Answer 6

At the level of logging you're describing a debugger seems to be far more sensible. Speaking at least for myself and my subfield we would use logging in two ways.

• General INFO and ad-hoc DEBUG level logging which let's one trace a bug to a specific part of the application and to provide meta data like id's and similar information.
• And secondly logging of all (user) actions to make it possible to see what exactly a user did (both for bug fixing or when a client has a claim that he did something two months ago which supposedly didn't work).

Next a debugger can be used to go through the code line by line, giving all the more detailed information that you're logging now, without all the explicit log lines describing what is happening (which, if necessary would be in comments, not logs).

Answer 7

It may be that for your particular example it may be useful to derive a subclass of dbContext (say, loggedDBContext) that wraps it's methods with code that logs whatever you need and then executes the 'true' method. Adding/removing logging then would consist in choice of using dbContext vs loggedDBContext at the constructor (or factory), but not changing anything else.

In some languages there are ways to inject such aspects directly in the functions - change their behavior without requiring the calling code to even know that the functions have changed and now also do logging; but I'm not sure if that can be done in C# without explicit subclassing.