Stephen Freeman Rotating Header Image

October, 2011:

Another reason not to log directly in your code

I’ve been ranting for some time that it’s a bad idea directly to mix logging with production code. The right thing to do is to introduce a collaborator that has a responsibility to provide structured notifications to the outside world about what’s happening inside an object. I won’t go through the whole discussion here but, somehow, I don’t think I’m winning this one.

Recently, a team I know provided another reason to avoid mixing production logging with code. They have a system that processes messages and have been asked to record all the accepted messages for later reconciliation with an upstream system. They did what most Java teams would do and logged incoming messages in the class that processes them. Then they associated a special appender with that class’s logger that writes its entries to a file somewhere for later checking. The appenders are configured in a separate XML file.

One day the inevitable happened and they renamed the message processing class during a refactoring. This broke the reference in the XML configuration and the logging stopped. It wasn’t caught for a little while because there wasn’t a test. So, lesson one is that, if it matters, there should have been a test for it. But this is a pretty rigorous team that puts a lot of effort into doing things right (I’ve seen much worse), so how did they miss it?

I think part of it is the effort required to test logging. A unit test won’t do because the structure includes configuration, and acceptance tests run slowly because loggers buffer to improve performance. And part of it is to do with using a side effect of system infrastructure to implement a service. There’s nothing in the language of the implementation code that describes the meaning of reporting received messages: “it’s just logging”.

Once again, if I want my code to do something, I should just say so…

Update: I’ve had several responses here and on other media about how teams might avoid this particular failure. All of them are valid, and I know there are techniques for doing what I’m supposed to while using a logging framework.

I was trying to make a different point—that some code techniques seem to lead me in better directions than others, and that a logging framework isn’t one of them. Once again I find that the trickiness in testing an example like this is a clue that I should be looking at my design again. If I introduce a collaboration to receive structured notifications, I can separate the concepts of handling messages and reporting progress. Once I’ve split out the code to support the reconciliation messages, I can test and administer it separately—with a clear relationship between the two functions.

None of this guarantees a perfect design, but I find I do better if I let the code do the work.

Test-First Development 1968

Seeing Kevlin Henney again at the Goto conference reminded me of a quotation he cited at Agile on the Beach last month.

In 1968, NATO funded a conference with the then provocative title of Software Engineering. Many people feel that this is the moment when software development lost its way, but the report itself is more lively that its title suggests.

It turns out that “outside in” development, with early testing is older than we thought. Here’s a quote from the report by Alan Perlis:

I’d like to read three sentences to close this issue.

  1. A software system can best be designed if the testing is interlaced with the designing instead of being used after the design.
  2. A simulation which matches the requirements contains the control which organizes the design of the system.
  3. Through successive repetitions of this process of interlaced testing and design the model ultimately becomes the software system itself. I think that it is the key of the approach that has been suggested, that there is no such question as testing things after the fact with simulation models, but that in effect the testing and the replacement of simulations with modules that are deeper and more detailed goes on with the simulation model controlling, as it were, the place and order in which these things are done.

It’s all out there in our history, we just have to be able to find it.