WTF is Log4j’s FQCN?

I’ve browsed through the Log4j source code several times when I needed to write a custom appender, debug some obscure logging issues, etc., and I’d seen the variables FQCN and callerFQCN but never really needed to know what those were until this week.

I had gotten frustrated with this bloated (but necessary) pattern in a lot of our code:

if (log.isDebugEnabled()) {
   log.debug("foo=" + foo + ", bar=" + bar);
}

The isDebugEnabled() check is necessary since foo and bar might have large and/or expensive toString() realizations, and if the Debug level isn’t enabled, the string concatenation will have been wasted, a potentially significant performance problem.

So we do a lightweight check to see if it’s even necessary to build up the string; the unfortunate part is that it takes 3 lines instead of 1, and if there’s a lot of debug logging in a class a significant portion of the code is just logging.

To simply things I borrowed an idea from Seam‘s logging and wrote a utility class that accepts a logger, a message with {0}, {1}, etc. placeholders in MessageFormat style, and varargs parameters to replace the {0}, {1} placeholders, e.g.

Logger.debug(log, "foo={0}, bar={1}", foo, bar);

and the Logger class handles the test that the provided log has debug enabled, and uses MessageFormat to build the final message only if necessary.

This worked great and I switched over a lot of verbose logging calls to use the new approach. But a team member complained that he’d turned on class (%C) and method (%M) logging, and it was claiming that the entries were being logged from the utility class Logger and method debug (although the category name was of course correct). I hadn’t noticed this since he’d only turned on these expensive extra options to debug some obnoxious bugs currently wreaking havoc on our application.

We’re using Commons Logging¹ so I needed to cast the Log instance to a Log4JLogger to access the native Logger via getLogger().

Once I do that, I can convert

log.debug(message);

to the equivalent but more useful

((Log4JLogger)log).getLogger().log(Level.DEBUG, message);

or more specifically

((Log4JLogger)log).getLogger().log(FQCN, Level.DEBUG, message, null);

where the last parameter is the optional Throwable, not relevant to this discussion.

But what’s the FQCN? This is a String, “org.apache.log4j.Logger” if you’re using Log4j directly. The purpose of this is to be able to find the calling method if necessary. Log4j uses a stack trace from a new Throwable to determine the caller (hence the expense of these logging parameters – they shouldn’t be used except for unusual cases).

A stack trace generated in Log4j’s code will have some number of stack elements from the Log4j method calls, then the logger call itself, then the application stack elements. So if you know the fully qualified class name of the logger class, then you can find it in the stack trace, go one deeper, and you know the class name, method, and line number (if javac debug is on).

But I’d introduced one more stack element into the trace, defeating the lookup. Luckily for me, all I needed to do was the replacement above, and substitute the full class name of my utility class and the actual calling method is now correctly resolved.

1. One of the first things I wanted to change when I started on the project was to remove Commons Logging and use Log4J directly since it provides no benefit in our application. I should have seen the nonsensical knee-jerk refusal to consider this as an omen of things to come, but I didn’t. Oh well, more on that later 😉 [back]

I’ve browsed through the Log4j source code several times when I needed to write a custom appender, debug some obscure logging issues, etc., and I’d seen the variables FQCN and...

This entry was posted on Monday, August 13th, 2007 at 2:30am and is filed under java, log4j. You can follow any responses to this entry through the RSS 2.0 feed. Both comments and pings are currently closed.