Log4J - SiftingAppender-like functionality

I work in a project that uses Log4J. One of the requirement is to create a separate log file for each thread; this itself was a odd issue, somewhat sorted by creating a new FileAppender on the fly and attaching it to the Logger instance.

Logger logger = Logger.getLogger(<thread dependent string>);
FileAppender appender = new FileAppender();
appender.setFile(fileName);
appender.setLayout(new PatternLayout(lp.getPattern()));
appender.setName(<thread dependent string>);
appender.setThreshold(Level.DEBUG);
appender.activateOptions();
logger.addAppender(appender);

Everything went fine until we realised that anothe开发者_C百科r library we use - Spring Framework v3.0.0 (which use Commons Logging) - does not play ball with the technique above – the Spring logging data is “seen” only by Appenders initialised from the log4.configuration file but not by the runtime created Appenders. So, back to square one.

After some investigation, I found out that the new and improved LogBack has an appender - SiftingAppender – which does exactly what we need i.e. thread level logging on independent files.

At the moment, moving to LogBack is not an option, so, being stuck with Log4J, how can I achieve SiftingAppender-like functionality and keep Spring happy as well ?

Note: Spring is only used for JdbcTemplate functionality, no IOC; in order to “hook” Spring’s Commons Logging to Log4J I added this line in the log4j.properties file:

log4j.logger.org.springframework=DEBUG

as instructed here.

In Log4j2, we can now use RoutingAppender:

The RoutingAppender evaluates LogEvents and then routes them to a subordinate Appender. The target Appender may be an appender previously configured and may be referenced by its name or the Appender can be dynamically created as needed.

From their FAQ:

How do I dynamically write to separate log files? Look at the RoutingAppender. You can define multiple routes in the configuration, and put values in the ThreadContext map that determine which log file subsequent events in this thread get logged to.

LogBack is accessed via the slf4j api. There is an adapter library called jcl-over-sjf4j which exposes the commons logging interface but makes all the logging to the slf4j API, which goes directly to the implementation - LogBack. If you are using maven, here are the dependencies:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.5.8</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>jcl-over-slf4j</artifactId>
    <version>1.5.8</version>
</dependency> 
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-core</artifactId>
    <version>0.9.18</version>
</dependency>

(and add the commons-logging to the exclusion list, see here)

I struggled for a while to find SiftingAppender-like functionality in log4j (we couldn't switch to logback because of some dependencies), and ended up with a programmatic solution that works pretty well, using an MDC and appending loggers at runtime:

//  this can be any thread-specific string
String processID = request.getProcessID();  

Logger logger = Logger.getRootLogger();

//  append a new file logger if no logger exists for this tag
if(logger.getAppender(processID) == null){

  try{
    String pattern = "%d{yy/MM/dd HH:mm:ss} %p %c{2}: %m%n";
    String logfile = "log/"+processID+".log";

    FileAppender fileAppender = new FileAppender(
        new PatternLayout(pattern), logfile, true);
    fileAppender.setName(processID);

    // add a filter so we can ignore any logs from other threads
    fileAppender.addFilter(new ProcessIDFilter(processID));

    logger.addAppender(fileAppender);
  }catch(Exception e){
    throw new RuntimeException(e);
  }
}

//  tag all child threads with this process-id so we can separate out log output
MDC.put("process-id", processID);

//whatever you want to do in the thread
LOG.info("This message will only end up in "+processID+".log!");

MDC.remove("process-id");

The filter appended above just checks for a specific process id:

public class RunIdFilter extends Filter {

  private final String runId;

  public RunIdFilter(String runId) {
    this.runId = runId;
  }

  @Override
  public int decide(LoggingEvent event) {
    Object mdc = event.getMDC("run-id");

    if (runId.equals(mdc)) {
      return Filter.ACCEPT;
    }

    return Filter.DENY;
  }
}

Hope this helps a bit.

I like to include all of the slf4j facades/re-routers/whateveryoucallthem. Also note the "provided" hack, which keeps dependencies from pulling in commons logging; previously I was using a fake empty commons logging library called version-99.0-does-not-exist.

Also see http://blog.springsource.com/2009/12/04/logging-dependencies-in-spring/

<dependencies>
    <dependency>
        <groupId>commons-logging</groupId>
        <artifactId>commons-logging</artifactId>

        <!-- use provided scope on real JCL instead -->
        <!-- <version>99.0-does-not-exist</version> -->

        <version>1.1.1</version>

        <scope>provided</scope>
    </dependency>

    <dependency>
        <groupId>commons-logging</groupId>
        <artifactId>commons-logging-api</artifactId>

        <!-- use provided scope on real JCL instead -->
        <!-- <version>99.0-does-not-exist</version> -->

        <version>1.1</version>

        <scope>provided</scope>
    </dependency>

    <!-- the slf4j commons-logging replacement -->
    <!-- if any package is using jakarta commons logging this will -->
    <!-- re-route it through slf4j. -->
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>jcl-over-slf4j</artifactId>

        <version>${version.slf4j}</version>
    </dependency>

    <!-- the slf4j log4j replacement. -->
    <!-- if any package is using log4j this will re-route -->
    <!-- it through slf4j. -->
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>log4j-over-slf4j</artifactId>

        <version>${version.slf4j}</version>
    </dependency>

    <!-- the slf4j java.util.logging replacement. -->
    <!-- if any package is using java.util.logging this will re-route -->
    <!-- it through slf4j. -->
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>jul-to-slf4j</artifactId>
        <version>${version.slf4j}</version>
    </dependency>

    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>

        <version>${version.slf4j}</version>
    </dependency>

    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>

        <version>${version.logback}</version>
    </dependency>
</dependencies>

<properties>
    <version.logback>0.9.15</version.logback>
    <version.slf4j>1.5.8</version.slf4j>
</properties>

have you looked at log4j.NDC and MDC? This at least allows you to tag thread specific data to your logging. Not exactly what you're asking, but might be useful. There's a discussion here.