Logging Events

ORIGINAL DRAFT

One of the first things I find myself doing on most new projects is thinking about how to log information. In bigger projects, this is a coordination effort, more intent on getting agreement about what should be logged rather than how to do it. This is always an ongoing effort, but the first objective is typically to put together a log file format consistent with the primary needs of the project. There are usually three areas worth considering: Error logs (to report problems), activity logs (which track important events for later analysis), and debug logs (used to narrow in on a given problem).

Debug logs are the domain of programmers and open to discretion. So long as they can be turned off, they can be used to find unusual problems expediently. With logging, performance can become an issue, especially if the logs are verbose, sometimes interfering with a running program by virtue of this effect, so you have to be reasonable about what you’ll log. Activity logs should be discussed with customers, which may be your marketing group and/or end-users. In either case, activity logs should contain enough information to make analysis useful but not so much that the system’s performance is affected. Error logs are simple enough. If an error or exception occurs, it should always be logged.

In this article, we’ll develop a simple infrastructure for logging, based on the standard Java event model. The notion that your are logging events is a given, but few log implementations take this into account. There is a small amount of overhead in this model but the flexibility more than makes up for it. In fact, when no listeners are associated with a given logging event, the overhead is the same as it would be if logging was turned off in any other model. If only one listener exists, the overhead is insignificant. If multiple listeners are used, there is probably some usefulness that outweighs the performance hit you have to take. For example, supporting remote debugging at more than one site, or streaming to both the console and a file to watch for problems, are both valuable options that are made possible by this event model.

We’ll make this model as simple as possible, allowing you to use the default events or create your own. We’ll provide a set of reusable LogListener objects, including a LogFile, LogConsole, LogRemote (with a LogServer to receive remote events). Finally, we’ll use a LogFactory to unify the use of logs across objects in an application. This helps avoid problems when multiple programmers are working on the same project in different parts of the code, removing opportunities for accidental writing to unintended log targets.

Figure 1: Log classes.

Figure 1 shows the classes we’ll be using. To make life easy, our LogListener interface is implemented by a LogWriter class which is effectively a PrintStream. Each of the LogFile, LogConsole and LogRemote classes extend the LogWriter class to implement their individual behaviors. We define a set of LogType objects to keep things type-safe. We’ll use a LogFactory class, which produces LogListener implementations and allows the same instance to be reused through static calls across an application. The LogDispatcher can be used to dispatch log events to multiple listeners. The LogServer class exists primarily to demonstrate how remote events can be monitored. The LogTest class is our unit test.

There isn’t room to print all the code in this article, so you’ll find full source code online at www.java-pro.com. Because our design is so simple, you’ll find that many of these classes are trivial to implement. We’ll discuss the more significant classes and leave the rest online.

Let’s take a quick look at the LogListener class.

public interface LogListener
{
  public void log(LogEvent event);
}

As you can see, we simply expect to receive a LogEvent in a single method called log. This is easy to implement and flexible enough to make it trivial to subclass LogEvent if you want to log something different.

Listing 1 shows the LogWriter class. The two constructors are there to support a standard PrintWriter extension. The log method, which implements the LogListener interface, merely prints a line by calling the LogEvent toString method. We flush the output to be sure any interruptions don’t invalidated logged events. This is important and worth a bit of elaboration.

You can get better performance if you don’t do flush lines every time, but in my experience, you need logged data to figure out what actually happened and if this information is buffered, there is a risk that the last moment information you need might be lost. If you you think this won’t be an issue, you can always use a BufferedWriter to filter the output. This may be OK with Activity logs, though I think it would be risky in error and debug logs.

To handle a LogFile, we extend the LogWriter class and merely create a FileWriter in append mode in our constructor. Writing to the console is simply a matter of using a System.out stream, so the LogConsole class is also trivial. The last extension for the LogWriter is the LogRemote class, which simply opens a Socket to a remote server and streams the output across TCP/IP connection. LogRemote provides a static method to open the socket and return the OutputStream for use by the LogWriter superclass. I won’t say much about the LogServer, class, which receives events through a socket from the LogRemote class. It’s a fairly standard, multithreaded SocketServer implementation, which merely prints each line to the console. It’s up to you to use more imagination if you want to make it behave differently, though it’s bound to be straight forward to do so.

Let’s take a look at the LogEvent class in Listing 2. We’re interested in logging the date and time stamp for each event, among other things. That means a new Date instance has to be created for each event. This is true regardless of whether you use this approach or another, but reminds us that the overhead of creating new LogEvent objects is not much more than what we would normally have to do in any case. The LogEvent constructor also determines the host name that the code is running on, but is smart enough to do this only once. In addition, we store the source object, LogType and text message in instance variables for later use. Note that time stamping the event when it is constructed is a better choice than doing so when the message is actually logged. Given any latency in the system, the log event will reflect the actual occurrence time rather than the point at which it was written.

The date and time stamps have to be written using a consistent format, so we’ve instantiated a static SimpleDateFormat object for each. We can use these, along with a static DELIMITER value, which is set to the space character by default, to formulate the output string. This is handled using a StringBuffer in the toString method. If you take a closer look, you’ll see that this implementation prints the date, time, source class name, event type, user name, host name and a message passed into the constructor. The LogType is one of ERROR, WARNING or INFO. The user name comes from the System properties.

