You Are Logging All Wrong

This post is based on an email one of the Principal Engineers at my company sent to the R&D mailing list a few months ago.

The scenario he described in the email is so obvious, and yet I can honestly say — that when I looked back at commits I did — I found that I did it myself from time to time. I liked it so much that I had so share it.

Two things to note

1. It talks about logging in Java but you will see that the concept is easily imported to other languages.
2. We wrapped log4j with a LogWrapper object we wrote, that among other things checks to see what is the current log level in the system before it continues to log the messages it got. So, when you see logger.debug — it is of type LogWrapper, and when you see m_logger it’s the wrapped logger.

This is an example of some code that logs messages the wrong way:

List<Stuff> veryLongList = …

…

// explicit invoke object's toString()logger.debug(“my long list is “ + veryLongList.toString());

logger.debug(“my extra long list is %s”, veryLongList.toString());

// implicit invoke object's toString()logger.debug(“my long list is “ + veryLongList);

All three of these versions are inefficient and error prone and should be avoided.

The reason is the call to toString(). it forces the creation of a possibly expensive String object that is then passed to the LogWrapper.debug() method.

To understand the problem with this, look at how the debug method is implemented:

public void debug(Object message) {if (ThreadedLogLevelManager.isDebugEnabled(m_logger)) {m_logger.log(s_className, Level.DEBUG, message, null);}}

public void debug(Object message, Object arg) {if (ThreadedLogLevelManager.isDebugEnabled(m_logger)) {m_logger.log(s_className, Level.DEBUG, message, arg);}}

...

public void debug(Object message, Object... args) {if (ThreadedLogLevelManager.isDebugEnabled(m_logger)) {m_logger.log(s_className, Level.DEBUG, message, args);}}

You can see that we first check and see the debug mode is enabled for this piece of code and only then goes to call the m_logger that does the logging.

Usually the m_logger won’t even be called since debug logging is generally disabled in production.

The m_logger itself then goes and turn the message into a string.You can see below that the way it converts it into string is also an important check that we as developers sometime forget to do:

protected final String convertToString(Object message) {return message == null ? (String)message : message.toString();}

This protects you from getting a NullPointerException.

The Right Way

The way to do such logs is simply:

logger.debug(“my long list is %s”, veryLongList);

This has 3 benefits:

1. LogWrapper will call toString() only when logging is enabled.
2. If the object in question is null, it will be logged as the “null” string rather than raising an exception.
3. The code is cleaner.

This may sound obvious but that are about 100 such cases in the code.

On a personal note, be minded in what you log. don’t log just for the sake of logging.

No better then Winston Churchill to sum it up most accurately:

“This report, by its very length, defends itself against the risk of being read.”

P.S. my good friend elad shmidov, while giving me notes on the post mentioned that:

Python has something similar about this in it’s logging best practice under the optimization section

P.S. 2 Another good friend/Editor/critic Guy Cepelevich, shared how they are doing it in Ruby:

// define the log methoddef loglogger.debug yield if Environment.type == DEVELOPMENTend

// use itlog {"this is what i want to log: " + String(element_list)}

The content of the curly brackets will be evaluated only when Environment.type == DEVELOPMENT