Quata 2: Logging

feature image

Quata 2: Logging

When it comes to code quality, logging is unique in that the readability issue is not so much in the code as it is in the output, the log file. You want your logs to be truly helpful, especially when you’re troubleshooting an issue in the middle of the night. You’ll thank yourself for being nitpicky with your log messages. It’s not just about readability, however. There’s also performance.

The examples below are syntactically compatible with slf4j, log4j, and log4j2. However, many of the principles apply to any logging framework, Java or otherwise.

They are all incomplete snippets. They assume that we have a logger object called LOGGER. I realize there’s some debate on whether to make loggers static and on whether to name them as you would constants. It’s obvious which camp I’m on, but let’s not get into that. Let’s focus on the method calls, shall we?

LOGGER.info(" The VAlidaton  failed ");
LOGGER.info("Validation failed for" + field);
LOGGER.debug("Validation failed for " + field);
LOGGER.debug("Returning {}", someObj.toString());

// assume that each of the following is inside a catch (IOException e) block

LOGGER.error(e.getMessage());
LOGGER.error(e.getMessage(), e);
LOGGER.error("IOException occurred", e);

LOGGER.error("Failed to open file", e);
throw e;

LOGGER.error("Failed to open file", e);
throw new RuntimeException("Failed to open file", e);

Here are my comments:

Line #Comment
1Watch out for misspellings, random uppercase/lowercase letters, and extraneous words and whitespace. For example, do we really need the word The to be there?

Some people do not notice extraneous spaces. But I believe that with conscious effort and constant practice, anyone can train their eyes to be more cognizant of them.
2There’s no space between for and the value of the field.
3Debug is usually disabled in production. This message will therefore never be logged. However, enabled or not, that string concatenation will always happen, resulting to a new String object being created each time. Either you wrap it around an if-debug-enabled check or use the nifty parameter placeholders. In both cases, the string formation does not happen unless and until it is determined that the effective log level does allow for the message to be logged. The corrected code below uses the latter technique.
4Okay. This one is using a placeholder. Well and good. However, in this case, the value is a result of some object’s toString(), which could be a very expensive operation, and it will always be called. Despite the use of the placeholder, we’d still want to wrap this around an if-debug-enabled check.

log4j2 also supports lazy evaluation using lambdas. The corrected code shows an example of it.
8We usually want the exception’s stack trace to be logged. This only logs the message.
9This one correctly logs the stack trace by having the exception as the second parameter. However, the message is redundant because it will appear again in the stack trace. The message needs to be at the right abstraction. It needs to say what it was trying to do that failed, not something that we can’t already tell by looking at the stack trace.
10Another example of a redundant message.
11This one has a better message. It tells you what it was trying to do that failed. However, I would question the need to log it. Most likely, an outer layer will log it anyway. If that’s the case, logging it here is redundant and is therefore a waste of space.
12For the same reason as in the previous one, I would question the need to log it. As you probably know, the stack trace of the RuntimeException object will include the original exception as the cause.

Here is the corrected code:

LOGGER.info("Validation failed");
LOGGER.info("Validation failed for " + field);
LOGGER.debug("Validation failed for {}", field);
if (LOGGER.isDebugEnabled()) {
  LOGGER.debug("Returning {}", someObj.toString());
}

// log4j2's lazy evaluation using a lambda expression
LOGGER.debug("Returning {}", () -> someObj.toString());

LOGGER.error("Failed to open file", e);

// For the example that logs and re-throws the exception,
// let's assume we found that it is indeed being logged in an outer layer,
// in which case, we don't need the entire catch block at all.
// No need to catch the exception only to log and re-throw it.

// For the example that logs and wraps it in another exception,
// let's assume we found that the outer exception is being logged elsewhere,
// in which case, we don't need to log it here.
throw new RuntimeException("Failed to open file", e);

That’s about all I have for now. Thanks and see you in another quata.

Leave a Reply

Your email address will not be published. Required fields are marked *

Post navigation

Previous Post :