Write custom appenders for log4j

Extend log4j to support lightweight over-the-network logging

Logging is the simple process of printing messages of various types to known places. Logging messages can go to a console, to a file, to a remote monitor, or anywhere else that you find convenient. Think of logging as a sophisticated sibling of:

 if( debug )
    System.out.println("Debugging diagnostic");

Logging has several advantages over simple

println()

statements, however. The logging system can add contextual information—filename, line number, and date, for example—to the message automatically. You can redirect the messages to different destinations, or change the formatting, without recompiling your program. (In log4j, you just modify a simple properties file.) You can easily turn categories of messages on and off so you can see debug messages when you're debugging, but easily turn them off when you're not, for example.

Logging is central to all of my programs. I use it to monitor my program's progress as it works. I use it to log error messages from library methods that might be used in a server-side context (where there's no console on which to print a stack trace). Most importantly, logging is one of my main debugging tools. Though visual debuggers are handy on occasion, I've noticed that I can find more bugs faster by combining a careful reading of the code with a few well-placed logging messages. (I'm not quite sure why reading/logging seems more effective than visual debugging, but my current theory is that a visual debugger narrows your focus to a single thread of control through the program, so you tend to miss bugs that aren't on that thread.)

Logging is essential in server-side debugging, where, typically, no console exists, so System.out proves useless. For example, Tomcat sends System.out to its own log file, so you never see messages that are sent there unless you have access to that log file. More to the point, you probably want to monitor a server's performance from somewhere other than the server itself. Checking server logs is nice, but I'd much rather see the logs on my workstation.

One of the better logging systems around is the Apache Software Foundation's log4j project. It's more flexible and easier to use than Java's built-in APIs. It's also a trivial install—you just put a jar file and a simple configuration file on your CLASSPATH. (Resources includes a good introduction article to log4j.) Log4j is a free download. The stripped-down but adequate-for-the-end-user documentation is also free. But you have to pay 0 for the complete documentation, which I recommend.

This article will look at how to extend log4j by adding a new appender—the part of the system responsible for actually sending the log messages somewhere. The appender I discuss is a lightweight version of the socket-based appender that comes with log4j, but you can easily add your own appenders to put log messages into a database or LDAP (lightweight directory access protocol) directory, wrap them in proprietary protocols, route them to specific directories, and so forth.

Using log4J

Listing 1 demonstrates how to use log4j. You create a

Logger

object associated with the current class. (The string argument to

getLogger()

is actually arbitrary, but the class name is by far the most useful name for the logger.)

Then, when you want to log a message, you just send it to the logger. Logged messages typically fall into one of five categories: debug, info, warn, error, or fatal, and methods named

debug()

,

info()

, and so on, handle each of these. When you're done logging, it's good style to shut down the logging subsystem with a call to

shutdown()

(at the bottom of

main()

). This call is particularly important for the example I'm about to cover because

shutdown()

indirectly causes socket connections to remote clients to shut down in an orderly way.

Listing 1. Test.java: Using the log4j classes

  1  import org.apache.log4j.Logger;
   2  import org.apache.log4j.LogManager;
   3  
   4  public class Test
   5  {
   6      private static final Logger log = Logger.getLogger( "com.holub.log4j.Test");
   7  
   8      public static void main(String[] args) throws Exception
   9      {
  10          // For testing, give the client that will display the
  11          // logged messages a moment to connect.
  12          // (It's in a 50-ms wait loop, so pausing for
  13          // 100 ms should do it).
  14          Thread.currentThread().sleep( 100 );
  15  
  16          log.debug("Debug   Message");
  17          log.warn ("Warning Message");
  18          log.error("Error   Message");
  19  
  20          Thread.currentThread().sleep( 100 );
  21          LogManager.shutdown();
  22      }
  23  }

The only other piece of the puzzle is a simple configuration file, which (thankfully) is not in XML format. It's a simple properties file, like the one in Listing 2.

