The Evolution of the Lowly Debug Statement
Or how I learned to stop worrying
and love my debug statements.

I use to think that debug statements were ugly. I looked forward to deleting them from my code so that I could reveal the assignments and method calls between them for their simple elegance as was intended. I've come to understand though that a debug statement is merely a step along the way of the continuous refactoring required to build and maintain robust code. This is a brief story about how I learned to stop worrying and to love my debug statements.

First a brief example I hope might serve to demonstrate a number of points in this meditation:

#!/usr/bin/perl -w use strict; use Carp qw/FatalsToBrowser/; my $obj = MyPackage->new(); my $argument = "Here is a scalar."; print $argument,"\n"; my $result = $obj->method($argument); print "My argument still is: $argument. \n"; print "My \$result is now $result.\n"; 1;

That code might get exercised for hours or days as I develop the object->method() to act on my argument and return my result. Eventually I begin to notice that some $result's suggest some sanity checks that contribute to the robustness of later parts of the code.

Robustness refers to the resilence of code, to its capacity to handle the useless data that real world users throw at it, while protecting the integrity o its data and still guiding its user to accomplish the task it was designed to facilitate.

Earlier this year I was working with a coding partner on a cgi application. I was churning out code to accomplish the client's requirements. My partner was writing tests to break my work.

During one of our phone calls, in a frustrated moment, he said to me: "The error path is as important as the path that gets the work done."

I was churning on the "prototype it quick, show the client, get early feedback" development paradigm. I wanted to see it work, even if I had to hold the user's hand and warn them against doing things that would break the code.

One of my early mentors in my development as a programmer had a version of tourettes syndrome that oddly only affected his debug messages. He would create code that looked like this:

my $result = $obj->method($argument); print "My <explicative deleted> argument still is: $argument. \n"; if($result eq 'ERROR') { print STDERR qw|!@#$%^&*(*&^$#$, still broken.|; } else { print STDERR "Yeah! It worked."; }
Working with his code, I would search the script for the latest explicative to show up in the logs. And then have to study the code itself to get some sense of why an error was thrown.

As I would do this and deconstruct the meaning of the error messages, I took it upon myself to rewrite his messages in a way which would mean something to and hopefully not offend a real user. Pronouns were replaced with their antecedants. His explicatives were substituted with more descriptive, if less colorful language.

Now, as my code develops over time, quick and dirty debug statements begin to evolve. They get rewritten and perhaps send to the logs. My routine begins to look more like this:

#!/usr/bin/perl -w use strict; use Carp qw/FatalsToBrowser/; . . . my $obj = MyPackage->new(); my $argument = "Here is a scalar."; print $argument,"\n"; my $result = $obj->method($argument); if($verbosity eq "DEBUG"){ print LOG "My argument still is: $argument. \n"; print LOG "My \$result is now $result.\n"; } if($result eq 'ERROR') { print LOG qw|The \$obj->method() is returning an error, it is still +broken.|; } else { print STDERR "The \$obj->method() ran without errors."; } 1;
I used to think that a series of calls to object methods unadorned by ugly debug statements made for the prettiest code. It looks great on the screen, with short lines that don't wrap and an easy to follow logic. But if I'm not sitting with my user to warn them against trying unsupported actions with my code, it probably makes sense to mess up my programs with conditionals that test return values and guide my users along to success in my absence.

I used to write simple conditionals like:

if($test) { $obj->method(); }
Now I'm more likely to write something like this:

if($test) { print LOG "The test was successful, now invoking \$obj->method()."; $obj->method(); } else { print LOG "The test was unsuccessful, so we won't invoke the \$obj-> +method()."; }
In fact, I've cultivated the habit of closing braces and parentheses before filling them in. A new conditional is likely to look like this, at first brush:

if(){ } else { }
I then return to the if line and add my conditional test between the parentheses. I'll code both paths, even if the failure path merely reports its invocation to the logs. Maybe some real work will have to be done on failure of the condition. But I want to see the failure first before I start coding around it.

By closing my braces from the start, I've had fewer syntax errors to debug. By writing an else clause for every if clause, by paying attention to the failure path as much as to the success path, my code has grown more robust.

I've seen errors that all look the same. But if there is something broken in my code and my only clue is a debug message which reads: "There has been an error.", a string used to report any of fifty different error conditions accounted for in the logic, I'll have my work cut out for me just finding the code in need of attention.

When I'm churning on the "prototype it fast" mode, I may throw in an error like: "We've encountered an error at line 35." By the time that this error gets rewritten to actually describe the nature of the error to a real human user and what that user might do to avoid the error in the future, it may no longer be on line 35, but may have shifted to line 48 or so.

But eventually I shift gears and translate. To a user, "Error code #53." or "Error on line 35." is pretty meaningless. But "Error code #53: An invalid date can not be processed by ->some_method() of MyPackage. Please use your back button to return to the form and enter a valid date before resubmitting your entries." keeps my user moving. An informative error message empowers a user to successfully use my software.

Here are some guidelines for error messages I try to code by:

I don't guess there is anything said here that is particularly Earth shattering, or that has not been said well by others, before, I'd guess. But I hope it might prove as useful to others as I have found it over this past year, as I have learned to stop worrying and to love my ugly debug statements.

-- Hugh

if( $lal && $lol ) { $life++; }

Replies are listed 'Best First'.
Re: The Evolution of the Lowly Debug Statement
by Anonymous Monk on Nov 10, 2006 at 08:12 UTC
    use Log::Log4perl qw(:easy); Log::Log4perl->easy_init($ERROR); DEBUG "This doesn't go anywhere"; ERROR "This gets logged";
Re: The Evolution of the Lowly Debug Statement
by cLive ;-) (Prior) on Nov 11, 2006 at 01:21 UTC
    You might also want to spend some time reading up on Log::Dispatch. Nice module :)
