Friday, July 9, 2010

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.

7 comments:

potter_ru said...

First of all, hanks for this blog post.

Fluent API is good, but in multi-threading environment fluent logging implementation should be thead-safe, and it is the main problem for implementation. Current API og java.util.logging, log4j, slf4j, etc. make logging not fluently, but thread-safe.
It is nice, if your implementation solve this. Can it be published under liberael license ?

Torgny said...

Thanks for you comment!
I'm sorry I can't publish the source since it was written at the company where I worked. But I can tell you roughly how the problem with thread-safety was solved.

It was quite simple actually, because every thread had its own instance of your home-written logger. Those instances built the string to log using a fluent interface, and when the entire string was built the string was passed to java.util.logging.

Not sure if that makes sense... I hope it does. :)

potter_ru said...

Hi, Torgny.

If I understand correctly, your implementation uses something like ThreadLocal for home-written logger.

It's ok, but maybe it will be simple to use some kind of LogEntry object with fluent API and pass it to ordinary (jul, log4j, logback) logger.

Just thinking.

Torgny said...

Not entirely sure I understand. Do you mean something like:

logger.info(new EntryBuilder().tryingTo("open port").variable("address", address).done());

That would be possible of course, but it's not particularly nice to look at/read. It's a bit messy in my opinion. But it sure works! :)

Or do I misunderstand you?

potter_ru said...

Yes, I mean something like EntryBuilder in your example.

I agree that it is not nice looking/readable code. :)

Magnus Heino said...

So the impl you had was building that log string all the time, then passing it to the log framework which depending on the level used it or not?

http://www.slf4j.org/faq.html#logging_performance

Torgny said...

Thanks for the link. No, the log string was not built if it wasn't used. Sorry that I didn't make it clear in the post.

All that happened was that references to the parts of the log string were collected. These parts were then "stringified" with "toString()" (if the part wasn't a string already) and then concatinated if and only if the log entry will be printed to the log. It not, the references was simply discarded.