Log information best practice

Question

I am doing production support, relying much on log to troubleshoot. I found that the log information is quite messy for now.

Could you provide the best practice or guide to write log information?

BTW: we're using log4Net. Do you have any suggestion on alternative library?

Thanks.

Answer 1

Ideally, your log messages should include details of When, What, Where, Who, and some indication of how serious the event that triggered the message was.

• Include the date as well as the time. If your application is distributed across timezones include a time zone indicator as well. It'll remove confusion if everyone know exactly what time 03:11:04 is in their timezone.
• Include the logging severity level.
• Include some indication of the module or class that triggered the log massage in the log message.
• If possible, encourage the developers to include specific information in the messages: e.g., 'File corrupt', is a lot less useful than, 'File corrupt: "C:\foo\bar.dat"'
• If possible, have the developers include some sort of session or transaction ID in the error message. It is handy to be able to filter the logs for messages from the transaction that had an error and ignore all the transaction that were fine.
• It is often a good idea to include an error code in the log messages for errors.

I'd second the advice gave @Oded in keeping the messages tidy. For the routine stuff, date & time, log level, error code, I'd try to format them to be a fixed width, and put them at the start. It makes scanning the logs much easier.

As regards good guides on log message formatting, the only thing I have come across is chapter 17, of the book 'Release It!': http://www.pragprog.com/titles/mnee/release-it A lot of the above advice is based on that.

Answer 2

ELMAH is a very good logging library and not a bad alternative to log4net.

In regards to the formatting of your logs (you say the information is "messy", though you don't explain exactly what that means) - make sure each entry is clearly separated from others and that it is formatted in a readable manner (spacing, linebreaks etc...).

Answer 3

@corriganjc has a lot of good suggestions.

I would add some specifics: Consider logging messages using UTC, if possible. On the one hand it can be annoying to look at the messagses generated in "your" timezone and then have to remember the right amount to offset them to interpret them "correctly". On the other hand, all of your log messages will be sortable by time/date without further interpretation. (If you have messages logged from two time zones and you have logged them using "local" time, you cannot sort them until you bring them to a common time zone).

Use the the GlobalContext, ThreadContext, and LogicalThreadContext objects to inject additional context into your messages. The suggestion to log something like "session id" or "transaction id" is a good one and can probably be accomplished most effectively using the "context" objects, rather than by explicitly adding these values to the actual logging call sites. You can set the context once and, with the addition of a formatting option, log that context with ever message.

If you use the context object, consider making "standard" value names or even defining string constants that can be referenced by developers so that they don't have make typos when trying to add their context:

//Context value names
public static class DiagnosticContextValueNames
{
  public static string TransactionId = "transactionid";
  public static string SessionId = "sessionid";
}

//In your code
log4net.ThreadContext.Properties[DiagnosticContextValueNames.TransactionId] = GetTransactionId();
log4net.ThreadContext.Properties[DiagnosticContextValueNames.SessionId] = GetSessionId();

//Somewhere later on...
logger.Info("hello");  // this message can be tagged with the transaction id and session id if you use the appropriate formatting options

You might even consider extension methods on GlobalContext.Properties, ThreadContext.Properties, etc, to help guide developers to setting the context values correctly:

public static class LoggingExtensions
{
  public static void SetTransactionId(this ThreadContextProperties props, string trans)
  {
    props["TransactionId"] = trans;

    // Or, using constants as defined above...
    props[ThreadContextValueNames.TransactionId] = trans;
  }
}


// In your code...
log4net.ThreadContext.Properties.SetTransactionId(GetTransactionId());

// As compared to this:
log4net.ThreadContext.Properties["transactionid"] = GetTransactionId();

If you wrap or inherit from the log4net logger, you can add some context information automatically, thus relieving your developers of that burden. There is a right way to wrap or inherit the log4net logger, but it is not rocket science. The key is to pass log4net the type of your wrapped logger. cfeduke's answer in this post gives one way to wrap a log4net logger.

You could follow his example, but implement all logging calls in terms of the "ILogger.Log" method. Inside of "Log" you can add the properties that you want for all of your log messages:

// This approach requires more effort than simply populating the context properties "normally", and
// is probably overkill for most situations.  However, it can prove useful if you are able
// to have access to the context information that you want to log from within the Log method
// of the logger.
public void Log(type loggerBoundaryDeclaringType, LogLevel level, object message, object exception)
{
  log4net.ThreadContext.Properties["transactionid"] = GetTransactionId();
  log4net.ThreadContext.Properties["sessionid"] = GetSessionId();
  _logger.Log(loggerBoundaryDeclaringType, level, message, exception);
}

As far as other logging platforms, you might take a look at NLog. A new version has been released as a Beta release recently. It has many capabilities that are similar to log4net.

You might also consider good old System.Diagnostics.TraceSource. If you go this route, look into Ukadc.Diagnostics over at codeplex. This is an addon library for System.Diagnostics that provides a rich message formatting capability (similar to what you can do with log4net and NLog). One good thing about Ukadc.Diagnostics is that it is a configuration-only dependency. You do not have to take a source or reference dependency to use it.

Answer 4

> ... we're using log4Net. Do you have any suggestion on alternative library? 

You can use common.logging ( http://netcommon.sourceforge.net) that is a tiny logging-wrapper that works together with

• log4net
• nlog
• Enterprise Library Logging

It makes logging configuration a bit more complicated since you have to configure what logging engine to use and you have to configure the logging engine as well.

Its logging api is inspired by the log4net-api