DSL: Domain Specific Logging

A few years ago, I was asked to to design a logging framework for our new Product X 2.0. Yeah, I know, "design a logging framework?". That's what I thought too. So I didn't really do much design; all I did was to say "let's use java.util.logging", and then I was done designing. Well kind of anyway...

I started to think back on my first impression of the logging framework in Product X 1.0. I remembered that I had a hard time understanding how it was (supposed) to be used from a developer's point-of-view. That is, when faced with a situation where I had to log, I could not easily answer:

• to which severity category does the entry belong (FINEST, FINER, FINE, INFO, WARNING, SEVERE, ERROR, etc)
• what data should be provided in the entry and how it should be formatted, and
• how log entries normally is expressed textually (common phrases, and other conventions used).

In other words, it was too general (i.e., complex) with too much freedom to define your own logging levels, priorities, etc.

That's why I proposed to make logging easier, thus, the logging framework in Product X 2.0 has very few severity levels. This is implemented by simply wrapping a java.util.logging.Logger in a new class that only has the most necessary methods.

This simplification reduced the code noise in the logger interface, which made it a lot easier to choose log-level when writing a new log message in the source. This had an important implication (that we originally didn't think of): given that a certain message had to be logged, we (the developers) agreed more on which level that message should be logged. No more, "oh, this is a log message written by Robert -- he always use high log level for unimportant messages".

Of course, you could still here comments like "oh, this log message is written by John -- he always use ':' instead of '=' when printing variables". This isn't much of an issue if an somewhat intelligent being is reading the logs, e.g., a human. However, if the logs are read by a computer program, this can be a big problem -- this was the case for Product X 2.0.

This variable-printing business could be solved quite easily; we simply added a method to the logger class (MyLogger) called MyLogger variable(final String name, final Object value) that logged a variable. Example:

logger.variable("result", compResult).low("Computation completed."); 

which would result in the following log message:

2008-apr-12 11:49:30 LOW: Compuation completed. [result = 37289.32];

When I did this, I began to think differently about log messages. It put me into a new mind-set -- the pattern matching mind-set. Patterns in log messages started to appear almost everywhere. Actually, most of our logs followed one of the following patterns:

• Started X
• Completed X
• Trying to X
• Failed to X
• Succeeded to X

Here is an example:

try {
  myLogger.tryingTo("connect to remote host").variable(
                    "address", remoteAddress).low();
  // Code for connecting.
  myLogger.succeededTo("connect to remote host").variable(
                       "address", remoteAddress).low();
} catch (final IOException e) {
  myLogger.failedTo("connect to remote host").cause(e).medium();
}

To take this even further, it is possible to only allow certain combinations of succeededTo, tryingTo, cause, etc, by declaring them in different interfaces. Let's assume that it should only be possible to use cause if the failedTo method have been called. Here's the code for doing that:

interface MyLogger {
  // ... other logging methods.
  CauseLogger failedTo(String msg);
} 

interface CauseLogger {
  LevelChooser cause(Throwable cause);
  LevelChooser cause(String message);
}

interface LevelChooser {
  void low();
  void medium();
  void high();
} 

This is essentially what's called fluent interfaces. It complicates the design of the logging framework, but also makes it impossible to misuse it. Good or bad? It's a matter of taste, I think, but it's a good design strategy to have up your sleeve.