To understand the file, you need to know a little about the logger architecture. Loggers form a runtime hierarchy of objects, organized by name. The "root" logger is at the root of the hierarchy, and the loggers you create are beneath the root (and each other), depending on their names. For example, a logger named a.b is beneath the logger named a, which is beneath the root.

Loggers write strings using two main helper classes called appenders and layouts. An appender object does the actual writing, and a layout object formats the message. Appenders are bound to a logger at runtime using information in the configuration file—this way, you can change them without recompiling. A particular logger can use several appenders, in which case, each appender sends the message somewhere, thus duplicating messages in several places. Log4j comes with several appenders that do things like console and file output and send logging messages using email or JMS (Java Message Service). Log4j also includes a socket-based appender similar to the one I illustrate in this article.

Layout objects, which control message formatting, are bound to appenders at runtime in a manner similar to loggers and appenders. Log4J comes with several layout classes, which format in XML, HTML, and by means of a printf-like format string. I've found these to be adequate for most of my needs.

Finally, loggers also have filtering. The idea is to filter out, or discard, all categories of messages below a certain priority. The categories I mentioned earlier (debug, info, warn, error, or fatal) are in priority order. (Debug is the lowest and fatal, the highest.) You can filter all messages at or below a specified level simply by telling the logger to do so—either in your code or in the configuration file.

Turning to Listing 2, the first line specifies the filter level (

DEBUG

) and the appenders (

FILE

,

CONSOLE

, and

REMOTE

) attached to the root logger. All loggers beneath the root in the runtime hierarchy inherit this filter level and these appenders, so this line effectively controls logging for the whole program (unless you use a more complex configuration file to specify something different).

The remainder of the configuration file specifies properties for the appenders. For example, Listing 2's second line says that the file appender named

FILE

is an instance of the

com.apache.log4j.FileAppender

class. Subsequent lines initialize this appender object when it's created—in this case, passing it the name of the file in which it will put the log messages, the layout object to use, and a format string for that layout object.

The rest of the configuration file does the same for the other appenders. The

CONSOLE

appender sends messages to the console, and the

REMOTE

appender sends messages down a socket. (We'll look at the source code for the

REMOTE

appender shortly.)

At runtime, log4j creates all the required classes for you, hooks them up as necessary, and passes the arguments you specify in the configuration file to the newly created objects using JavaBean-style "setter" methods.

Listing 2. log4j.properties: A log4j configuration file

 log4j.rootLogger=DEBUG, FILE, CONSOLE, REMOTE
log4j.appender.FILE=org.apache.log4j.FileAppender
log4j.appender.FILE.file=/tmp/logs/log.txt
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout.ConversionPattern=[%d{MMM dd HH:mm:ss}] %-5p (%F:%L) - %m%n
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=[%d{MMM dd HH:mm:ss}] %-5p (%F:%L) - %m%n
log4j.appender.REMOTE=com.holub.log4j.RemoteAppender
log4j.appender.REMOTE.Port=1234
log4j.appender.REMOTE.layout=org.apache.log4j.PatternLayout
log4j.appender.REMOTE.layout.ConversionPattern=[%d{MMM dd HH:mm:ss}] %-5p (%F:%L) - %m%n

Using a remote appender

One of log4j's major strengths is that the tool is easy to extend. My

RemoteAppender

extension provides a way to log messages across the network to a simple socket-based client application. Log4J actually comes with a means of doing remote logging (an appender called

SocketAppender

), but this default mechanism is too heavyweight for my needs. It requires you to have the log4j packages on the remote client, for example.

Log4j also comes with an elaborate standalone GUI called Chainsaw that you can use to view messages from a

SocketAppender

. But Chainsaw is also way more than I need and really badly documented to boot. (I've never have had the time or patience to figure out how to use Chainsaw.) In any event, I just wanted to watch debugging diagnostics scroll by on a console window as I tested. Chainsaw was way too much for this simple need.

Listing 3 shows a simple viewer application for my

RemoteAppender

. It's just a simple socket-based client application that waits in a loop until it can open a socket to the server application that logs the messages. (See

Resources

for a discussion of sockets and Java's socket APIs). The port number, which is hard-coded into this simple example (as

1234

) is passed to the server via the configuration file in Listing 2. Here's the relevant line:

 log4j.appender.REMOTE.Port=1234

