Almost 16 years ago when I started working on GSM billing systems I came across a piece of C code that had a comment written in German. I turned to my Dutch colleague and asked whether he could assist with a basic translation of the comment. His response was “I don’t know what this code does or how it works”. My immediate reaction was “Just tell me what the comment is saying”. He laughed and said “That was the translation!”.
I suspect my conservative approach to logging, and to some extent inline code commentary, has been tainted by this event. Logging, the way I have seen it applied, has always seemed like commentary that a developer wanted to echo back by way of an expensive file write. And much like the comment in my short dialogue, written in a different language to the code itself, and a reflection of what the developer thought the code did rather than what it really did, which in this case was not entirely understood.
A good few years later when I was called into a bank to help identify a performance issue with a particular transaction I was reminded of this first encounter with logging as a form of fiction writing. During the course of the performance investigation the problem was found in a different transaction than had been indicated. It was in someway similiar to the one that had been identified by operations but not the same. The initial reaction to my findings when presented to management was that my performance monitoring product was broken (the joys of performance consultancy). When asked how they had come to associate the performance problem with a different transaction the response was “It is written in the log file.”. Instead of asking to see the code for the other “problem transaction” I instead asked for the code related to the transaction I had identified. There in the code was a log statement that looked to have been directly copied over from the other transaction without any change in the labeling. A similar issue recently occurred as a result of a log statement causing misclassification of a transaction label via the stringifying (Object.toString) of state prior to the proper setup and execution of a transaction. In this case we did not have to look at the code because our metering change set showed clearly that the behavior logged was incorrect .
Here are a few observations I’ve made over the years which I believe contribute to the disconnect that can occur between what a log file says occurred and what actually happened.