Custom Configuring Java Apps: Extending log4j

The Implementation

My ExtendedLogger class is in Listing One.

Starting at the beginning, I spent (probably way too much) time thinking about whether to call this class Logger or something else. Since it implements all of methods of the log4j Logger, if I called my class Logger as well, then I could wean existing code from the standard log4j Logger to my Logger simply by modifying a few import statements. On the other hand an ExtendedLogger is not a Logger, so there's some potential for confusion, particularly if you try to cast it to a log4j Logger. I opted for the unique name, but I still go back and forth on the issue.

ExtendedLogger objects are created using the Singleton design pattern. Normally, a Singleton is a one-of-a-kind object, in the sense that only one instance of the class exists at runtime, The pattern also requires that the instance be globally accessible. Log4j's reasonable variation on Singleton loosens the definition a bit to say that only one instance of a Logger class with a given name will exist at runtime. To enforce that guarantee of uniqueness, you can't really let people create ExtendedLogger objects at will using new. Consequently, the constructor (on line 125) is private. You'll create objects by calling one of the static public getLogger() methods (on line 131), which gets the (unique) logger from log4j and then passes it to the constructor, which just stores it in wrapped.

The other critical thing that the factory methods do is ensure that log4j is configured properly. They all call configureIfNecessary() (line 165), which calls configure() (line 191) to configure the logging subsystem. Since you can't log anything until you get a Logger instance, and since the only way to get a Logger instance is via one of the getLogger() methods, then you're guaranteed that configuration happens before any logging can happen. This approach (using a Singleton, that is) solves static-initializer problems I discussed earlier. The configure() method just looks for log4j.properties or log4j.xml in the Places.CONFIG directory (I discussed the Places enum last month), and then calls one of the standard log4j configuration methods, depending on the file type (xml or properties). You obviously have to use ExtendedLogger everywhere for this configuration strategy to work.

The bulk of the ExtendedLogger methods (from line 238 to line 321) do nothing but chain through to standard log4j methods, usually the ones with the same name.

The one oddity is in the low-level call that does the actual logging (in print(), on line 373). Here's the interesting (for the moment) line:

   wrapped.log( fullyQualifiedClassName, level, message, e );

That fullyQualifiedClassName is not explained at all in the log4j documentation, but is critical. The variable is declared as follows (on line 115)

   private static final String fullyQualifiedClassName = ExtendedLogger.class.getName();

Log4j uses class name to get the location information (file name, line number, etc.) that it prints in the log message. To see how, consider the following short program:

  package com.holub;
  
  class log4jLogger
  {   public void log(String message)
      {   try
          {   throw new Exception("foo");
          }
          catch( Exception e )
          {   StackTraceElement[] elements = e.getStackTrace();
              int i = 0;
              for( StackTraceElement current : elements )
              {   System.out.printf("elements[%2d]: %24s %4s [%s, line %d]\n",
                                      i++,
                                      current.getClassName(),
                                      current.getMethodName(),
                                      current.getFileName(),
                                      current.getLineNumber() );
              }
          }
      }
  }
  
  class Wrapper
  {   log4jLogger wrapped = new log4jLogger();
      public void log( String message )
      {   wrapped.log(message);
      }
  }
  
  public class LogWrapperDemo
  {   public static void main( String[] args )
      {   a();
      }
      static void a(){ B.b();   }
  }
  class B
  {   static void b(){ C.c();   }
  }
  class C
  {   
      static final Wrapper log = new Wrapper();
      static void c(){ log.log("hello");  }
  }

The log4jLogger class simulates log4j itself. The Wrapper class, just below it, simulates my ExtendedLogger class. The other classes just make the output more interesting. main() (in LogWrapperDemo) calls a(), which calls B.b(), which calls C.c(), which logs something. Running the program prints the following:

    elements[ 0]:    com.holub.log4jLogger  log [LogWrapperDemo.java, line 6]
    elements[ 1]:        com.holub.Wrapper  log [LogWrapperDemo.java, line 26]
    elements[ 2]:              com.holub.C    c [LogWrapperDemo.java, line 42]
    elements[ 3]:              com.holub.B    b [LogWrapperDemo.java, line 37]
    elements[ 4]: com.holub.LogWrapperDemo    a [LogWrapperDemo.java, line 34]
    elements[ 5]: com.holub.LogWrapperDemo main [LogWrapperDemo.java, line 32]

