Logging as a First Class Citizen

Today, I would like to explore how applications can be designed differently if logging were not treated as an afterthought or debugging tool, but as an application feature just as important as any other requirement. So let's start by doing some requirements analysis for logging.

• We need to be able to remember that an event happened.

• We react to different types of events in different ways.

• We are interested in long term patterns with the events.

• We want our recording of events to be reliable.

Starting with remembering that something happened. How would we do this with a first class feature, such as a bank transaction? You probably wouldn't write it to a text file in your application's log directory. Instead, let's store it in a database.

How about reacting to different types of events in different ways? With first class features we create domain objects that have the associated behavior, so lets create a domain object specific to the kind of log message we are remembering.

How about asking questions about long term patterns? For first class features we don't query plain text files with regular expressions, so let's not do it with logging either. Instead store your events with a structure that makes it easy to query and aggregate based on the information you are interested in.

Regarding reliability, since we are treating logging as a first class feature, let's get our log statements under full test coverage. Also be sure to refactor away any structural or literal duplication.

That gets the basics out of the way, now let's explore some details about how this style would affect our code base.

Structural Duplication

Consider this common logging pattern:

if(log.isDebugEnabled()) {
log.debug(
String.format(
"BEFORE: min %d, max %d",
computeMin(list),
computeMax(list)));
}

...

if(log.isDebugEnabled()) {
log.debug(
String.format(
"AFTER: min %d, max %d",
computeMin(list),
computeMax(list)));
}

Here we have some structural duplication. Rather than consider this a "best practice", as I have often heard this particular pattern called, let's remove the structural duplication like we would if this were a first class feature.

The calling code might look like this:

log.notifyListChanged("before", list);

…

log.notifyListChanged("after", list);

Where the contract of the logging code might look like this:

interface ListNotifications {
void notifyListChanged(String caption, List list);
}

And here are two sample implementations:

class ListNotificationsNoOperation {
void notifyListChanged(String caption, List list){}
}

class ListNotificationsUsingLogger(Logger log) {
void notifyListChanged(String caption, List list){
log.debug(
String.format(
"%s: min %d, max %d",
caption.toUpperCase(),
computeMin(list),
computeMax(list)));
}
}

Notice that there is no structural duplication, and you can turn the logging on and off by switching the implementation you are using. Here I am using constructor injection, which is appropriate for when you don't need to configure the logging at runtime. If you did need to be able to configure logging at runtime, it would be a matter of placing another implementation of the same interface in between to act as a dispatcher. The point is to think about the actual use case. Do we actually find ourselves adjusting the logging at runtime?

Test coverage

First lets consider some reasons we usually skip putting logging under test coverage:

• Since the logged values are formatted into a string, to check for the correct value you have to parse it back out again

• Many of the logging frameworks force you to put logging configuration into a specifically named file, making it difficult to configure the logging differently for each test

A happy side effect of removing the structural duplication, is that we have made our logging easier to test. Once logging is behind an interface, it is trivial to create a fake implementation that simply records what was logged for our tests to verify. This handles testing what is persisted to the log.

Coercing everything to a string & querying by string pattern matching

A common use case for logging is to format a data structure into a string, write it to a file, then query the data from a log viewer with a regular expression. However, when you think about it, we have done some unnecessary work here. We had structured data. We threw away that structure by formatting it into a string, now we are using a regular expression to try and pull the data back out again.

Imagine what this would be like if we did the same thing for our data layer. Instead of columns, sql, or a key-value store, we merged the whole domain object into a string. And then, we wrote each of these strings on a separate line. And finally, we got the data back with regular expressions.

If we instead store our log events the way we store first class features, we have a lot more tools available to us when we want to query the data.

Is logging a cross cutting-concern?

I don't think so. To explain why, imagine how we could argue that persistence is a cross-cutting concern. If every screen on your application is going to either display information from your data store, or allow your data store to be edited, then there could be no concern more cross-cutting than persistence. So similar to having a call to LogFactory in every class, we could also have database connection factory in every class.

The actual need for logging is usually one of two things:

• The application is communicating with a collaborator beyond its control, such as a data store or a socket.

• There is a temporary need to expose internal details of the application for debugging purposes. Once the actual behavior is understood and/or fixed, the logging gets shut off.

For the case of collaborators, there are only a finite number of them, so the focus should be on recording enough information to repeat any particular interaction in your development environment.

For cases of temporary debugging, why not printlns? They will be easy to identify and remove later, and since you only need them until you track down the problem, you might as well use the simplest thing that could possibly work.

Does logging provide sufficient business value to be a first class citizen?

Just because something is hard to measure does not mean it is not valuable. Logging can seem to be less valuable than customer facing features, but if a bug gets into production that is costing you a million dollars a day, the time it takes you to understand that bug is quite literally money. It is easy to understand the value of customer facing features, but just as we include the cost of our persistence layer when estimating a user facing feature, we should also include the cost of making sure we can quickly get information about what is going on in production.

Recommendations

• Initially treat logging as a first class citizen, until you can cite specifically why any particular case is deserving of an exception.

   

• Pay attention to the boundaries between your application code and its collaborators Think about what types of queries you might be running against your logged data before deciding on how you will store it.

   

• Avoid logging anything that you are not sure how to act on.

   

• If you are logging a lot of internal details, think about how you can remove the need for these details if you focus on sufficient detail in the inputs and outputs to collaborators.

   

• Initiate your logging via an interface with structured data as parameters; even if all you do on the other side is convert it to a string and write it to a file.

   

• Pay special attention to unhandled exceptions. It may even be worth adding a user interface that developers can access. Imagine how much sooner developers can detect and respond to problems if they have access to an "unhandled exception" page in production.

   

• Go ahead and use a typical logging framework for the cases where you don't want to treat logging as a first class citizen, but still place that portion behind a single interface, so you it is easier to adjust if you find yourself needing more powerful features.