Facets of Logging

I was debugging a ‘fun’ issue recently – a test that failed if you ran it through the CI test runner rather than running it through Visual Studio, even on the same machine. Solving it necessitated giving up on the interactive debugger and falling back to old school print statements. As I was adding yet more print statements to the code to narrow in on the problem, I started thinking about the kind of information I was logging and realized there were two basic kinds of information being logged as well as a third kind of information that was created by the logs as a whole.

The first kind of information is about where the execution is in the program. Did it execute the if or the else? Did execution reach line 68? The simplest most rudimentary logging statements fall into this category. They are essentially a fixed string output at some point in the program. A stack trace is a special sort of log data since it not only tells you where you are, it also tells you some information on how you got there. These types of logs can still have lots of value if you have no other insight into the activity of the program, but are generally a smaller component of  more valuable sorts of logs.

The second kind of information was program state; x=3 etc. This is fairly straightforward, since each variable has some value at this point. This encapsulates the information from the first kind of logging under most circumstances, but if the program has multiple places that could log the same output, then this doesn’t give you full information on “where.”

The third kind of information is the programmatic flow. A then B then C. It isn’t a single log statement but the combination of them in order. At first “ordered” seems like a given for a log – A happened then B happened then C happened – but in a multithreaded world chronologically A may have happened after B but been logged first. Knowing which thread/request a log came from is valuable as it can also help to untangle the mess you are getting into. Each operation can be looked at as an independent log if they were truly working in parallel and not communicating with each other.

In my case I managed to track the behavior of the application via the logs, with thread IDs. It showed that most of the threads were processing correctly, but one of them was failing to find a configuration file it needed. The interleaving of the messages in the log without the thread IDs made it more difficult to figure out which thread was failing and track back the missing resource.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s