Henrik Warne is a software developer in Stockholm, Sweden. He has been programming professionally for more than 20 years. Henrik is a DZone MVB and is not an employee of DZone and has posted 20 posts at DZone. You can read more from them at their website. View Full User Profile

Great Programmers Write Debuggable Code

05.08.2013
| 6762 views |
  • submit to reddit

All programs need some form of logging built in to them, so we can observe what it is doing. This is especially important when things go wrong. One of the differences between a great programmer and a bad programmer is that a great programmer adds logging and tools that make it easy to debug the program when things fail.

When the program works as expected, there is often no difference in the quality of the logging. However, as soon as the program fails, or you get the wrong result, you can almost immediately tell the good programmers from the bad.

Example 1: “Let’s make a debug version”

For example, a tester came to me with a call case that didn’t work. We looked at the logs, and saw that the problem seemed to be in a neighboring module. A call to the other module to get a list of values simply returned null. When we enabled logging in the neighboring module and re-ran the test case, there was no more information available. No clues to why null was returned – did we supply the wrong arguments, did some external system fail, was there an error in the neighboring module, or what?

When asking the developer responsible for the code, the answer we got was: “Oh, then we have to make a debug version to see what happens”. Fail! It must be possible to get some sense of where the problem is just from the logs. If this had been in a production system, adding a debug version would have been a lot of work. The code needs to include enough information in the log statements so you at least have some idea of why it fails.

Example 2: Show Me How We Got Here

One of our products at work finds the cheapest route for the delivery of SMS:s (text messages) to mobile phones. Depending on the current location of the phone, and the operator the destination subscriber belongs to, there are many possible routes to choose from, each with a given cost and other characteristics.  In addition, there can be exceptions that forbid some routes, and promote other routes. There are typically many thousands of routes defined. The system finds the cheapest route in each case, given the constraints, and delivers the SMS.

Now, suppose a certain SMS gets delivered using route A, but we believe it should have used route B. Why was route A chosen? If there is no logging information (other than “route A was chosen”), we are left with hundreds of possible routes, their costs, the exceptions, and a complex algorithm. Good luck figuring out why A was chosen.

In our implementation, the log includes all potential routes, in cost order. As routes are eliminated due to different restrictions, the eliminated routes are listed in the log, together with the reason for elimination. With all the information on the input to the algorithm, as well as the steps taken, listed in the log, it is fairly easy to see why a certain route was picked.

Why Not?

So, why don’t all programmers write debuggable code? I can think of three reasons:

  1. You have to be humble enough to realize that there will be cases when your code doesn’t work as expected. I believe many programmers have a hard time with this.
  2. If you test your own code thoroughly, you will make sure it works (or fails gracefully) in a lot of different scenarios. For each scenario, it is natural to add logging. If you don’t test those cases, you are less likely to add logging there.
  3. Many programmers don’t trouble-shoot their own code in production systems often enough. If you have a problem in a live system, and the logs tell you nothing about why there is a problem, you have a strong incentive to add logging that will actually help you the next time you are in a similar situation.

Is Your Code Debuggable?

There are of course cases where even good logging messages don’t give you the full story on why something fails. You may still have to make that debug version. But your regular logging should at the very least give you some hints on what the problem might be.

So, how well have you prepared? When your code fails, will the logs tell you what’s going on?

 

Published at DZone with permission of Henrik Warne, author and DZone MVB. (source)

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Tags:

Comments

Rick J. Wagner replied on Wed, 2013/05/08 - 7:03am

 Thanks, Henrik.  An important topic, we need to learn as a profession how to better identify the places where debuggable code should be placed.

Rick

Henrik Warne replied on Wed, 2013/05/08 - 7:48am in response to: Rick J. Wagner

Hi Rick,

Yes. Central points in the processing, like message dispatch or state changes, are good places to put logging statements in my experience.

Mileta Cekovic replied on Wed, 2013/05/08 - 2:45pm

In my experience most problems with exception handling and logging are because programmers are inexperienced and place it in wrong places.

However, there are simple rules that should be followed to have consistent exception handling and logging:

1) Exceptions should be caught and logged only and always on system boundaries. System boundaries would be:

- Return points from remote methods (Web Services methods, REST requests, etc...)

- Thread exits (including main thread)

- Asynchronous task executions

Failing to catch and log exception on system boundary leads to potential silent exceptions (no trace of exception within component or sub-system).

Logging exception should not happen at any other place as it would potentially lead to duplicate logging.

2) Never forget to chain root cause exception (ok, there are rare cases when this should not be done).

That's it, two simple rules and you will be able to trace into every problem.

Henrik Warne replied on Wed, 2013/05/08 - 4:18pm in response to: Mileta Cekovic

One of the best antidotes to logging the wrong things, or in the wrong places, is to trouble-shoot the system yourself. Then you quickly get a sense of what’s needed, and where.

Also, a lot of bugs don’t lead to exceptions – the logic is wrong somewhere, so you just get the wrong result. You want to be able to find and fix those problems as well.  

Lund Wolfe replied on Sun, 2013/05/12 - 3:23am

You probably don't want to have logging everywhere any more than you'd want to have defensive coding or preconditions/postconditions everywhere.

Add logging (and probably validation) at suspect locations, like data entry points and external system points and points where you are uncertain of the data/requirements/code logic.  After that, you can add logging as needed just as you'd add tests when fixing reported bugs.

Stephen Henderson replied on Wed, 2013/05/15 - 8:51am

Another very important tip for writing debug logging: never try to be funny. Ever.

Yes I'm sure that "I can haz ecception!!! oh noes!! " log seemed hilarous when you were writing it but at 3am in the morning when your entire production system is falling apart it's the most annoying thing in the universe. (especially when it's spewing out 100 times a second without any other context...).

I wish I could say this wasn't a common problem :(

Good logging is definitely a key part in produciing maintainable systems and something that's often forgotten about. In the excellent "Growing Object Oriented Software Guided By Tests"  it's even suggested to go as far as making the logging a core part of your unit tests (I've never done this personally but I'm quite keen to introduce it going ahead).

Henrik Warne replied on Wed, 2013/05/15 - 9:07am in response to: Stephen Henderson

I agree - be professional in the log messages, and provide as much information as possible to help trouble-shoot problems.

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.