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.

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.

An example of an unhedged software call option

At a client, we’ve been reworking some particularly hairy calculation code. For better or worse, the convention is that we call a FooFetcher to get hold of a Foo when we need one. Here’s an example that returns Transfers, which are payments to and from an account. In this case, we’re mostly getting hold of Transfers directly because can identify them1.

public interface TransferFetcher {
  Transfer      fetchFor(TransferId id);
  Transfer      fetchOffsetFor(Transfer transfer);
  Set<Transfer> fetchOutstandingFor(Client client, CustomerReference reference);
  Transfer      fetchFor(CustomerReference reference);
}

This looks like a reasonable design—all the methods are to do with retrieving Transfers—but it’s odd that only one of them returns a collection of Transfers. That’s a clue.

When we looked at the class, we discovered that the fetchOutstandingFor() method has a different implementation from the other methods and pulls in several dependencies that only it needs. In addition, unlike the other methods, it has only one caller (apart from its tests, of course). It doesn’t really fit in the Fetcher implementation which is now inconsistent.

It’s easy to imagine how this method got added. The programmers needed to get a feature written, and the code already had a dependency that was concerned with Transfers. It was quicker to add a method to the existing Fetcher, even if that meant making it much more complicated, than to introduce a new collaborator. They sold a Call Option—they cashed in the immediate benefit at the cost of weakening the model. The team would be ahead so long as no-one needed to change that code.

The option got called on us. As part of our reworking, we needed to change how Transfer objects were constructed so we could handle a new kind of transaction. The structure we planned meant changing another object, say Accounts, to depend on a TransferFetcher, but the current implementation of TransferFetcher depended on Accounts to implement fetchOutstandingFor(). We had a dependency loop. We should have taken a diversion and moved the behaviour of fetchOutstandingFor() into an appropriate object, but then we had our own delivery pressures. In the end, we found a workaround that allowed us to finish the task we were in the middle of, with a note to come back and fix the Fetcher.

The cost of recovery includes not just the effort of investigating and applying a solution (which would have been less when the code was introduced) but also the drag on motivation. It’s a huge gumption trap to be making steady progress towards a goal and then be knocked off course by an unnecessary design flaw. The research described in The Progress Principal suggests that small blockers like this have a disproportionate impact compared to their size. Time to break for a cup of tea.

I believe that software quality is a cumulative property. It’s the accumulation of many small good or bad design decisions that either make a codebase productive to work with or just too expensive to maintain.

…and, right on cue, Rangwald talks about The Tyranny of the Urgent.



1) The details of the domain have been changed to protect the innocent, so please don’t worry too much about the detail.

Thanks to @aparker42 for his comments

Going to Goto (twice)

GOTO ConferencesI’ll be at Goto Aarhus October 9-14 this year, giving a presentation and workshop on Nat Pryce and my material on using Test-Driven Development at multiple levels, guiding the design of system components as well as the objects within them.

If you register with the code free1250, you’ll get a discount of 1250 DKK and Goto will donate the same amount to Computers for Charities

Some of us are then rushing to Goto Amsterdam, where I’ll be giving the talk again on Friday. Again the code free1250 will do something wonderful, but I’m not quite sure what.

Is Dependency Injection like Facebook?

The problem with social networks

I think there’s a description in Paul Adams’ talk about online vs. offline social networks of how Dependency Injection goes bad, particularly when using one of the many automated frameworks.

Adams describes a research subject Debbie who, in “real life” has friends and contacts from very different walks of life. She has friends from college with alternative lifestyles who post images from their favourite LA gay bars. She also trains local 10-year olds in competitive swimming. Both the college friends and swimming kids have “friended” her. She was horrified to discover that these two worlds had inadvertently become linked though her social networking account.

This is the “Facebook problem”. The assumption that all relationships are equivalent was good enough for college dorms but doesn’t really scale to the rest of the world, hence Google+. As Adams points out,

Facebook itself is not the problem here. The problem here is that these are different parts of Debbie’s life that would never have been exposed to each other offline were linked online.

Like most users, Debbie wasn’t thinking of the bigger picture when she bound the whole of her life together. She was just connecting to people she knew and commenting on some pictures of guys with cute buns.

Simile alert!

Let’s revisit the right-hand side of that illustration.

This is Nat‘s diagram for the Ports and Adapters pattern. It illustrates how some people (including us) think system components should be built, with the domain logic in the centre protected from the accidental complexity of the outside world by a layer of adapters. I do not want to have my web code inadvertently linked directly to my persistence code (or even connected to LA gay bars).

That’s the trouble with the use of DI frameworks in systems that I’ve seen, there’s only one level of relationship: get me an object from the container. When I’m adding a feature, I just want to get hold of some component—and here’s an easy way to do it. It takes a lot of rigour to step back at every access to consider whether I’m introducing a subtle link between components that really shouldn’t know about each other.

