Some time ago I ran into a not so usual logging problem: too much logging output and no way of turning off the unwanted bits. This article describes the problem of how to control the amout of logging output which is created in complex class hierarchies.

Consider the classes A, B and C with B extends A and C extends B. A,B and C are concrete classes and a couple of instances of them are in use.

Prelude: present situation

I wanted to separate the logging output from A,B and C into different logfiles. Instances of A should write to A.log, instances of B log to B.log and instances of C log to C.log. This was more than the usual

class A {
  protected static final Logger LOG = Logger.getLogger(A.class);
}

could handle. Because B and C would inherit A’s LOG with A as the Category. Overwriting LOG in B and C like this:

class B {
  protected static final Logger LOG = Logger.getLogger(B.class);
}

wouldn’t help either because now instances of B would write their output to either A.log and B.log. If for example some code from B is executed it logs to B.log but if an instance of B executes inherited code from A, it would still log to A.log which would complicate the debugging a lot.

The simple solution was to use one Logger per instance and initialize it at runtime in A’s constructor.

class A {
  protected Logger log;
  public A () {
    log = Logger.getLogger(this.getClass());
  }
}

2 Logger for each class

The Problem: Now all instances from A log to category A, all instances from B to B etc… This was my intended behaviour but soon I found out, that I forgot something. Class A and B were older classes which worked fine but had a lot of legacy debug statements. C was under development.

C wrote all output to category C, which was fine. But when code inherited from A or B was executed they wrote to category C, too. This was the correct behaviour according to my initial plan but it cluttered the whole logfile with debug output I didn’t need at that time and couldn’t turn off. I didn’t want to remove the logging statements, because according to Murphy 5min later I’ll need them. Basically I was looking for a way to turn the debug statements inherited from A and B off without affecting the ones in C.

The Solution was to introduce a second Logger, for each class. This Logger uses the category for this class and is only used to check, if something should be written to the actual Logger.

class A {
  protected Logger log;
  private static final Logger LOG_A = Logger.getLogger(A.class);

  public A () {
    log = Logger.getLogger(this.getClass());
  }

  public void doSomething() {
    if (LOG_A.isDebugEnabled()) {
      log.debug("logging message");
    }
  }
}

This is not as much overhead as it looks, because most logging statements already had a surrounding check, to avoid some expensive toString() calls. Additionally, this seconde logger can be static which makes it only one additional logger per class not per instance.

if (log.isDebugEnabled()) {
  log.debug(o.toString());
}

Now I could turn debug messages from A and B off without affecting C:

log4j.category.A=ERROR
log4j.category.B=ERROR
log4j.category.C=DEBUG

Additionally, I wrote a small wrapper for Logger to prevent me from logging to the second Logger

public final class LoggingSentinel {

  private final Logger logger;

  public LoggingSentinel(final Class c) {
    logger = Logger.getLogger(c);
  }

  public final boolean isDebugEnabled() {
    return logger.isDebugEnabled();
  }

  public final boolean isInfoEnabled() {
    return logger.isInfoEnabled();
  }

  public final boolean isWarnEnabled() {
    return logger.isEnabledFor(Priority.WARN);
  }
  // ...
}

so the code looks like this:

class A {
  protected Logger log;
  private static final LoggingSentinel SENTINEL = new LoggingSentinel(A.class);

  public A () {
    log = Logger.getLogger(this.getClass());
  }

  public void doSomething() {
    if (SENTINEL.isDebugEnabled()) {
      log.debug("logging message");
    }
  }
}