Why (in some cases) does logback invoke toString() even though logging level is disabled?

Question

We recently ran into a performance problem in our system, where toString() was being invoked by Logback even though the specified logging level (DEBUG) was not enabled for that particular logger. Now of course, an additional problem was that our toString() method was very CPU intensive, but this was very unexpected behavior by logback. Given the following simple test case, with the log level of mypkg.LogTest2 unspecified (default), I see toString() invoked twice, but no log messages print (note: linking against logback-classic-0.9.29 and logback-core-0.9.29).

package mypkg;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class LogTest2 {
   private static Logger ROOT_LOGGER = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME);
   private static Logger CLASS_LOGGER = LoggerFactory.getLogger(LogTest2.class);

   public static void main(String[] args){
      LogTest2 obj = new LogTest2();
   }
   public LogTest2() {
      if (CLASS_LOGGER.isDebugEnabled()) {
         ROOT_LOGGER.info("A CLASS_LOGGER debug guarded ROOT_LOGGER info message: {}", this);
         CLASS_LOGGER.debug("A class logger debug message: {}", this);
      }
   }
   public String toString() {
      System.out.println("================= LogTest2 toString invoked.");
      return "{LogTest2}";
   }
}

Output from the above program:

================= LogTest2 toString invoked.
================= LogTest2 toString invoked.

For completeness, here is the logback.xml file I am using:

<?xml version="1.0" encoding="UTF-8"?>
<configuration  scan="true" debug="true">
  <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
    <encoder><pattern>%c -> %msg%n</pattern></encoder>
  </appender>

  <!--  
  <logger name="mypkg" level="debug">  <appender-ref ref="stdout" />  </logger>
  -->
</configuration>

If I update the above logback.xml file to uncomment the "mypkg" logger, the output changes, but still invokes toString() an extra time:

================= LogTest2 toString invoked.
================= LogTest2 toString invoked.
mypkg.LogTest2 -> A class logger debug message: {LogTest2}

This goes against all my understanding of how slf4j and logback logging is supposed to work. Can anyone help me understand this? Is this a bug or expected behavior (and why)?

I can confirm that this doesn't happen in newer versions of Logback, in particular 1.1.2. — Sotirios Delimanolis
I just tried this with logback 1.0.3 (the current latest version we have installed on our project), and although it still has the same behavior, I get a new, helpful warning message out of logback: WARN in Logger[ROOT] - No appenders present in context [default] for logger [ROOT]. — Ogre Psalm33

Sotirios Delimanolis Sotirios Delimanolis · Accepted Answer · 2014-06-04T16:07:04

The ROOT logger is created with a level of DEBUG. When a child logger is created, its effective logging level is set to that of its parent. Also, isDebugEnabled() checks if the effective logging level of the Logger (an int value) is >= to the value of DEBUG. In this case, it is equal since it is inherited from ROOT.

In the example where you don't have a logger declared, it also doesn't have any appenders. The message gets constructed but there's no where to log it to. So while the debug level does get satisfied, it doesn't log anywhere.

In newer versions of logback, it appears the log message construction is done after appenders are checked.

Why (in some cases) does logback invoke toString() even though logging level is disabled?

1 Answers