Friday, December 31, 2010

Logging Token Pattern

Ok, Ok, so this is speculative as I haven't tried it yet, but hear me out.

On my last assignment with ThoughtWorks I was working with my good friend Simon Brunning. We were doing some file processing stuff that was apt to fail, if not on a complete file basis, then at least on a line by line basis.

We wanted to know what went right and what went wrong. Originally the code passed around a bunch of lists that would contain working things and failing things and exceptions (yes, the actual object) and so on.

Brunning created a customised object that tracked the progress of the file processing. It printed nice results when it finished, outlining what happened at what stage. It made the code much nicer, and the reporting much nicer.

For some reason, at the same time, I was thinking about the over abundance of log messages in your typical log, and how useless they are to the poor old Ops staff.

These two concepts gelled. Why not log the bejesus out of your process, but only print things to the log if something goes wrong.

An initial cut could be a 'transaction based' logger... 'start' a log stream, and then either 'render' if something goes wrong or 'drop' if it's all ok.

In this way the Ops team get a shite load of logs, but only if something went wrong. Surely a huge improvement? And/But the developer could put in heaps more info than they might otherwise.

The next level would be to create these custom objects that know how to talk about what they were doing and what went wrong. This would require people to think about stuff, so seems unlikely :)

Both these approaches would have to be thread based (as in: thread local variable), but the second one would have to know what sort of logging/tracking token was being updated within the current Thread. That's not easy, but Felix is up to this kind of thing.

So, given I haven't tried it, what do you think?

No comments:

Post a Comment