The client application waits in a loop until it can connect to the server, and then it just reads messages from the server and prints them to the console. Nothing earth shattering. The client knows nothing about log4j—it just reads strings and prints them—so the coupling to the log4j systems is nonexistent. Launch the client with

java Client

and terminate it with a Ctrl-C.

Listing 3. Client.java: A client for viewing logging messages

  1  import java.net.*;
   2  import java.io.*;
   3  
   4  public class Client
   5  {
   6      public static void main(String[] args) throws Exception
   7      {
   8          Socket s;
   9          while( true )
  10          {   try
  11              {
  12                  s = new Socket( "localhost", 1234 );
  13                  break;
  14              }
  15              catch( java.net.ConnectException e )
  16              {   // Assume that the host isn't available yet, wait
  17                  // a moment, then try again.
  18                  Thread.currentThread().sleep(50);
  19              }
  20          }
  21  
  22          BufferedReader in = new BufferedReader(
  23                                  new InputStreamReader( s.getInputStream() ) );
  24  
  25          String line;
  26          while( (line = in.readLine()) != null )
  27              System.err.println( line );
  28      }
  29  }

Note, by the way, that the client in Listing 3 is a great example of when not to use Java's NIO (new input/output) classes. There's no need for asynchronous reading here, and NIO would complicate the application considerably.

The remote appender

All that's left is the appender itself, which manages the server-side socket and writes the output to the clients that connect to it. (Several clients can receive logging messages from the same appender simultaneously.) The code is in Listing 4.

Starting with the basic structure, the

RemoteAppender

extends log4j's

AppenderSkeleton

class, which does all of the boilerplate work of creating an appender for you. You must do two things to make an appender: First, if your appender needs to be passed arguments from the configuration file (like the port number), you need to provide a getter/setter function with the names

getXxx()

and

setXxx()

for a property named

Xxx

. I've done that for the

Port

property on line 41 of Listing 4.

Note that both the getter and setter methods are

private

. They're provided strictly for use by the log4j system when it creates and initializes this appender, and no other object in my program has any business accessing them. Making

getPort()

and

setPort()private

guarantees that normal code can't access the methods. Since log4j accesses these methods via the introspection APIs, it can ignore the

private

attribute. Unfortunately, I've noticed that private getters and setters work only in some systems. I have to redefine these fields as public to get the appender to work correctly under Linux, for example.

The second order of business is to override a few methods from the AppenderSkeleton superclass.

After log4j has parsed the configuration file and called any associated setters, the

activateOptions()

method (Listing 4, line 49) is called. You can use

activeOptions()

to validate property values, but here I'm using it to actually open up a server-side socket at the specified port number.

activateOptions()

creates a thread that manages the server socket. The thread sits in an endless loop waiting for the client to connect. The

accept()

call on line 56 blocks, or suspends, the thread until a connection is established;

accept()

returns a socket connected to the client application. The thread is terminated in

close()

, which we'll look at shortly, by closing the

listenerSocket

object. Closing the socket causes a

SocketException

to be thrown.

Once the connection is established, the thread wraps the output stream for the client socket in a

Writer

and adds that

Writer

to a

Collection

called

clients

. There's one

Writer

in this

Collection

for each client connected to the current appender.

The synchronization is worth mentioning. I put objects into

clients

in the socket-management thread, but the collection is also used by whatever thread actually doing the logging.

The code that does the actual appending is in the

append()

method (Listing 4, line 93). The appender first delegates message formatting to the layout object specified in the configuration file (on line 107) and then writes the message to the various client sockets on line 120. The code formats the message only once, but then iterates through the

Writer

s for each client and sends the message to each of them.

That iteration is tricky. I could have wrapped the

