Jan 9, 2012

Filtering Log Messages from Abstract Classes

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.

About the Author

Object Partners profile.
Leave a Reply

Your email address will not be published. Required fields are marked *

Related Blog Posts
Up to Spec: JavaScript Numeric Separators
Let's take a look at the proposal to add Numeric Separators to the JavaScript specification.
Using Conftest to Validate Configuration Files
Conftest is a utility within the Open Policy Agent ecosystem that helps simplify writing validation tests against configuration files. In a previous blog post, I wrote about using the Open Policy Agent utility directly to […]
SwiftGen with Image & Color Asset Catalogs
You might remember back in 2015 when iOS 9 was introduced, and we were finally given a way to manage all of our assets in one place with Asset Catalogs. A few years later, support […]
Tracking Original URL Through Authentication
If you read my other post about refreshing AWS tokens, then you probably have a use case for keeping track of the original requested resource while the user goes through authentication so you can route […]