Steve Freeman Rotating Header Image

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.

10 Comments

  1. Besides the logging being first class requirements and therefore should be spcified and tested – it seemsed so obvious when i first heard you mention this. This example appears to me as a good reason to not base implementation on what’s available, but to base your implementatioms on your own abstractions – easier to test and, most probably, to read as.well.

  2. Mike says:

    It’s not clear whether the anecdotal breakage made it to (pre-)production or not. If so, it’s the sort of thing that service monitoring ought to catch.

    We rewrote our config parser a while ago to be very strict and very proactive. No defaults, no on-demand lookup in an untyped bag of values – if anything’s missing or unexpected then everything falls over at startup. Haven’t regretted it yet.

    I’m growing increasingly convinced that XML configuration should be pared down to the absolute bare minimum. XML makes a lousy programming language, and doesn’t offer anywhere near the level of flexibility it promises. The meaningful question isn’t “what can you change without a recompile”, it’s “what can you change on a production server without needing some level of QA, at which point you might as well have recompiled”.

  3. +1 for Mike’s comment, I keep hearding that issue with XML configuration from different sources.
    What do you think of AOP solutions to introduce logging into ordinary code?

  4. Jamie says:

    When I am the boss – and forget all this self-organising rubbish – I simply ban logging for programmers. I prefer other methods to get to diagnostic information, i.e. TDD, test drivers, etc, when the stress is on people revert to habit, which for many programmers is the logger or debugger.

    Good piece.

  5. @Mike of course you’re right. My point, which I should emphasise more, is that some techniques help me move a better direction than others. I don’t find direct logging code in production to be one of them.

    @Giorgio not sure that AOP is really the issue here. Logging seems to be the standard example given for AOP, but that’s a technical fix it doesn’t help me to express the intent of the code.

  6. Mike says:

    @Steve – ah, OK, I’ve just read your linked rant. I think one reason I was missing your point is that we don’t do any of what you call “diagnostic logging” – all logging calls are intended for production and (should) have unit tests.

    I’m not convinced about moving formatting to a “support” helper though. Unless a lot of your log calls look very very similar (which is a smell in itself) then either the support interface is going to grow a zillion different methods to handle a zillion different logging scenarios, or callers are going to drop potentially-useful information on the floor because it doesn’t fit any of the existing signatures.

  7. Malte Finsterwalder says:

    Hi Steve,

    I also read your book and as such also what you wrote about logging.
    It intrigued me.
    I think for the case you state in this post, I’m absolutely on your side. Just writing a log message is not the right tool for a feature requirement. An explicit colaborator is the way to go here.

    But I’m not so sure where to stop.
    I would have to see a reasonable sized system that does not log directly, but always uses collaborators to see what it’s like in the large.

    We do a lot of logging in our code base. (Too much in several places, actually)
    Replacing all our logging with collaborators would introduce a lot of collaborators.

    Debug-Logging is our of the question for me. I would never introduce a collaborator for that.
    Info-Logging is a maybe. Leaning more to the plrobably not side.
    Warn and Error logging is where it get’s more interesting, I think. Cause there I really need to think what I’m doing and logging (or error handling in general) is more important.

    Do you also make these destinctions?
    Did you work on a larger system before, that does not use logging directly?
    Does it turn into a lot of extra collaborators?

    Thanks,
    Malte

  8. Steven Shaw says:

    What’s more is that it seems a big naive to use a logging framework to write application messages to a log. I understand that they’d have used a different appender to filter out these application messages. Even still, they’d still have to choose a debug level such as debug, info, error etc which doesn’t seem to apply in this case. Often logging can be tuned while in production and not just in development – e.g. via JMX. Not to mention what guarantees does the logging framework make about when the application messages make it into the log file, what happens when the disk fills etc.

  9. Sam says:

    In my opinion, the team erred in using a logging framework to feed validation of program processing. What I typically consider a human-mined timeline of important events became a data flow intended to double-check core processing of the program.

    This touches on the delicate definition of what is logging? What is auditing? What is the activity described here?

    Thanks for the post.

    Sam

  10. Neil says:

    As I often say “XML: just say no.”

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <strike> <strong>