Ruby’s Logger class, and the ruby logging ecosystem in general, has
grown up with 5 standard log levels:
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:
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
FATALmessage 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 1or 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.
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.
ERRORmessages 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.
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.
What we are doing, and, if relevant, to whom.
INFOmessages 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
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
You’ll note that
DEBUG are closely related. This is not an
accident: I’ll often have pairs of log commands looking like this:
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
INFO unless I’m using separate appenders.
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
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.