The 5 Java logging rules

Logging is a critical factor that should be always kept into account during the software development.

When something bad happens in production, the log files are usually the starting point of our fault analysis. And, often, they are the only information in our hands to understand what is happened and which is the root cause of the problem.

It is so very important to have the required information logged properly.

The following five logging rules are a way to check and, possibly, improve how we handle the logging in our code.

Please note that we will not discuss how to configure a logging engine nor we will compare them to each other.

Rule 1. Logging is for readers

The logging messages should be meaningful to who will read the log files, not only to who wrote the (logging) code.

It seem a very obvious rule but it is often violated.

For example, let’s consider a log message like the following

ERROR: Save failure - SQLException .....

Saving what? This message could mean something for the developer but it is completely useless for the poor guy which is looking at the production problem.

Much better message is

ERROR: Save failure- Entity=Person, Data=[id=123 surname="Mario"] - SQLException....

which explains what you wanted to save (here a Person, a JPA entity) and the relevant contents of the Person instance. Please note the word relevant, instead of the world all: we should not clutter log files with useless info like the complete print of all entity fields. Entity name and its logical keys are usually enough to identify a record in a table.

Rule 2. Match the logging levels with the execution environment

All logging facades and engines available in the Java ecosystem have the concept of logging level (ERROR, INFO…), with the possibility to filter out messages with too low level.

For example, Java util logging uses the following levels: SEVERE, WARN, INFO, FINE, FINER, FINEST (+ CONFIG and OFF).

On the contrary, the two most popular logging facade, Apache Commons Logging and SLFJ, prefer the following levels: FATAL, ERROR, WARN, INFO, DEBUG, TRACE.

Logging level filtering should depends on which stage of the development is your code: logging level in the production should not be the same as in test/integrations environments.

Moreover, logging level should also depends on the code owner. In general our own application code should have a more detailed logging compared to any third party library we are using. There is no big meaning to see, for example, Apache Commons debug messages in our log files.

I usually configure the logging as following:

  • Production: INFO level for my code and WARN for third party libraries.
  • Test / Integration: DEBUG level for my code and WARN (or INFO if needed) for third party libraries.
  • Development: whatever make sense

Note: I personally discourage the use of the TRACE/FINEST level (and I’m not alone, see for example here). I don’t see big difference between DEBUG and TRACE and it is usually difficult for the young team members to decide which one, DEBUG or TRACE, to use. Following the Kiss principle, I suggest to use ERROR, WARN, INFO and DEBUG levels only.

Rule 3. Remove coding help logging before the commit.

While coding, we usually add logging messages, using the logger or the System.out, in our code for a better understanding of what it is happening in our application during execution /debugging sessions.

Something like:

    void aMethod(String aParam) {
        LOGGER.debug(“Enter in aMethod”);
        if (“no”.equals(aParam)) {
           LOGGER.debug(“User says no”);
          ….

The main purpose of these messages is to trace application behaviour by showing which method is invoked and by dumping internal variables and method parameters values. Quite popular among non TDD devotes.

Unfortunately these messages do not have usually big meaning once the code has been released (to test and then production).

So this rule simply says: once you have finished to develop, remove all temporary and unnecessary logging messages just before committing the code to the SCM system (git, svn..) in use.

This rule does not require to remove all DEBUG messages but only the ones that do not have meaning once the application is completed and released; in other words when we are reasonably sure that the application is working properly.

Rule 4: Check log level before logging DEBUG messages

According to Rule 2, in production logs we will show ERROR, WARN, INFO messages only but in our code we can have many DEBUG messages that should not affect production execution.

Every time you want to log a DEBUG message (all the ones which remain after rule 3), add in front a check if DEBUG logging is enabled:

    if ( LOGGER.isDebugEnabled() ) {
        LOGGER.debug (…….)
    }

This will prevent you code to build the log messages and call the logger. It is for efficiency in the program execution at production.

Rule 5: Know your logger

How we use the logger methods can have a significant cost:

  • To build the message string
  • to collect the data to be included in the message string

We should review the javadoc of the selected logging facade/engine and understand the most efficient way to use its logger.

For example, we could create a message like this:

    LOGGER.info(“Person name is “ + person.getName());

which creates unnecessary strings instances.

Using SLF4J, the correct use is :

    LOGGER.info(“Person name is {}“, person.getName());

where format string is constant and the final message is build only if logging is enabled. See here for more details.

Advertisements

5 thoughts on “The 5 Java logging rules

  1. Pingback: Links & Reads from 2015 Week 48 | Martin's Weekly Curations

  2. Pingback: Tutorial: Correct SLF4J logging usage and how to check it | Gualtiero Testa

  3. Hello Gualtiero!
    Thanks for the article.
    I have a question about Rule 4: do we really need to add additional check of log level? For example, Log4jRollingAppender has the following code in LOGGER.debug() method:
    if(this.logger.isDebugEnabled())

    So it means that implementation of logger already has this check and we can remove additional if() statement around LOGGER.debug()?

    • Hi Dimitry, yes, the debug method has an internal check of the log level for the current log. This is a kind of filter which is valid for all logger methods. Thanks for this filter, debug messages are not really logged if the log level is, for example, INFO.
      For static messages like logger.debug(“enter in the method”), the rule 4 external additional check is useless (it is a duplicated test).
      For dynamic messages which use object values and method calls returns, like logger.debug(“Message {} for user {} is {}”, message.getId(), user.name(), message) (SLF4J syntax), there is a cost to create the arguments (the placeholders) for the log message string. We pay this cost even if log level is INFO because arguments are resolved before debug() method invocation (this is how Java works) and so before the internal debug method () check .
      In the latter case, the dynamic, which, by the way, it should be the most common case (see Rule 1), the external guard save us the cost to build the arguments.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s