A few tips for better logs

Learning to log well is almost as hard as learning to program. There are sadly few articles about how to do it, which goes some way toward explaining the state of our logs. Sometimes we log too much, sometimes too little, sometimes nothing at all. That makes troubleshooting in production much harder. At GoodData we use Splunk to read our logs. It lets us query the hundreds of gigabytes of logs we produce every day. Even with that fine tool, you're out of luck if the information is missing and you can't work it out from the context of other logged events. Good logging means capturing the important events at the right severity, recording enough context to find more detail, and continually improving your logging. You rarely get it right on the first attempt.

Log levels

Logged information has several severity levels: TRACE, DEBUG, INFO, WARN and ERROR. The first problem is drawing a line between them. Much logging code uses too low a level, DEBUG. At the other extreme, it logs events of little consequence at ERROR, a level that should effectively mean someone will wake you at two in the morning over it. If you don't distinguish the levels carefully enough, you won't be able to monitor your system effectively. I found a basic classification of events by log level in Logging levels — Logback — rule-of-thumb to assign log levels. I'll put it in my own words.

ERROR
Use this for serious events that directly threaten the operation of the system and have a direct impact on customers or users. Someone has to intervene to address the cause. This is the kind of problem that should get you out of bed at two in the morning. If someone can't sign in because you can't connect to the database, that's certainly an ERROR.

WARN
These events have no direct impact on the customer but are serious enough to deserve immediate attention. At the very least, record them in the incident tracker and review them. I use WARN, for example, when checking application configuration. If production is using settings meant primarily for development, that should raise a flag. A WARN should signal that the system's operation may be at risk. A failed cache is one example. It poses no immediate threat to the system's function, but other components may become overloaded.

INFO
Routine system events that let us see what happened. These include events from the infrastructure itself, such as a component starting or stopping, and from the application, such as successful sign-ins, password changes and sent emails. Unexpected events certainly don't belong at this level. Those go one level higher.

DEBUG
This captures highly detailed events that let you reconstruct much of the program's state. Examples include decision points or timings showing where the program spent its time. This level tends to be chatty. At this level we log everyday expected events, such as obtaining a database connection or finding that a user has a given set of permissions.

TRACE
The finest-grained level, essentially for debugging. It prints variable states, method calls and the like. We only use this level in unusual cases, and most programs can do without it. DEBUG gives you an almost exact picture, while TRACE gives you the exact picture.

If you were the only person reading your logs, the level you chose would hardly matter. When several people analyze the logs, they're likely to get lost without meaningful levels. Monitoring and automatic alerts on ERROR or WARN are another good reason to use the levels properly. The standard level in production is INFO. Turn DEBUG on as needed, because it can generate a lot of data and put load on the system.

A few suggestions

If you don't know whether to log an event at DEBUG or INFO, ask whether it is expected from the system's point of view (DEBUG) or unusual (INFO).

//user session validity
if(System.currentTimeMillis() > userSession.getValidity()) {
    log.debug("User session has expired already");
    return false;
}

We chose DEBUG here because the session expired, which is unremarkable.

if(userSession.cookie.id != userSession.httpParam.id) {
  log.info("User session id in cookie dosn't match with  session id in HTTP request param");
  return false;
}

We chose INFO here because we consider the situation unexpected. It shouldn't normally happen if everything is working properly. It can happen, though, and we want to know about it.

Sometimes I use a DEBUG event in place of a comment in the code. It still explains the context and can also describe what is happening as the system runs.

if(!shoppingCart.isEmpty()) {
    //Creates a new order based on the shopping cart
    return new Order(shoppingCart);
}

if(!shoppingCart.isEmpty()) {
    logger.debug(Creating a new order based on the shopping cart {} ", shoppingCart);
    return new Order(shoppingCart);
}

Most logging libraries now let you use parameters. We use SLF4J. Parameters save you from concatenating strings. Performance isn't the issue, since the compiler will optimize that for you. The issue is how easy the code is to read.

logger.debug("User " + user + " with login " + login + " updated profile ");

logger.debug("User {} with login {} updated profile", user, login);

If machines will process your events, it helps to make them easy to parse. Splunk, for instance, recognizes and indexes parameters. A parameter is anything separated by an equals sign. That lets me query and analyze them.

log.info("action=request_processing_request status=end uri={} method={} time={} size={} httpStatus={}",...);

We often log a stack trace when we don't really need it. Generally, log an exception and its stack trace when it was unexpected and unhandled, you don't know what to do with it, or you are unsure of its cause. Then the stack trace will help you look for the cause. If you know what happened, the exception and its stack trace clutter the log.

try (BufferedReader br = new BufferedReader(new FileReader(file))) {
    ...
} catch (FileNotFoundException e) {
    log.error(e);
}

Here we know why it failed, so there's little point in logging the exception. We should log what happened in terms a person can understand.

try (BufferedReader br = new BufferedReader(new FileReader(file))) {
    ...
} catch (FileNotFoundException e) {
    log.error("The  key file '{}' for signature verification doesn't exist");
}

Always consider whether a person or a machine will be the main reader of an event. If people will analyze the logs to find out what happened, for instance, it's better to be more descriptive and provide context. If the events are for machine processing, choose an appropriate format. Most applications have both types of events.

Conclusion

Logging is a long-term endeavor. I've tried to share a few tips and techniques I use and find useful. Of course, you may have observations of your own. Feel free to share them in the discussion below.