This output is, of course, just the runtime stack trace—the sequence of calls from main(...) (at elements[5]) to the place where the exception was thrown (at elements[0]).

Putting ourselves in the place of log4j, the log() method (at position 0 on the runtime stack) wants to print the location information for the caller, which is directly below it on the runtime stack. All of the location information that log4j needs to put in the log message is there in the java.lang.StackTraceElment object. The only real problem is finding the correct information, which brings us back to the fullyQualifiedClassName that's passed to log4j's log(...) method. The equivalent fully-qualified class name in the current example is com.holub.LogWrapper. log4j finds the location information by finding that fullyQualifiedClassName string in the stack trace, and then using the location information from the element that follows the one that contains the wrapper's fully-qualified name. This example is pretty simple. The actual stack trace in log4j is more complicated, and the element you want isn't necessarily the third from the top. In fact, there's no way to predict exactly where in the stack trace the wrapper call will be located, so log4j does a linear search for the string you pass to it.

Moving on, the new, printf()-like logging methods are defined in Listing One on line 327. They all just chain to the printf() workhorse method on line 386. The main thing this method is doing (other than creating the log message using PrintWriter.printf() and relaying it to log4j's log() method) is handling exception objects in the argument list. I wanted a call like this one:

Exception e;
//...
log.debug("The stack trace is: [%128.128s]\n", e );

To output the same text you'd get when you called e.printStackTrace(). If all you want is the message, you can always do this:

log.debug("The message is: %s\n", e.getMessage() );

but the Throwable (and Exception) classes do not have a getStackTrace() method, so I wanted to make it easier to print one. I didn't want to add a new formatting specifier to printif() — that's way too much work — so I opted to translate Throwable arguments into Strings. The loop on line 391 just goes through the variable-argument list and replaces Throwables with Strings that show the stack trace. (If you haven't worked with variable-argument lists, just remember that elipsis (...) in a method definition's argument list are just semantic sugar. Argument lists are actually passed into "varargs" methods as arrays, so just mentally replace the ... with []. A call to

    System.out.printf("%s %s", hello, world );

is translated by the compiler into something like this:

    System.out.printf("%s %s", new Object[]{hello, world} );

The final programming issue has to do with handling an ambiguity in the method overloads. The problem is that I wanted to support both the old-style exception logging:

    Throwable e;
    //...
    log4jlogger.debug("Message", e);

and printf-style logging:

    Throwable e;
    //...
    log4jlogger.debug("The stack trace is: %s\n", e);

The compiler looks at those two calls and sees an ambiguity: There are two overloads of debug() that can take two arguments, and either one will match both calls:

String debug( String message, Throwable t );
String debug( String format, Object... args );

Java resolves the ambiguity in favor of an exact match, so debug(String,Throwable) is always used, but that version will print garbage if I expect printf()-like behavior.

I solve the problem in print() (on line 373) by using Java's regular-expression mechanism to see if there's a legal "%s" specifier in the first argument. If so, I delegate to printf() (line 386). The "%s" specifiers can be quite complicated once you start adding modifiers (e.g., "%3$-10.5s". is legal), so simple string matching doesn't work. The regular expression that matches them is on line 360, and the time consuming operation (compiling the regular expression) is preformed only once when the class is loaded, so there isn't a huge amount of overhead, here.

Finishing up, note that ExtendedLogger is fully thread safe. The factory methods are all synchronized, as are all the static methods, and that the one object-level instance variable (wrapped, on line 121) is final, which is all you need to do, here, to make the class fully thread safe. Synchronizing the static methods assures that only one thread can be configuring log4j at a given time, and access to read-only fields like wrapped don't have to be synchronized to be safe. (So-called "race conditions" only exist if one thread can be modifying a variable while a different thread is accessing it.) Since there aren't any other shared fields, and since the methods of ExtendedLogger do nothing but call other thread-safe methods (log4j methods are all thread safe), nothing else in ExtendedLgoger needs to be synchronized to be safe.