7 tips for an effective logging strategy

Have you ever faced an issue in production, but have no idea what is going on?

A form is not saving everything, or an expected workflow is not triggering?

'It's impossible!', you say, 'It just can't do that!'. Or worse yet, '...are you sure we're looking at the right part of the system?'.

Well, it's happening, in production too, and you need to get it fixed ASAP.

You've seemingly endless possibilities of what the problem could; if only you could debug it to really see what is happening!

This is exactly the situation where you need a solid logging strategy!

If you have to debug, you're not logging enough!

Not every problem appears as an error

It's obvious but worth emphasising - not every bug shows up as an error.

Sometimes it's that data just doesn't flow as you expect.

Isolating and fixing where those types of issues are occurring is where good logging can save you valuable time!

When you do have an error, you get a stack trace.

Sure, from the stack trace you know where an error is happening, but often times that is not enough.

What else was that thread doing before it got the error?

What parameters was it working with?

Which guard clauses were been triggered?

A strategy for good logging

Therefore, you need to have a solid approach for logging.

Fundamentally, your logs should tell a story. They need to paint as clear a picture as possible as to what is going on.

You can't and shouldn't log everything.

However, if you log the important bits, when you're armed with nothing but a log to tackle a production issue, you'll thank yourself later!

Your logs should:

  • Provide enough information to solve a problem
  • Be able to target a specific section of code
  • Not affect performance of the entire system

Logger per class

Depending on what your code does, it's pretty safe to say that you don't want to turn on diagnostic logging across the entire code base.

Especially in production, the sheer quantity of log entries would be overwhelming, let alone the performance hit of doing so much.

So you want to be able to isolate parts of the system and log extra detail in specific areas.

This can be done by creating a logger per class. For example, using Common.Logging .NET you can do the following:

var ILogger _log = LogManager.CreateLogger(typeof(MyClass))  

This gives you the option to selectively configuring the logging level at the namespace or class level.

Need to know what's happening in your EmailPublisher? Turn on DEBUG logging for just that class!

Use the correct logging level:

The logging levels are different per logging framework, but the general guide of what to log at each level is the same:

DEBUG

Use to log information you'd want to know as a developer. I like to think of this as the "diagnostic" level - what would I need to know if I was investigating an issue.

INFO

Use to log the general business flow of the application. It should tell the higher level story of what the application is doing, rather than how (that's DEBUG).

WARNING

Use when your code recovers from an error, or an unexpected situation, but continues to process. For example, if you handle an exception in a try ... catch, you're code would be doing so as it can carry on. Log it as a WARNING so you know it happened!

ERROR

Use when the application must stop execution, it can't carry on or automatically recover. Typically this will be when a thrown exception is unhandled until the very top layer of your app.

Be concise yet descriptive in your log

A simple single line format is often the best to scan and read.

Hard to read:

02-03-2016 12:02:22 - CustomerImport  
    Parameters: 
        Name: Bob Smith
        Account: 123456777
02-03-2016 12:02:41 - CustomerImport  
    Parameters: 
        Name: Alan Smith
        Account: 23332377

Easier to read:

02-03-2016 12:02:22 - CustomerImport { Name: Bob Smith, Account: 123456777 }  
02-03-2016 12:02:41 - CustomerImport { Name: Alan Smith, Account: 23332377 }  

By using the logger-per-class approach, you'll automatically know where in your code your log entry is referring to.

Log parameters (inputs)

This is all part of letting the log tell the story of what is happening in your application.

When logging values, pick a simple format:

  • User=Bob Smith, Acc=123765987
  • {User Bob Smith}, {Acc 123765987} (easy to parse with regex)
  • {"User": "Bob Smith", "Acc": "123765987" } or full JSON.

It doesn't matter which format, just be consistent. It's much easier to search the log if you know the data format.

Log all branching decisions

All if's, else's, switch statements, etc.

These represent the flow of your application, so to tell an effective story in your logs, you need to log that decision.

So for example:

public string ParsePhoneNumber(string phoneNumber)  
{
    if(String.IsNullOrWhitespace(phoneNumber)){
        _log.Debug("ParsePhoneNumber: phoneNumber null, return String.Empty");
        return String.Empty;
    }

    // ... Do some parsing stuff here
}

The log entries work a bit like 'coded comments' - useful when writing code, and still useful when running in production.

Warning: Be aware of side-effects

Be aware of what you are logging and how.

Don't do something when writing a log entry that hits an external service or database in the logging.

Not only is that a performance problem (especially with lazy loading in Entity Framework), but if it errors, you've got next-level problems!

The last thing you want is when the act of turning on logging causes another bug to show up, probably masking the issue you are investigating in the first place.

Give it a go

Hopefully, you see that with a little upfront effort you'll:

  • Save time
  • Save hassle
  • Gain confidence you can support a problem in production.

The next time you have an issue in development, before rushing to the debugger, check your logs. Do they have any insight?

Try it.