Why log4j was giving me too much information

At one point when I was configuring log4j output to a log file, the log file was getting way too much information.  Instead of only logging the com.ontsys.advice and org.springframework.transaction.jta categories, it was logging ‘most everything, it seemed.

It was a simple thing to fix: I just needed to remove my AdviceLogger appender-ref from the <root> loggers down at the bottom of jboss-log4j.xml.

It wasn’t JBoss’s fault

I saved my changes to jboss-log4j.xml and waited for JBoss to notice the new file… but it never seemed to notice it, and my advice.log kept not showing up in the log directory.  I immediately suspected JBoss.  “Why isn’t it watching server/default/conf/jboss-log4j.xml like it’s supposed to be?”

Then I remembered that I was editing a copy of jboss-log4j.xml in my Eclipse workspace, so I’d have the benefit of Eclipse’s local history feature.  Oops!

I copied jboss-log4j.xml from my Eclipse workspace out to JBoss’s server/default/conf directory, and sure enough… JBoss noticed the changes.  : )

Customizing log4j logging on JBoss

I want to turn up the logging level on JBoss so that I can verify that the transactional AOP advice runs before the Spring-security-context-populatin’ advice.  The reason being, I want to make sure we’re already in a transaction if something goes wrong in the security context advice, so the message will get rolled back onto the queue.

To be more precise, I want to turn up the logging level on the right categories of classes — my server/default/log/server.log is already 190MB today, and Notepad and Eclipse are having trouble opening it.

The Packages I want to log about

For the first round, I want to see DEBUG-level messages for my Spring-security-context-populatin’ advice (the com.ontsys.advice package in my prototype) and the org.springframework.transaction.jta package.

Adding Logging to my Class

First, I need to add logging to my class — it currently doesn’t log any messages.

Adding logging to a class is simple:

import org.apache.log4j.Logger;
public class MyClass {
    private static final Logger LOGGER = Logger.getLogger(MyClass.class); 

    public void decombobulate() {
        LOGGER.debug("Decombobulating...");
        //...
    }
}

Configuring jboss-log4j.xml

The Logging Conventions chapter of the JBoss Development Process Guide (see also the Logging page on the JBoss Wiki) explains how to log certain categories to a different file.

Only instead of  ${jboss.server.home.dir}/log/ I’ll use more elegant ${jboss.server.log.dir}/ .

Everything in its Proper Place

Note that according to the log4j 1.2.15 DTD, the elements have to be ordered with all appenders first, followed by categories, and then the root element:

<!ELEMENT log4j:configuration (renderer*, appender*,plugin*, (category|logger)*,root?,
                               (categoryFactory|loggerFactory)?)>

Additivity

Note also that there is an additivity attribute you can use on the on the appenders.  The section called Redirecting Category Output has this to say about the additivity attribute:

The additivity attribute controls whether output continues to go to the root category appender. If false, output only goes to the appenders referred to by the category.

That would explain why my main server/default/log/server.log was so small the other time I tried adding a category appender — I think I had additivity=”false” from an example configuration I found somewhere, without understanding what it meant — so output that was going to my special log file was no longer going to my server.log file.

The DTD says that the additivity attribute defaults to “true” though, which is what I want, so I’m leaving it out.

My Changes to jboss-log4j.xml

Here’s what I eventually came up with:

<appender name="AdviceLog" class="org.apache.log4j.FileAppender">
<errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler" />
<param name="Append" value="false" />
<param name="File" value="${jboss.server.log.dir}/advice.log" />
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d %-5p [%c] %m%n" />
</layout>
</appender>
...
<category name="com.ontsys.advice">
<priority value="DEBUG" />
<appender-ref ref="AdviceLog" />
</category>
<category name="org.springframework.transaction.jta">
<priority value="DEBUG" />
<appender-ref ref="AdviceLog" />
</category>

Success

This worked great!  Only stuff from the com.ontsys.advice and org.springframework.transaction.jta packages in the advice.log, at the DEBUG level.

For Next Time

At first the advice.log file was getting way too much information… but we’ll stop here for the moment!

Why the slf4j-jdk14 artifact was optional

Man, are these posts deep-soup technical these days, or what?  I’m afraid all my non-techie friends must have given up in despair some time back…  Ah well, trudging on:

Last time I made a comment about how I thought the slf4j-jdk14 artifact should be marked as a non-optional dependency in Bitronix Transaction Manager’s pom file.  Well, I was wrong.  Here’s why:

slf4j is a façade — something like an interface that can be implemented different ways.  The BTM project does depend on slf4j-api, but it’s apparently up to the dependent project (me) where I want those debug messages to go to.  I choose where I want ‘em to go by installing one of the slf4j providers, such as slf4j-jdk14 (routes to the JDK logger), slf4j-log4j12 (routes to log4j), etc.  Ludovic has explained this to me and pointed me to the BTM page that explains it.  (I think I had glanced at that page before, but at that time I didn’t understand what I was seeing.)  I understand now why BTM doesn’t make the slf4j-XXXX dependency non-optional: that would be choosing an implementation of the slf4j-api, and that decision should be left to the user of BTM (me!)

Fixing my project

Not realizing that there were different implementations of slf4j-api, I had added slf4j-jdk14 to my pom file, which meant that most of BTM’s debug messages were routed to the JDK logger, which I’m not using, so they were being lost.  I just need to change that dependency to this:

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-log4j12</artifactId>
            <version>1.4.3</version>
            <scope>runtime</scope>
        </dependency>

Now when I add this line to my log4j.properties, I get more DEBUG-level output from the BTM classes.

Thanks for the help, Ludovic!