clients Collection

in a synchronized wrapper by calling

Collections.synchronizedCollection()

and not explicitly synchronized. Had I done so, however, the

add()

method back in the socket-management thread would have thrown an exception if an iteration was in progress when it tried to add a new client.

Since clients aren't added often, I've solved the problem simply by locking the

clients Collection

manually while iterations are in progress. This way, the socket-management thread blocks until the iteration completes. The only downside to this solution is that a client might have to wait a while before the server accepts the connection. I haven't found this wait to be problematic.

The only appender method that remains is an override of

close()

(Listing 4, line 143), which closes the server socket and cleans up (and closes) the client connections. As I mentioned earlier, closing the

listenerSocket

terminates the thread that contains the

accept()

loop.

Listing 4. RemoteAppender.java: A custom log4j appender

  1  package com.holub.log;
   2  
   3  import org.apache.log4j.AppenderSkeleton;
   4  import org.apache.log4j.spi.LoggingEvent;
   5  import org.apache.log4j.spi.ErrorCode;
   6  import org.apache.log4j.Layout;
   7  import org.apache.log4j.helpers.LogLog;
   8  
   9  import java.util.*;
  10  import java.io.*;
  11  import java.net.*;
  12  
  13  /** This appender works much like log4j's Socket Appender.
  14   *  The main difference is that it sends strings to
  15   *  remote clients rather than sending serialized
  16   *  LoggingEvent objects. This approach has the
  17   *  advantages of being considerably faster (serialization
  18   *  is not cheap) and of not requiring the client
  19   *  application to be coupled to log4j at all.
  20   *
  21   *  <p>This appender takes only one "parameter," which specifies
  22   *     the port number (defaults to 9999). Set it with:
  23   *  <PRE>
  24   *  log4j.appender.R=com.holub.log4j.RemoteAppender;
  25   *  ...
  26   *  log4j.appender.R.Port=1234
  27   *  </PRE>
  28   *
  29   */
  30  
  31  public class RemoteAppender extends AppenderSkeleton
  32  {
  33      // The iterator across the "clients" Collection must
  34      // support a "remove()" method.
  35  
  36      private Collection   clients = new LinkedList();
  37      private int          port    = 9999;
  38      private ServerSocket listenerSocket;
  39      private Thread       listenerThread;
  40  
  41      private void setPort(int port)  { this.port = port; }
  42      private int  getPort()          { return this.port; }
  43  
  44      public boolean requiresLayout(){ return true; }
  45  
  46      /** Called once all the options have been set. Starts
  47       *  listening for clients on the specified socket.
  48       */
  49      public void activateOptions()
  50      {   try
  51          {   listenerSocket  = new ServerSocket( port );
  52              listenerThread  = new Thread()
  53              {   public void run()
  54                  {   try
  55                      {   Socket clientSocket;    
  56                          while( (clientSocket = listenerSocket.accept()) != null )
  57                          {   // Create a (deliberately) unbuffered writer
  58                              // to talk to the client and add it to the
  59                              // collection of listeners.
  60  
  61                              synchronized( clients )
  62                              {   clients.add(
  63                                      new OutputStreamWriter(
  64                                          clientSocket.getOutputStream()) );
  65                              }
  66                          }
  67                      }
  68                      catch( SocketException e )
  69                      {   // Normal close operation. Doing nothing
  70                          // terminates the thread gracefully.
  71                      }
  72                      catch( IOException e )
  73                      {   // Other IO errors also kill the thread, but with
  74                          // a logged message.
  75                          errorHandler.error("I/O Exception in accept loop" + e );
  76                      }
  77                  }
  78              };
  79              listenerThread.setDaemon( true );
  80              listenerThread.start();
  81          }
  82          catch( IOException e )
  83          {   errorHandler.error("Can't open server socket: " + e );
  84          }
  85      }
  86  
  87      /** Actually do the logging. The AppenderSkeleton's 
  88       *  doAppend() method calls append() to do the
  89       *  actual logging after it takes care of required
  90       *  housekeeping operations.
  91       */
  92  
  93      public synchronized void append( LoggingEvent event )
  94      {   
  95          // If this Appender has been closed or if there are no
  96          // clients to service, just return.
  97  
  98          if( listenerSocket== null || clients.size() <= 0 )
  99              return;
 100  
 101          if( this.layout == null )
 102          {   errorHandler.error("No layout for appender " + name ,
 103                                  null, ErrorCode.MISSING_LAYOUT );
 104              return;
 105          }
 106  
 107          String message = this.layout.format(event);
 108  
 109          // Normally, an exception is thrown by the synchronized collection
 110          // when somebody (i.e., the listenerThread) tries to modify it
 111          // while iterations are in progress. The following synchronized
 112          // statement causes the listenerThread to block in this case,
 113          // but note that connections that can't be serviced quickly
 114          // enough might be refused.
 115  
 116          synchronized( clients )
 117          {   for( Iterator i = clients.iterator(); i.hasNext(); )
 118              {   Writer out = (Writer)( i.next() );
 119                  try
 120                  {   out.write( message, 0, message.length() );
 121                      out.flush();
 122                      // Boilerplate code: handle exceptions if not
 123                      // handled by layout object:
 124                      //
 125                      if( layout.ignoresThrowable() )
 126                      {   String[] messages = event.getThrowableStrRep();
 127                          if( messages != null )
 128                          {   for( int j = 0; j < messages.length; ++j )
 129                              {   out.write( messages[j], 0, messages[j].length() );
 130                                  out.write( '\n' );
 131                                  out.flush();
 132                              }
 133                          }
 134                      }
 135                  }
 136                  catch( IOException e )  // Assume that the write failed
 137                  {   i.remove();         // because the connection is closed.    
 138                  }
 139              }
 140          }
 141      }
 142  
 143      public synchronized void close()
 144      {   try
 145          {   
 146              if( listenerSocket == null ) // Already closed.
 147                  return;
 148              listenerSocket.close();     // Also kills listenerThread.
 149  
 150              // Now close all the client connections.
 151              for( Iterator i = clients.iterator(); i.hasNext(); )
 152              {   ((Writer) i.next()).close();
 153                  i.remove();
 154              }
 155  
 156              listenerThread.join();      // Wait for thread to die.
 157              listenerThread  = null;     // Allow everything to be
 158              listenerSocket  = null;     // garbage collected.
 159              clients         = null;
 160          }
 161          catch( Exception e )
 162          {   errorHandler.error("Exception while closing: " + e);
 163          }
 164      }
 165  }