The LogFactory in Listing 3 shows how we make it easy to work with logs in larger applications. You can call the getLogFile, getLogConsole, and/or getLogRemote methods to create a new instance of a LogListener. You can also call getLogWriter if you want to stream to another output target. In each case, you are expected to provide a key object, which is used in subsequent calls to getLog to gain access to the LogListener. Only once instance is stored for any given key, so ideal use involves creating a named log output (typically a file) in the main method of your application. Declaring constants for ACTIVITY, ERROR and DEBUG logs is a good idea. Then each programer can use a call to LogFactory.getLog(<logname>) to access the appropriate log. Logging is then a simple matter of constructing an event like so: debugLog.log(new LogEvent(this, LogType.INFO, “Just did something important”));

The LogDispatcher class exists to support multiple output destinations. For example, you may be writing to a LogRemote listener but may also want to stream the output to the console, using a LogConsole instance at the same time, especially during pre-release debugging sessions. This is easily done by a LogDispatcher and you can see how this works in Listing 4. The implementation allows you to add or remove a LogListener and dispatches any LogEvent to registered listeners. Since the LogFactory lets you access named logs, you can change the initial definitions without affecting any other code in your application and configure logging however you see fit.

This implementation is very simple but powerful enough to work with large projects. There is enough flexibility to make sure a wide array of circumstances can be accounted for and the overhead is minimal. I’d recommend a more finely tuned system for high-performance applications that truly need to log a lot of data, but you’ll find the investment in better logging decisions to be more a of a factor than the processing overhead of your logging implementation. Log what you need to log without being too verbose. Log things that allow you to analyze critical aspects of your system and avoid leaving instrumentation in a debug log unless you’re dead sure you’re going to need it later.

I think you’ll find this event-driven implementation both flexible and practical. The use of events is more consistent with the purpose of information logging than most implementations I’ve seen. Having the ability to direct events to varying, sometimes multiple, listeners introduces many new possibilities and the small processing overhead involved is a negligible price to pay for the benefits. This model is intuitive and based on a recognized Java event/listener pattern. I hope you find it useful in your own applications.

Listing 1

import java.io.*;

public class LogWriter extends PrintWriter
  implements LogListener
{
  public LogWriter(Writer writer)
  {
    super(writer);
  }
  
  public LogWriter(OutputStream stream)
  {
    super(stream);
  }
  
  public void log(LogEvent event)
  {
    println(event.toString());
    flush();
  }
}

Listing 2

import java.net.*;
import java.util.*;
import java.text.*;

public class LogEvent extends EventObject
{
  protected static String DELIMITER = " ";
  protected static DateFormat
    dateFormat = new SimpleDateFormat("MM/dd/yyyy");
  protected static DateFormat
    timeFormat = new SimpleDateFormat("hh:mm:ss aa");
  protected static String host = null;
  protected static String	user =
    System.getProperties().getProperty("user.name");
  
  protected Date time;
  protected LogType type;
  protected String text;
  
  public LogEvent(Object source, LogType type, String text)
  {	
    super(source);
    time = new Date();
    this.type = type;
    this.text = text;
    if (host == null)
    {
      try
      {
        host = InetAddress.getLocalHost().getHostName();
      }
      catch (UnknownHostException e)
      {
        host = "Unknown";
      }
    }
   }
  
  public Date getTime()
  {
    return time;
  }
  
  public LogType getType()
  {
    return type;
  }
  
  public String getText()
  {
    return text;
  }
  
  public String toString()
  {
    StringBuffer buffer = new StringBuffer();
    buffer.append(dateFormat.format(time));
    buffer.append(DELIMITER);
    buffer.append(timeFormat.format(time));
    buffer.append(DELIMITER);
    buffer.append(getSource().getClass().getName());
    buffer.append(DELIMITER);
    buffer.append(type.toString());
    buffer.append(DELIMITER);
    buffer.append(user);
    buffer.append(DELIMITER);
    buffer.append(host);
    buffer.append(DELIMITER);
    buffer.append(text);
    return buffer.toString();
  }
}

Listing 3

import java.io.*;
import java.util.*;

public class LogFactory
{
  protected static Map table = new HashMap();

  public static LogListener getLog(Object key)
  {
    if (!table.containsKey(key))
      throw new IllegalArgumentException("LogListener not found.");
    return (LogListener)table.get(key);
  }

  public static LogListener getLogConsole(Object key)
  {
    if (!table.containsKey(key))
      table.put(key, new LogConsole());
    return (LogListener)table.get(key);
  }

  public static LogListener getLogFile(Object key, String filename)
    throws IOException
  {
    if (!table.containsKey(key))
      table.put(key, new LogFile(filename));
    return (LogListener)table.get(key);
  }

  public static LogListener getLogRemote(Object key, String host, int port)
  {
    if (!table.containsKey(key))
      table.put(key, new LogRemote(host, port));
    return (LogListener)table.get(key);
  }

  public static LogListener getLogWriter(Object key, Writer writer)
    throws IOException
  {
    if (!table.containsKey(key))
      table.put(key, new LogWriter(writer));
    return (LogListener)table.get(key);
  }

  public static LogDispatcher getLogDispatcher(Object key)
  {
    if (!table.containsKey(key))
      table.put(key, new LogDispatcher());
    return (LogDispatcher)table.get(key);
  }
}

Listing 4

import java.util.*;

public class LogDispatcher implements LogListener
{
  protected ArrayList listeners = new ArrayList();

  public void addLogListener(LogListener listener)
  {
    listeners.add(listener);
  }
  
  public void removeLogListener(LogListener listener)
  {
    listeners.remove(listener);
  }
  
  public void log(LogEvent event)
  {
    ArrayList list = (ArrayList)listeners.clone(); 
    for (int i = 0; i < list.size(); i++)
    {
      LogListener listener = (LogListener)list.get(i);
      listener.log(event);
    }
  }
}

Claude Duguay

Enterprises, Inc.

Logging Events

ORIGINAL DRAFT