For the past year I’ve been seeing messages like this in a little project I’d been working on:

[Dec-15 21:26:10.777][DEBUG][http-8080-2] [org.springframework.security.web.
authentication.preauth.AbstractPreAuthenticatedProcessingFilter
:doAuthenticate] No pre-authenticated principal found in request

Pretty innocuous, but it turns out that this particular Spring Security filter spits out a lot of messages at the DEBUG level - so many, in fact, that it made it difficult to find debugging messages that I was actually interested in. I had configured Log4J to record org.springframework.security log events at the WARN level or higher, and had spent a couple of hours scratching my head, trying to figure out why these messages were still being logged.

I recently revisited the logging infrastructure in this project, switching out Log4J in favor of SLF4J and Logback.  I eliminated all references to commons-logging using the SLF4J JCL bridge and migrated my log4j.xml config to a logback.xml config, yet the debug messages from Spring Security still continued to be emitted. After a few hours of debugging my way through the depths of the logging systems and this stackoverflow.com post, I figured out what the problem was: the name of the logger used did not match the classname being emitted by the log message.

Consider this code:

public abstract class A {
    private static final Logger LOG = LoggerFactory.getLogger(getClass());
    public void performAbstractOperation()
        { LOG.debug("Performing abstract operation"); }
}

public class B extends A {
    private static final Logger LOG = LoggerFactory.getLogger(B.class);
    public void performConcreteOperation()
        { LOG.debug("Performing concrete operation"); }
}

If the logging facility is set up to report the class name that issues the logging event and is configured to emit logging events from class A at WARN level or higher and from class B at DEBUG level or higher, the LOG.debug message from class A (“Performing abstract operation”) will still show up in the logs when your code runs (and will show up as being emitted by class A!), even though it appears that the logging facility is configured to filter out that logging event.

This happens because of how Log4J and Logback implement their loggers. Each logger has a name associated with it. This name is technically any arbitrary string, but is usually a fully-qualified Java package or class - for example, org.springframework.security or com.mycompany.MyClass. (Using fully-qualified Java package names or class names allows logging configurations to manage entire hierarchies of classes with a single logger entry.) These loggers are fetched by name using the LoggerFactory.getLogger() facility (for SLF4J/Logback - Log4J uses LogFactory.getLog()), passing the object’s Class object as an argument. The named logger that gets fetched is named identically to the fully-qualified class name. In the example above, class B gets the logger named “B” - but class A also gets the logger named “B”, by virtue of using getClass in the call to getLogger (because class “A” is abstract, any instantiated class would have to be of type “B”, which is what getClass() returns).  Because they both get the logger named “B” and “B” is configured to emit DEBUG messages or higher, the logging events from both “A” and “B” are recorded.

By default, the logger name is not emitted into the log files, but the class name is, so it appears that unwanted logging messages aren’t being properly filtered by the logging facility. However, both Log4J and Logback can use “%c” as a pattern in their logging configurations to emit the logger name used by a logging event. This makes it very easy to track down and eliminate any pesky debugging messages from abstract classes (like in the example above.)

Because both “A” and “B” use the same name, it is impossible to filter the DEBUG event from “A” while still seeing the DEBUG event from “B”. In order to fix this, pass a unique name (as a String) to LoggerFactory.getLogger() in either the abstract class or the derived class. This name will become the name of the logger for that class, while the other class will retain the fully-qualified name of the derived class for the name of its logger. The logging facility can then be configured to allow logging events at one level for the logger with the unique name and to allow logging events at a different level for the logger with the name of the derived class.