Conclusion

That's all there is to building an appender. You override a few methods of AppenderSkeleton and add getter/setter methods for the parameters. Most of the nastiness here is socket-and-thread related. The actual log4j code was simplicity itself (extend a class and overwrite a few methods). Writing your own appenders for things like logging to a database, for example, is equally simple.

In general, you can use custom appenders in many interesting ways. For example, your appender could put the log messages into a database so you can search them using SQL. You can distribute the messages to a directory (either LDAP or files) to make it easier to separate critical messages from noncritical ones. You could even write appenders to send people pages or SMS (short message service) messages when something goes really wrong with the system (though the built-in SMTP appender might be able to do that as well). Appenders make an already powerful system even more powerful.

Allen Holub has worked in the computer industry since 1979 on everything from operating systems, to compilers, to Web applications. He is a consultant, providing mentoring and training in object-oriented design and Java development, technical due diligence, design reviews, and he writes programs on occasion. He served as a chief technology officer at NetReliance and sits on the board of advisors for Ascenium and Ontometrics. Allen has authored nine books (including Holub on Patterns: Learning Design Patterns by Looking at Code, Taming Java Threads, and Compiler Design in C) and more than 100 magazine articles. Allen has been a contributing editor for JavaWorld since 1998 and for SD Times since 2004.

Learn more about this topic

Join the discussion
Be the first to comment on this article. Our Commenting Policies