When Print Debugging Fails


I have a medium sized project which is effectively a state machine. While I keep promising to write a reusable modular system which lets you specify the states and transitions between the states and let behavior manage itself, I haven't done that yet.

This means that occasionally I have to debug the transition logic.

Suppose I have a series of articles in a publication queue, and suppose each article has a state() method accessor/mutator. Moving an article between states (from SOLICIT to EDIT to PREVIEW to PUBLISHED) means calling state() and passing a token which represents the appropriate state.

Because I haven't yet consolidated all of the transitions into a single place, an article's state may change in any of half a dozen places in the entire codebase. That's not awful, but if state transitions are not occurring as I expect, that's multiple places to watch as I debug.

I rarely use the Perl debugger. (I'm a fan of debuggers for compiled languages such as C, and I've used debuggers in IDEs for languages which require IDEs to great success, but I've never found Perl's debugger productive.) I usually annotate my code with log messages and bisect problems that way.

This seemed easy today; use Moose advice to surround the state() method and display some logging information. (Shouldn't this be a pattern already? Certainly there must be something on the CPAN to accomplish this.)

around state => sub
    my ($orig, $self, @values) = @_;

    return $self->$orig() unless @values;
    my $original = $self->$orig();
    my $title    = $self->title;
    my @caller   = caller(2);

    print STDERR "Setting '$title' from $original to $values[0] " .
                 "from $caller[1]:$caller[2]\n";

If you already see the bug, you're doing better than I am today. After five minutes of head scratching, and looking elsewhere, I figured out why my logs showed the first transition happening successfully but nothing else happened.

The moral of the story is to be very careful what you measure, lest you change that which you observe... or in my case, fail to allow that change to occur.


Are you using @values in your call to $orig() ? It doesn't appear that you are, and I imagine that you should be.

Exactly the problem. I forgot to call the mutator.

Modern Perl: The Book

cover image for Modern Perl: the book

The best Perl Programmers read Modern Perl: The Book.

affiliated with Modern Perl Whitepapers



About this Entry

This page contains a single entry by chromatic published on December 15, 2011 3:37 PM.

If We Could Resolve Predicates at Compile Time was the previous entry in this blog.

How Would You Track User Behavior with Plack and Catalyst? is the next entry in this blog.

Find recent content on the main index or look in the archives to find all content.

Powered by the Perl programming language

what is programming?