Better Code

Swimming in Someone Else's Pool

Log Level Rationale

| Comments

Ruby’s Logger class, and the ruby logging ecosystem in general, has grown up with 5 standard log levels: FATAL, ERROR, WARN, INFO and DEBUG. There are no generally accepted guidelines for how these should be used, other than that those “high” on the list should be used in “more serious” situations than those lower down. This is not detailed enough for a useful policy. Better guidelines would mean that your logs would become more predictable and more useful.

I have been experimenting with a set of rules for using the different log levels over time which I think works well, and gives me confidence that logging at a given level will show only the information that I am actually interested in. Here’s what the different levels indicate:

  • FATAL

    The process as a whole can no longer continue. Some fundamental assumption has been violated. We may want to keep track of what happens during the shutdown process, so it’s perfectly possible that the FATAL message is not the last message in the log. There’s no assumption that the next call after the log(:fatal, msg) call is an exit 1 or the like, but if you’re following the “fail early and hard” principle then it probably should be. Out of memory errors are a good example here.

  • ERROR

    A single “request” or “operation” (however those terms are best defined in the context of the application) must terminate because something went wrong, or an assumption pertinent to the current operation has been violated in a way which can be contained. ERROR messages correspond roughly to exceptions in the classic sense: an unexpected event occurred which we cannot, or should not, handle within the main code body, and signal that while the process is safe, the current operation will be dropped on the floor. As with FATAL, this may not be the final log message generated by this operation.

  • WARN

    The current operation has fallen off the happy path in an anticipated way, and we are guiding execution flow within the main body of the code to a failure response. An authentication failure, for instance, might be logged at WARN. The steps involved in handling that authentication failure, however, would not.

  • INFO

    What we are doing, and, if relevant, to whom. INFO messages do not make distinction between whether we’re on a happy or sad code path. If they contain run-time data, it is only the minimum required to identify the entities involved in the operation. Since we expect to generate INFO-level messages frequently, they should be terse. An incoming HTTP request would be logged at INFO.

  • DEBUG

    These describe how and why we are doing what we are doing. Like INFO, they do not make any distinction between whether we’re at an execution point corresponding to “good” or “bad” behaviour. On the assumption that INFO messages will also be present at the appropriate points, any run-time data which will be used in a conditional expression would be suitable for a DEBUG message.

You’ll note that INFO and DEBUG are closely related. This is not an accident: I’ll often have pairs of log commands looking like this:

1
2
log :info, "Reticulating splines"
log :debug, "Spline parameters: #{params.inspect}"

This set of rules means that I can set the log level to DEBUG for an execution trace, to INFO for a user activity log, and to WARN for a user problem log.

As a purely practical matter, I can’t envisage a situation where I’d raise the log level above WARN, and I’m unlikely ever to raise it above INFO unless I’m using separate appenders. ERROR and FATAL are most useful as locatable tags in a file with more context. That being said, if you don’t want to run your log gathering at a low level all the time, one option might be to dynamically alter the log level. You could lower the log level to INFO for the current operation when you hit a WARN situation, and lower it to DEBUG when you hit an ERROR or FATAL. I’ll be trying this on one project shortly and post when I’ve got a clear picture of how well this works.

The thought does occur to me that a hierarchy of levels isn’t the right way to represent what we try to do with logging, but that is a subject for a future post.

ruby

Comments