Friday, August 19, 2011

A simple guide to effective logging

One of my coding pet peeves is lack of useful log messages. While logging is the simplest, yet effective tool in a developer's arsenal, it is often the most neglected one. We developers do not take the time to think through what and where we should add log messages in our codes.

We tend to use only "error" and "debug" level log messages. We use "debug" messages to help test our codes during development stage. But we add these debug messages on an ad hoc basis. And, our applications usually do not have debug level turned on in production (and we don't want to). The only other time we log messages is when there is an error or exception. This is partly because traditionally developers are not required to provide operational support for the software they write. They are usually removed from production support by 1 or 2 levels- a support team in the client's organization and then another in their own organization. With SaaS model, this separation is going away to some extent, but the issue persists. Well thought out log messages can save a lot of time & frustration with debuging production issues.

Here is a set of rules I use when I write codes,
  1. Use a good mix of 4 levels of log messages- error, warn, info, and debug.
  2. Usually "info" to "debug" ratio is 30%.
  3. "Info" is the most important log level from operations perspective, yet the most neglected and misunderstood one. Systems should run at info level. I see it as the "system's heart beat." At any point in time, anyone should be able to say how the system is doing by reviewing info messages. The trick is to achieve that using the minimum number of messages with just enough useful information.
  4. Use "info" message to trace high level application flow.
  5. Use "debug" message to trace detailed level application flow. Never use "system.out" messages.
  6. Use "warn" level messages when system can recover from a failure. Also use warn when a user is doing anything unusual, i.e. multiple attempt to login, or trying to access functions that they are not supposed to etc. This is specifically useful in the SaaS systems. "Warn" messages can serve as an early warning signal.
  7. Send email when an "error" message is logged. Do not use "error" level if you do not want to receive an email about it.
  8. Be vigilant about what data you write out in a log message. Only enough data to help track activities, but never any security sensitive data (in the context of the domain).
  9. Add context to the log messages. For example, date & time, line#, class name, method name, session id, user id etc. Logging frameworks available in most languages now-a-days are designed after "log4j," one of the most well-designed framework by Ceki Gülcü. Log4j and similar frameworks make it easy to automatically add this context to all messages. 
  10. Format log messages in a way so that it is easy to plop them into a tool like Excel for easier analysis. Here is an example of a good formatted log message,
[ DEBUG] | 110817 21:28:58 | pid-609 | user 2 | session 12345 | controller | effective_logging.rb:17:in `descope_multiple' | wi 12 descoped
Here is an example code showing a good mix of log messages used:



What guideline do you follow for logging?

2 comments:

  1. One of the most required and popular weather measuring instrument is instrument to measure wind speed,wind meters.For measuring barometric pressure, temperature, wind direction, wind speed,humidity;it's crucial.

    ReplyDelete
  2. This includes an extraordinary level of wellbeing to the note. Income from other salary properties likewise can substitute for income from the property being set as security. website link

    ReplyDelete