I know that most of the frameworks support managing different contexts but it seems that, frankly, that’s more thinking and organisation than most teams have time for at the beginning of a project. As for cleaning up after the fact, well it’s a good way to make a living if the company can afford it and you like solving complex puzzles. More critical, however, is that the Ports and Adapters structure is recursive. Trying to manage the environments of multiple levels of subsystem with most current containers would be, in Keith Braithwaite‘s words, “impossible and/or insane”.

new again

The answer, I believe, is to save the DI frameworks for the real boundaries of the system, the parts which might change from installation to installation. Otherwise, I gather object assembly into specialised areas of the code where I can build up the run-time structure of the system with the deft use of constructors and new. It’ll look a bit complex but no worse than the equivalent DI structure (and everyone should learn to read code that looks like lisp).

If I later find that I can’t get access to some component that I think I need, that’s not necessarily a bad thing. It’s telling me that I’m introducing a new dependency and sometimes that’s a hint that a component is in the wrong place, or that I’m trying to use it from the wrong place. The coding bump is a design feedback mechanism that I miss when I can just pull objects out of a container. If I do a good job, I should find that, most of the time, I have just the right components at the time that I need them.

Test-Driven Development and Embracing Failure

At the last London XpDay, some teams talked about their “post-XP” approach. In particular, they don’t do much Test-Driven Development because they find it’s not worth the effort. I visited one of them, Forward, and saw how they’d partitioned their system into composable actors, each of which was small enough to fit into a couple of screens of Ruby. They release new code to a single server in their farm, watching the traffic statistics that result. If it’s successful, they carefully propagate it out to the rest of the farm. If not, they pull it and try something else. In their world, the improvement in traffic statistics, the end benefit of the feature, is what they look for, not the implemented functionality.

I think this fits into Dave Snowden’s Cynefin framework, where he distinguishes between the ordered and unordered domains. In the ordered domain, causes lead to effects. This might be difficult to see and require an expert to interpret, but essentially we expect to see the same results when we repeat an action. In the complex, unordered domain, there is no such promise. For example, we know that flocking birds are driven by three simple rules but we can’t predict exactly where a flock will go next. Groups of people are even more complex, as conscious individuals can change the structure of a system whilst being part of it. We need different techniques for working with ordered and unordered systems, as anyone who’s tried to impose order on a gang of unruly programmers will know.

Loosely, we use rules and expert knowledge for ordered systems, the appropriate actions can be decided from outside the system. Much of the software we’re commissioned to build is about lowering the cost of expertise by encoding human decision-making. This works for, say ticket processing, but is problematic for complex domains where the result of an action is literally unknowable. There, the best we can do to influence a system is to try probing it and be prepared to respond quickly to whatever happens. Joseph Pelrine uses the example of a house party—a good host knows when to introduce people, when to top up the drinks, and when to rescue someone from that awful bore from IT. A party where everyone is instructed to re-enact all the moves from last time is unlikely to be equally successful1. Online start-ups are another example of operating in a complex environment: the Internet. Nobody really knows what all those people will do, so the best option is to act, to ship something, and then respond as the behaviour becomes clearer.

Snowden distinguishes between “fail-safe” and “safe-fail” initiatives. We use use fail-safe techniques for ordered systems because we know what’s supposed to happen and it’s more effective to get things right—we want a build system that just works. We use safe-fail techniques for unordered systems because the best we can do is to try different actions, none of which is large enough to damage the system, until we find something that takes us in the right direction—with a room full of excitable children we might try playing a video to see if it calms them down.

At the technical level, Test-Driven Development is largely fail-safe. It allows us, amongst other benefits, to develop code that just works (for multiple meanings of “work”). We take a little extra time around the writing of the code, which more than pays back within the larger development cycle. At higher levels, TDD can support safe-fail development because it lowers the cost of changing our mind later. This allows us to take an interim decision now about which small feature to implement next or which design to choose. We can afford to revisit it later when we’ve seen the result without crashing the whole project.

Continuous deployment environments such as at Forward2, on the other hand, emphasize “safe-fail”. The system is partitioned up so that no individual change can damage it, and the feedback loop is tight enough that the team can detect and respond to changes very quickly. That said, even the niftiest lean start-up will have fail-safe elements too, a sustained network failure or a data breach could be the end of the company. Start-ups that fail to understand this end up teetering on the edge of disaster.

We’ve learned a lot over the last ten years about how to tune our development practices. Test-Driven Development is no more “over” than Object-Orientation is, it’s just that we understand better how to apply it. I think our early understanding was coloured by the fact that the original eXtreme Programming project, C3, was payroll, an ordered system; I don’t want my pay cheque worked out by trying some numbers and seeing who complains3. We learned to Embrace Change, that it’s a sign of a healthy development environment rather than a problem. As we’ve expanded into less predictable domains, we’re also learning to Embrace Failure.



1) this is a pretty good description of many “Best Practice” initiatives
2) Fred George has been documenting safe-fail in the organisation of his development group too, he calls it “Programmer Anarchy
3) although I’ve seen shops that come close to this

Speaking and tuting at QCon London. 7-11 March

Speaking at QCon London 2011 Nat and I will be running our “TDD at the System Scale” tutorial at QCon London. Sign up soon.

