Dynamically Configuring Logging at Runtime

I've been using SLF4J - the Simple Logging Facade for Java, and Logback - a native and the preferred implementation, for about 3 years. Logback is an excellent replacement for the popular log4j project, development of which has mostly stalled by Apache. Both SLF4J and Logback were designed and are maintained by Ceki Gülcü, the founder of log4j. This combination of SLF4J and Logback are currently used in many significant projects, ironically including many Apache projects, as well as Hibernate, Jetty, and others. See also on Wikipedia: SLF4J and Log4j.

Like log4j and similar logging frameworks, Logback provides several, powerful options for configuration. This includes an XML configuration file that supports variable substitution, nested variables and property files, default values, and file inclusion, among other features. However, what can be done when these options aren't enough?

In particular, Logback resolves its variables from Java's system properties. These must be set when Java starts, or at another point before SLF4J (Logback) is accessed for the first time and automatically configures itself. (Logback can always be reconfigured, but this isn't exactly clean and can cause other issues.) I have seen practices where all calls to the logging framework are expected to go through a proxy class that would first perform the configuration, but this is prone to error. Even if none of multiple developers accidentally call SLF4J or Logback without going through the proxy, there may be 3rd-party libraries that wouldn't even know of the proxy. Additionally, variables by themselves may not be able to provide the dynamic configuration options desired at runtime.

Even Java's built-in java.util.logging introduced with Java 1.4 reads a java.util.logging.config.class system property that can be used to configure the logging within code. However, this again relies on the system property to be set before logging is accessed. Ideally, it would have a default value and class name that could be read from the classpath. Logback does provide a StatusManager, it is primarily meant only for receiving configuration status updates. While it could feasibly be used as a hook for further configuration, this would be an ugly hack at best, and is not the shown intent of the StatusListeners.

I was adding SLF4J and logback into a large, multi-tiered environment, with multiple application server nodes, and multiple JVMs per node. All JVMs operate from the same NAS mount, so even without considering the multiple JVMs per node, simply providing separate configuration options is not an option - not to mention the need it would introduce to maintain multiple files. Logback's FileAppender actually supports this configuration, in having multiple JVMs write to the same log files through the use of the prudent configuration property - but not without approximately tripling the cost of writing logging events. In this performance-critical environment, this increased cost is not an option - so I needed a way to quickly, easily, and reliably store separate logging files per node and JVM.

The easiest way I found to implement this was by using a sub-classed FileAppender. Here is an example of my configuration:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <rollingPolicy class="com.ziesemer.example.MAZTimeBasedRollingPolicy">
      <FileNamePattern>maz-%d-%jvm.log.gz</FileNamePattern>
      <MaxHistory>60</MaxHistory>
    </rollingPolicy>
    <layout class="ch.qos.logback.classic.PatternLayout">
      <!-- http://logback.qos.ch/manual/layouts.html#PatternLayout -->
      <Pattern>%d [%t] %-5p %c %X - %m%n</Pattern>
    </layout>
  </appender>
  <root>
    <level value="WARN"/>
    <appender-ref ref="FILE"/>
  </root>
</configuration>

And my sub-class:

package com.ziesemer.example;

import java.io.File;
import java.net.InetAddress;

import ch.qos.logback.core.rolling.TimeBasedRollingPolicy;

public class MAZTimeBasedRollingPolicy<E> extends TimeBasedRollingPolicy<E>{
  @Override
  public void setFileNamePattern(String fnp){
    try{
      fnp = fnp.replace("%jvm", System.getProperty("PROCESS_ID"));
      
      String serverName = InetAddress.getLocalHost().getHostName();
      File f = new File("/<logPath>/" + serverName);
      // Logback will create any necessary parent paths.
      super.setFileNamePattern(f.getAbsolutePath() + "/" + fnp);
    }catch(Exception ex){
      throw new RuntimeException(ex);
    }
  }
}

This assumes that the basic functionality of the time-based rolling policy and rolling file appender was still desired. Otherwise, the normal FileAppender could have been sub-classed and used instead. This also assumes that the parent process launching the Java process sets a Java system property called "PROCESS_ID". Otherwise, Igor Minar lists some options for obtaining the process ID through Java, though none are perfect or the most ideal: How a Java Application Can Discover its Process ID (PID) (blog.igorminar.com, 2007-03-03). Still otherwise, a random number or other information could potentially be used to differentiate by JVM.

Note that this implementation doesn't completely control the file name pattern - even though it could. Instead, it is using and extending the file name pattern configured in the XML. It intercepts the configured pattern through the setFileNamePattern(String) method, then calls super with the extended version. Besides adding child directories for each server, it adds support for a new, custom "%jvm" variable - in addition to the "%d" already supported by TimeBasedRollingPolicy.