Jun 01

5 Common Log4J Mistakes

Tag: development,java,learning,log4j,opensourcepmularien @ 10:22 pm

I’ve seen these antipatterns over and over again, and I thought it was time to write about them to help any folks who are new to Log4J out there. Senior developers – please share this with your junior peers and save yourself the pain of refactoring later! I’m interested in common mistakes or points of confusion that you’ve seen as well.

Read on to get a quick tutorial, or reference to point your developers at…

Mistake 1: Not logging exceptions at all

Many times, developers don’t realize that there are overloaded versions of the basic log4j methods. I have seen this more times than I can count:

 catch(SomeMeaningfulException e) {
   LOG.error("Bad things: " + e.getMessage());

Why is this bad? Because you just lost the single most valuable piece of information in the exception: the stack trace! Obviously, a well-thought out exception strategy is ideal, but at the very least, do this:

  LOG.error("Bad things",e);

Mistake 2: Not logging exceptions with the correct method

 catch(SomeMeaningfulException e) {
   LOG.error("Bad things");

This is a tricky one. The single-parameter method signature for log4j will simply call toString on the object passed in. In the case of a Throwable, this means you will get the output of getMessage; thus you have exactly the same result as in #1.

Mistake 3: Not adding thread name to PatternLayout

Many, many sample log4j configuration files to be found on the net (such as this example) exclude the crucial thread name property (%t). This is absolutely required when using log4j in any kind of multi-user environment. Without it (and without smart alternative use of something like the MDC/NDC functionality), it’s impossible to trace a series of log statements to a single, consecutive, series of actions — for example, a user request in most modern web frameworks.

Make sure you include the %t conversion parameter if you’re running in any multi-user environment!

Mistake 4: Not making appropriate use of log categories

It’s very common to use the typical fully qualified class name as the name of the Category you log to:

 static Logger LOG = Logger.getLogger(ThisClass.getClass());

This is all well and good, but suffers from 2 flaws:

  • Developers tend to copy and paste this boilerplate code from one class to another. Since the class names are often hard-coded in the static initializer, this is a pattern that is extremely vulnerable to copy-and-paste errors. Java unfortunately doesn’t allow ‘this’ in a static context, and doesn’t have an alternative way to refer to “the current Class”.
  • It doesn’t offer logical organization, especially for API providers. One of the brilliant things that the Hibernate team did in their use of logging is that, in addition to FQCN-named loggers, they identified a series of key “logical” logging categories that abstracted common logging use cases into simple categories (most notably logging of all SQL statements, which can happen in many different classes using the same logical category.

There are various tricks to avoid this scenario.

  • Checkstyle can look for common log4j antipatterns. You’re using checkstyle anyway, right?
  • You can create a logger factory which will look on the call stack for the current class name (as shown here).
  • You can use smart annotations or DI (such as is easily done with Guice) to annotate your Loggers and fill in at runtime.

Mistake 5: Not understanding how (or where) log4j is configured

It’s amazingly common for developers not to know how to configure log4j, or even know where to start to set it up. I personally have answered many, many questions from both co-workers and forum / mailing list folks who can’t figure out how to get started with log4j. Usually this is in conjunction with 3rd party libraries like Spring or Hibernate, running in a web application.

Admittedly, the log4j documentation is not super clear on this subject, and I will attempt to cover the very common scenarios that I have seen confuse developers.

  • If you are running in a web application, generally the log4j configuration file will go in WEB-INF/classes. If you are building in Eclipse, you can explicitly create this directory, or (in some versions of Eclipse) place it in your Java source root directory and it will go to the right place.
  • If you are running in a console application, the log4j configuration file must be somewhere on your CLASSPATH.

You need to have log4j configuration defined in a file called log4j.xml (using the DOMConfigurator syntax), or log4j.properties (using the PropertyConfigurator syntax).

Reference: log4j Default Initialization Procedure

That’s it! What kinds of common problems have you (or developers working with you) run into with log4j? Have you moved to SLF4J, or some other framework? I’ll take the best responses and consolidate them into a new post.

Thanks as always for reading!

8 Responses to “5 Common Log4J Mistakes”

  1. dju` says:

    Thanks for sharing these points. I personally use SLF4J, mainly to benefit from the {} placeholders. With Spring the jcl adapter is needed.

  2. Rusty Wright says:

    I also use logback/slf4j, but for item 4, the pattern is the same. My question has always been, why use a static since it’s probably in a spring bean and there’s only one instance of it anyhow? When it’s not static then you can use getClass(); e.g.,

    private final transient Logger log = LoggerFactory.getLogger(getClass());

  3. Rusty Wright says:

    One of my biggest gripes with log4j is the properties format of the configuration file; this is thankfully gone with logback. I think the xml format is much, much easier to understand. I wish everyone would use the xml format with log4j in their examples.

    Thanks for the tip about the thread name; I’d taken it out long ago not realizing how useful it can be.

    Another thing that can be helpful with exceptions and stack traces is Jakarta Commons Lang has an ExceptionUtils class with many helpful methods.

  4. Ceki Gulcu says:

    Hello Peter,

    The tips here apply to SLF4J (1,2,4) while 3 and 5 apply to logback. I think it would benefit the users of those projects to be aware of the pitfall you enumerate. If you could create a new post reflecting on these pitfalls as applicable using SLF4J and logback, I would gladly link to that post from our project pages.

  5. pmularien says:

    Thanks for the comments, Ceki – I will put that on my queue of articles to write!

  6. Cody Burleson says:

    I agree with Rusty that the XML configuration format is much better. For me, it is much easier to understand and to work with than the legacy properties file format.

    Though most of your readers probably understand the need to use guarded logging (e.g. if(LOG.isTraceEnabled(){…}), I believe that a revision to this post could at least be beneficial for newer developers. Unguarded logging is one of the worst offenders I have seen repeatedly in other people’s code.

    Humbly, I must also add that I am guilty of at least one crime you illuminate in this article, so thanks for pointing it out! Great post!

  7. cmeier says:

    I once worked with an open source app where the authors had written a wrapper around log4j which made it impossible to figure out the line number and class where the actual log call was made because the line number and class logged was always the line number and class name of the wrapper!

  8. mark says:

    log4j’s NDC and MDC functionality is basically very useful, but its usability could need some improvement: to avoid messing up the NDC stack/MDC map by not exactly removing everything at exactly the right time, one needs to explicitly remove elements before EVERY return and on EVERY Exception.

    Is there any solution to that problem?

Leave a Reply

XHTML: You can use these tags: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>