I’ll also be presenting an engaging rant on why we should aspire to living and working in a world where stuff just works.

If you quote the promotion code FREE100 when you sign up, QCon will give you a discount of £100 and the same amount to Crisis Charity.

What are we being primed for?

The excellent BBC popular science programme Bang Goes the Theory, recently reproduced this experiment on priming. In the original experiment, the subjects were primed by being asked to write sentences based on sets of words: one set was neutral and the other contained words related to an elderly sterotype. The result was that

participants for whom an elderly stereotype was primed walked more slowly down the hallway when leaving the experiment than did control participants, consistent with the content of that stereotype.

In the “Bang” experiment, they took two queues of people entering the Science Museum and placed pictures of the elderly and infirm around one queue, and the young and active around the other. The result was the same, people in the queue with the elderly images took significantly longer to walk into the building.

It’s striking that such a small thing can affect how we behave.

Now, look around your work environment and consider what it’s priming you for. Are you seeing artefacts of purpose and effectiveness? Or does it speak of regimentation and decay? Now look at your computer screen. Are you seeing an environment that emphasises productivity and quality? Or does it speak of control and ugliness?

It’s amazing that some of us get anything done at all.

This isn’t about spending lots of money to look nice (although that espresso machine is appreciated). I suspect that the sort of “funky, creative” offices that get commissioned from designers dressed in black are usually an upmarket version of motivational posters.

My guess is that a truly productive environment must have some “authenticity” for the people who spend most of their days in it. Most geeks I know would be happy with a trestle-table provided they get to spend the difference on a good chair and powerful kit, and other disciplines might have other priorities.

But then, perhaps every environment is authentic since the organisation is making clear what it really values most. And what might that imply?…

Bad code isn’t Technical Debt, it’s an unhedged Call Option

I’d been meaning to write this up for a while, and now Nat Pryce has written up the 140 character version.

Payoff from writing a call.

This is all Chris Matts‘ idea. He realised that the problem with the “Technical Debt” metaphor is that for managers debt can be a good thing. Executives can be required to take on more debt because it makes the finances work better, it might even be encouraged by tax breaks. This is not the same debt as your personal credit card. Chris came up with a better metaphor, the Call Option.

I “write” a Call Option when I sell someone the right, but not the obligation, to buy in the future an agreed quantity of something at an price that is fixed now. So, for a payment now, I agree to sell you 10,000 chocolate santas1 at 56 pence each, at any time up to 10th December. You’re prepared to pay the premium because you want to know that you’ll have santas in your stores at a price you can sell.

From my side, if the price of the santas stays low, I get to keep your payment and I’m ahead. But, I also run the risk of having to provide these santas when the price has rocketed to 72 pence. I can protect myself by making arrangements with another party to acquire them at 56 pence or less, or by actually having them in stock. Or, I can take a chance and just collect the premium. This is called an unhedged, or “Naked”, Call. In the financial world this is risky because it has unlimited downside, I have to supply the santas whatever they cost me to provide.

Call options are a better model than debt for cruddy code (without tests) because they capture the unpredictability of what we do. If I slap in an a feature without cleaning up then I get the benefit immediately, I collect the premium. If I never see that code again, then I’m ahead and, in retrospect, it would have been foolish to have spent time cleaning it up.

On the other hand, if a radical new feature comes in that I have to do, all those quick fixes suddenly become very expensive to work with. Examples I’ve seen are a big new client that requires a port to a different platform, or a new regulatory requirement that needs a new report. I get equivalent problems if there’s a failure I have to interpret and fix just before a deadline, or the team members turn over completely and no-one remembers the tacit knowledge that helps the code make sense. The market has moved away from where I thought it was going to be and my option has been called.

Even if it is more expensive to do things cleanly (and I’m not convinced of that beyond a two-week horizon), it’s also less risky. A messy system is full of unhedged calls, each of which can cost an unpredictable amount should they ever be exercised. We’ve all seen what this can do in the financial markets, and the scary thing is that failure, if it comes, can be sudden—everything is fine until it isn’t. I’ve seen a few systems which are just too hard to change to keep up with the competition and the owners are in real trouble.

So that makes refactoring like buying an option too. I pay a premium now so that I have more choices about where I might take the code later. This is a mundane and obvious activity in many aspects of business—although not, it seems, software development. I don’t need to spend this money if I know exactly what will happen, if I have perfect knowledge of the relevant parts of the future, but I don’t recall when I last saw this happen.

So, the next time you have to deal with implausible delivery dates, don’t talk about Technical Debt. Debt is predictable and can be managed, it’s just another tool. Try talking about an Unhedged Call. Now all we need is a way to price Code Smells.



1) There is an apocryphal story about a trader buying chocolate santa futures and forgetting to sell them on. Eventually a truckload turned up at the Wall Street headquarters.

Machiavelli on code quality

As the doctors say of a wasting disease, to start with, it is easy to cure but difficult to diagnose. After a time, unless it has been diagnosed and treated at the outset, it becomes easy to diagnose but difficult to cure.

— Nicolo Machiavelli, The Prince

via Dee Hock, Birth of the Chaordic Age