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.