Logging: Test tool and system under test in one

James Bach brings up the logging in a system as a tool for the exploratory tester. I really like this, and am going to see if I can straighten out his list to fit my specific project and situation. I have been thinking about this some time now, but mostly about the information within the log entries, and not the logging mechanism itself.

The system I am testing at the moment has extensive logging features, or at least it logs very many things at multiple levels. I use the logging sort of like he mentions, but not relying as extensively on it as it sounds in his post. The system is pretty straightforward relying on one input that creates one single output. Apart from that, there is only logging and status management to keep track of events.

In our case, when testing a part of the system and keeping my eyes on the logging, it struck me that there was a line “check that x has not failed”. This line was very common to see, since it was logged for every event created successfully. But thinking about it, was this entry a useful entry? NO! In my case it was so obvious that none of the developers had been thinking about it, but it was an horrible entry. Why? One of our statuses for events was “FAILED”. So if an event would fail, the obvious thing is to grep for this word in the logs. But having every successful event instance log the word failed would be devastating for any operator trying to find the cause of a failet event.

So what I would like to extend in James’ list, is that of bullet 5″- Event type description: short, unique human readable label” and “- Event information: any data associated with the event that may be useful for customer service or assessing test coverage, this data may be formatted in ways specific to that event type.”

I want to point out the value and importance of having these string fields not interfere between different types of log entries. Like my example above, keeping the word ‘Failed’ away from any successful events at all times is crucial. The problem is that it is so easy to get it wrong. Developers need to think about this when coding, and not only log what the code does, but create the human readable log entry consistent from the user/operator perspective. If something is successful, it does not matter that the code is “checkJobNotFailed(job)”, but the logged entry should verify the success.

Other types of risks with the logging content is of course that of usernames and passwords. If this type of information is logged in a readable way at any logging level, the log files must be handled according to the security policy of this information.

I have made two examples to point out less good logging events. So, what more examples of “good vs bad” log entries are there? Remember that I am not talking about the logging mechanism and its’ good and bad practices like the ones presented by James, but the content of the event entry messages.

Please enlighten me with more input.