Take the 2-minute tour ×
Code Review Stack Exchange is a question and answer site for peer programmer code reviews. It's 100% free, no registration required.

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?

share|improve this question

migrated from programmers.stackexchange.com Mar 24 at 10:32

This question came from our site for professional programmers interested in conceptual questions about software development.

2  
What you want is not logging, operations actually either want an audit trail or event sourcing. Logs are not reliable: You logged "Something done on bar with id=...", but what if changes to dbContext never saved? –  abuzittin gillifirca Mar 26 at 8:31
    
I noticed UriAgassi italicized operations too, in my case it was because it's not clear who operations is. Requirements coming from COO or IT Operations have different goals, different solutions that address them and they might have different priorities. –  abuzittin gillifirca Mar 26 at 8:47

7 Answers 7

up vote 27 down vote accepted

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.

share|improve this answer
2  
Aspect-Oriented Programming with the RealProxy Class is quite a good read. –  scheien Mar 24 at 10:16
1  
A good tool for this kind of thing is PostSharp –  AndyBursh Mar 24 at 11:39
    
I don't think we're actually calling it aspects, but we are applying something of that sort for the basics of our logging. There are certainly exceptions where we hand-code the logging instead, to better control what gets reported, but in many cases we do produce the entry/exit messages automatically. –  keshlam Mar 24 at 23:21
    
I've used Castle DynamicProxy to accomplish this in the past: docs.castleproject.org/… –  Scott Lerch Mar 28 at 22:29

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.

share|improve this answer
    
I agree with you, the levels I had put above were just there as part of the pseudo code. The reason for the ops team wanting the logs like this is so that if a customer logs a support call, it is normally about a specific unit. This would marry to the id written in the logs. The support team then just opens the log files, filters by that id and they we see everything the system has done with that item. They can then see where/what last happened to it. –  Nick Williams Mar 24 at 14:33
3  
I understand their logic, but you should argue that what the ops need is the user activity, not the user trace. This scope is much higher in level and should include, IMHO, at most every entry point the user had (which end-point and when), and every exit point (whether it was successful, and if not, why, and maybe some benchmark for how long it took) –  Uri Agassi Mar 24 at 14:39
    
Sorry, perhaps I should have included that it is a Windows Service. So there isn't really a user. Don't know if that makes a difference? I do agree that it feels wrong. –  Nick Williams Mar 24 at 15:15
    
I believe it's just a matter of terminology - replace "user" with "customer" or whatever, "entry point" with "activity start", "exit point" with "activity end"... –  Uri Agassi Mar 24 at 15:52

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.

share|improve this answer

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.

share|improve this answer
    
Yes, this. But ideally both. Every method that loads an entity from an ID should log the same information: id=x, found=y. This should be applied consistently across all entities. Once you do this, you can remove four lines of logging from client methods and shrink your code base considerably. –  David Harkness Mar 27 at 2:41

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.

share|improve this answer
    
Is your "debrix codes"-'addin' for eclipse somewhere free to download? –  MrSmith42 Mar 24 at 22:07
    
This is the jar for Eclipse, it's rough around the edges because I mainly use VS, and installation is manual dropbox.com/s/oxx9efxhhh0n8ih/AidemaDebrix_1.0.0.6.jar | A manual for eclipse: help.eclipse.org/indigo/… –  Sten Petrov Mar 25 at 3:05
    
And here's the VS addin installer, tested on VS2008-2012: dropbox.com/s/idgvodomej1gbrk/VisualDebrixSetup.msi –  Sten Petrov Mar 25 at 3:06
    
+1 This is a great idea. I take great pains to keep log messages up-to-date, often by creating typed methods to enforce the semantics. But the use of a unique message code makes filtering a breeze. –  David Harkness Apr 4 at 2:53
    
@DavidHarkness the VisualDebrix plugin actually takes the upper case letters from current file name as a prefix for the whole code, this way messages produced within the same class have the same prefix and the "random" code actually gives you a non-random clue. Useful for reading the neighboring log messages –  Sten Petrov Apr 4 at 13:45

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).

share|improve this answer

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.

share|improve this answer

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.