Re: The Evolution of the Lowly Debug Statement
by Anonymous Monk on Nov 10, 2006 at 10:43 UTC
    Each error message should be unique enough to uniquely identify the code which threw the error, and to permit that code to be found with a simple search for the error message itself.

    Not necessarily. One of the most common error messages is about not being able to open a file. If I can't open a file, I don't care at all where in the code the error occurs, only two things are relevant: which files was tried to be opened, and why did it fail.

    Furthermore, I think that one shouldn't bother the user with line numbers where problems occur. Line numbers are fine for debug messages, as debug messages are (mostly) for the developer. Error messages are for the user, and (s)he can give diddle twit where the error occurs. Take for instance your cell phone. If you dial a number, and you cannot connect, you expect the phone to show you the number it tried to connect to, and the reason the connection failed. You don't really care on which line of the code this error message is on.

      If all you have is the filename and reason of failure then you might spend hours trying to find out why the heck did you try to open the file at all. The unability to open a file doesn't have to be an administration problem, a permissions issue or something similar. You migth have an error somewhere in the code that generates the filename and then it might be very helpfull to be able to tell which open statement failed.

      OTOH, it may be good to display only the "basic" stuff to the user and log the details into a file. Sometimes this is not possible and then it may be fine to include information that will be useless to the user directly, but may come in handy when the user calls that he just got an error that something went wrong on some silly line 12345.

Re: The Evolution of the Lowly Debug Statement
by roboticus (Chancellor) on Nov 13, 2006 at 15:51 UTC
    hesco:

    Nice post, with some good followups. My only contribution is this:

    1) I frequently find that the debug statements make for some nice internal documentation of the code. Normally, I just comment them out when I'm done with them for the moment. (Though now that I've seen the first AnonyMonk reply, I'll have to start using that technique, instead.)

    2) I see two splits that should be made: User/Developer as well as Error/Warning/Informational messages, with differing requirements for each. A User:Error message needs to help the user remediate the problem or discover a workaround, whereas a Developer:Informational message may have numerous random bits of information. I first try to figure out which category I'm writing my message for before writing it. For User:* messages, I try to be complete without specifying details the user doesn't want or need, while for Developer:* messages I tend to be terse and laden with information I want to see.

    --roboticus

Re: The Evolution of the Lowly Debug Statement
by doom (Deacon) on Nov 16, 2006 at 05:25 UTC
    I've periodically started developing fancy debug/logging proceedures, but I find that I keep falling back on simple, semi-manual approaches like this:

    ($DEBUG) && print STDERR "The filename is $filename at line " . __LINE__ . "\n";

    Where $DEBUG is a package variable that is either set at the top of the file as an embedded constant, or is set on the command line if "-d" is used (using Getopt::Std or the like).

    I like having the ($DEBUG) at the front of each debug statement -- it's a visual reminder it's not part of the real code. Knowing what line number the message comes from is often useful, of course. Sometimes I prefix the messages with a $0 so you can see which program generated it.

    Probably the fanciest thing that I do is for some code that I've been having trouble debugging (e.g. recursively defined algorithms), I'll begin every sub with the line:

    my $sub = (caller(0))[3];
    So my debug messages can always explain which sub generated the message.

    In general though, I think techniques like this are a little cheesy, and it's usually better to think about how to use the perl debugger to solve the problem (note: this is admittedly a little harder to do with web-oriented code, but not impossible).

    Update: Someone wrote to suggest that my techniques seem to be re-inventing features in the "Carp" module, but I don't quite agree.

    Carp provides "cluck" and "confess" functions that generate full stack back traces, and these are great if you want back traces, but if you don't it clutters your debugging log tremendously.

    Carp also has an interesting feature where you can run a script like this:

    perl -MCarp=verbose script.pl
    And automatically convert your "carp"s into "cluck"s with full back traces; that might seem easier to you than hand-rolling your own debug/verbose flags, but I personally prefer having hand-crafted ones that do whatever I want them to.