man cutting tress using chainsaw

The Java world had an… interesting weekend when security researchers revealed on December 9 a vulnerability in the popular Apache Log4j 2 software library for recording and debugging events. Systems as diverse as Amazon Web Services, Apple iCloud, and the Minecraft video game could be exploited to run arbitrary code on a server merely by sending a specially-​crafted string of text. Information technology professionals have been scrambling ever since the initial disclosure to patch, upgrade, reconfigure, or otherwise protect affected servers. It’s bad, and past unpatched vulnerabilities like this have been responsible for the exposure of millions of people’s sensitive data.

Many Perl applications use the similarly-​named and ‑designed Log::Log4perl library, and the good news is that as far as I can tell the latter doesn’t suffer from the type of vulnerability described above. This doesn’t mean poorly-​written or ‑configured Perl-​based systems are immune to all exploits, just this particular one. You should be safe to continue using Log4perl unless someone has deliberately configured it otherwise, and in fact, my work uses it extensively.

You might be surprised to read me suggesting a logging framework after writing multiple articles espousing the Perl step debugger as an alternative. Log4perl developer Mike Schilli’s 2002 introduction to the package for Perl.com came down on the opposite side of the argument. It can seem like one of those programmer religious issues like tabs vs. spaces, vim vs. Emacs, or Linux vs. Windows. (For the record, the correct answers are spaces, BBEdit, and macOS. 😉)

But in this case, you can and should have the best of both worlds—logging at different levels to appropriate destinations while still dropping into the interactive debugger when you need to do something trickier like examine program state or tweak a data structure on the fly. I use both techniques and only emphasize the advocacy of step debugging because it’s understood less.

In March I wrote The Perl debugger can be your superpower, introducing the step debugger as a better way to debug your Perl code rather than littering your source with temporary print statements or logging. I use the debugger all the time, and I’ve realized that some more techniques are worth covering.

Although I mentioned a caveat when debugging web applications, our apps at work all adhere to the Perl Web Server Gateway Interface (PSGI) specification and thus we can use tools like Test::WWW::Mechanize::PSGI or Plack::Test to run tests and debugging sessions in the same Perl process. (Mojolicious users can use something like Test::Mojo for the same effect.)

To demonstrate, let’s get started with something like this which tests that a given route (/say-hello) returns a certain JSON structure ({"message": "Hello world!"}):

#!/usr/bin/env perl

use Test::Most;
use Test::WWW::Mechanize::PSGI;
use JSON::MaybeXS;
use Local::MyApp; # name of app's main module

my $mech = Test::WWW::Mechanize::PSGI->new(
    # a Dancer2 app, so to_app returns a PSGI coderef
    app => Local::MyApp->to_app(),
);
$mech->get_ok('/say-hello');
lives_and {
    my $json = decode_json($mech->content);
    cmp_deeply( $json, {message => 'Hello world!'} );
} 'message is Hello world!';

done_testing;

All very fine and well, but what happens if that route starts returning a different message or worse, invalid output that causes decode_json to fail? Eventually, you’ll rewrite the test in the script to output the offending content when something goes wrong, but right now you want to suss out the root cause.

Debuggers have the concept of breakpoints, which are flags that tell the debugger to stop at a certain line of code and wait for instructions. We can set them while running the debugger with the b command or continue to a one-​time breakpoint with the c command, or we can insert them into the code ourselves before running it through the debugger in the first place.

Add this line right after the lives_and { line:

$DB::single = 1;

This simulates having typed the s command in the debugger at that line, stopping execution at that point. Run our test with perl’s -d option, and then type c to continue to that breakpoint:

$ perl -d -Ilib t/test_psgi.t

Loading DB routines from perl5db.pl version 1.60
Editor support available.

Enter h or 'h h' for help, or 'man perldebug' for more help.

[Local::MyApp:7170] core @2021-07-06 07:33:22> Built config from files: /Users/mgardner/Projects/blog/myapp/config.yml /Users/mgardner/Projects/blog/myapp/environments/development.yml in (eval 310)[/Users/mgardner/.plenv/versions/5.34.0/lib/perl5/site_perl/5.34.0/Sub/Quote.pm:3] l. 910
Test2::API::CODE(0x7ffabea39ee8)(/Users/mgardner/.plenv/versions/5.34.0/lib/perl5/site_perl/5.34.0/Test2/API.pm:71):
71:	    INIT { eval 'END { test2_set_is_end() }; 1' or die $@ }

  DB<1> c

[...]
ok 1 - GET /say-hello
main::CODE(0x7f8069caf2c8)(t/test_psgi.t:14):
15:	    my $json = decode_json($mech->content);

  DB<1> 

From here we can examine variables, set other breakpoints, or even execute arbitrary lines of code. Let’s see what became of that HTTP GET request:

  DB<1> x $mech->content

0  '{"error":"Undefined subroutine &Local::MyApp::build_frog called at lib/Local/MyApp.pm line 11.\\n"}'

  DB<2> 

Aha, something has returned some different JSON indicating an error. Let’s look at the lines around (1020) the offending line (11):

  DB<2> f lib/Local/MyApp.pm

  DB<3> l 10-20

10:	        my $method = 'build_frog';
11:	        $method->();
12 	    }
13:	    catch ($e) {
14:	        send_as JSON => {error => $e};
15 	    }
16:	    send_as JSON => {message => 'Hello world!'};
17:	};
18
19 	sub build_frob {
20:	    return;

  DB<4>

Yep, a typo on line 11, and one that wasn’t caught at compile time since it’s generated at runtime.

Just to be sure (and to demonstrate some other cool debugger features), let’s set another breakpoint while in the debugger and then exercise that route again. Then we’ll check that $method variable against the list of available methods in the Local::MyApp package.

  DB<4> b 11

  DB<5> $mech->get('/say-hello')

[...]
Local::MyApp::CODE(0x7f8066f2db60)(lib/Local/MyApp.pm:11):
11:	        $method->();

  DB<<6>> x $method

0  'build_frog'

  DB<<7>> m Local::MyApp
any
app
body_parameters
build_frob
captures
config
content
[...]
  DB<<8>>

No doubt about it, that variable is being set incorrectly.

Quit out of the debugger with the q command, make the fix (we probably want errors to give something other than an HTTP 200 OK while we’re at it), and re-​run the test:

$ perl -Ilib t/test_psgi.t

[Local::MyApp:8277] core @2021-07-06 07:48:36> Built config from files: /Users/mgardner/Projects/blog/myapp/config.yml /Users/mgardner/Projects/blog/myapp/environments/development.yml in (eval 309) l. 910
Name "DB::single" used only once: possible typo at t/test_psgi.t line 13.
[...]
ok 1 - GET /say-hello
ok 2 - message is Hello world!
1..2

Note that warning about leaving $DB::single in there. While harmless, it’s a good reminder to remove such lines from your code so that they don’t surprise you or your teammates during future debugging sessions.

And that’s it. Note that because we’re using PSGI, we were able to set breakpoints in our web app code itself and the debugger stopped there and enabled us to have a look around. And as you’ve seen, once you’re at a breakpoint you can switch to different files, add/​remove more breakpoints, run arbitrary code, and more. The perldebug documentation page has all the details.

Happy debugging! For your reference, here’s the full app module and test script used in this article:

MyApp.pm

package Local::MyApp;
use Dancer2;
use Feature::Compat::Try;

our $VERSION = '0.1';

get '/say-hello' => sub {
    try {
        no strict 'refs';
        my $method = 'build_frob';
        $method->();
    }
    catch ($e) {
        status 'error';
        send_as JSON => {error => $e};
    }
    send_as JSON => {message => 'Hello world!'};
};

sub build_frob {
    return;
}

true;

test_psgi.t

#!/usr/bin/env perl

use Test::Most;
use Test::WWW::Mechanize::PSGI;
use JSON::MaybeXS;
use Local::MyApp; # name of your app's main module goes here

my $mech = Test::WWW::Mechanize::PSGI->new(
    # a Dancer2 app, so to_app returns a PSGI coderef
    app => Local::MyApp->to_app(),
);
$mech->get_ok('/say-hello');
lives_and {
    my $json = decode_json($mech->content);
    cmp_deeply( $json, {message => 'Hello world!'} );
} 'message is Hello world!';

done_testing;

brave doctor in flying superhero cape with fist stretched

We’ve all been there: Deep in the bowels of a program, trying to figure out why something’s not working right. 

Maybe a variable isn’t getting the right value. Maybe a function or method isn’t getting called or has the wrong arguments. Maybe we don’t even know if a line of code is being reached.

So what do we do? We litter our code with print statements or logging. Got value.” Calling foo with x.” Reached line 42.”

And then we have to make sure to clean it all out, lest these informal clues make their way to production and the eyes of users.

There’s a better way

What if I told you that you could freeze time in the middle of your program and examine all these details while they happen, or even before they happen? That you could be alerted when variables or expressions changed and immediately dive in to see the cause? That you could even run exploratory test code and play what if” scenarios?

All of this is possible with a debugger, and Perl has one built-​in. Run your program with perl -d, and after a slight delay you’re presented with a new command line prompt:

% perl -d hello.pl

Loading DB routines from perl5db.pl version 1.57
Editor support available.

Enter h or 'h h' for help, or 'man perldebug' for more help.

main::(hello.pl:7):	say 'Hello world!';
  DB<1> 

Before you go any further, you might want to know how to exit the debugger. Just type q and then press Enter and you’ll be back at your normal command line.

Perl also comes with a good (if incomplete) tutorial on using the debugger, and I suggest you work through that to familiarize yourself. It will tell you how to get help, list and view variables and lines of code, set breakpoints, and step through line by line.

And then there’s the full manual, where you can learn how to do things like getting a stack backtrace of all calls leading up to the current line.

My favorite debugging trick

By far my favorite thing to do with the debugger is to run it against test scripts using the prove command. This takes advantage of proves ability to run an arbitrary interpreter through its test harness. Run it like this:

% prove --verbose --lib --exec 'perl -Ilib -d' t/foo.t

…and you’ll be able to step through the test script at t/foo.t, loading any necessary modules from the lib directory, getting verbose test output along the way.

This is extremely helpful when paired with modules like Test::Mojo, which can load Mojolicious web application classes and then exercise them using its own user agent. (You can do similar things with other PSGI applications using Plack::Test.)

A caveat

If you’re debugging and testing your applications strictly through network requests to another process, such as through Test::WWW::Mechanize, running the debugger will only show you the client-​side of things and not allow you to step through execution of the server side. This is especially prevalent among legacy apps not using the PSGI protocol. If you’re using Apache mod_​perl have a look at Apache::DB, which enables you to run the Apache httpd web server with the interactive debugger.

So what’s your superpower?

A debugger is a common feature in many languages and development environments, and Perl has had one for decades. Yet I’m constantly surprised that more developers don’t know about or don’t use this powerful tool that can cut through the add prints/​run/​stop/​add more prints/​run” cycle.

How can you integrate the Perl debugger into your programming workflow? Leave me a message in the comments and let me know.

beetle on green leaf

I spent this week debugging an issue with an internal web tool that our company’s support team relies upon to pull up information about our customers, making changes on their behalf to their subscriptions of the various packages and services that we offer. Trying to view one particular customer — one! — would always crash the application, leaving an unhelpful message that said, Internal Server Error: Please contact the server administrator. More information about this error may be available in the server error log.” Unfortunately, there was only a single line in the log, Error 500,” which only indicated that yes, an error had happened on the server. No details from the application.

Luckily, this application was written in Perl, an expressive programming language with a rich ecosystem of open-​source libraries. It also has a built-​in debugger mode that can run your program step by step, line by line. Any program that can be run from the text command line can be paused, have its variables and objects examined, new code interactively entered, and then continue its execution as if nothing had happened.

However, this was a web application that assumed it was running in a web server environment, and the customer’s information was in our production database, safe from prying eyes (including curious developers like me) due to financial compliance rules. I could not simply run this program on my desktop and reproduce the problem with this one customer — I had to somehow tease out more information from a running system and report it back using the only tool available: the server error log mentioned above.

But still, the Perl debugger approach was appealing. Could I somehow get the application to log each line of code as it was executed? Could I then see what was running the moment before it crashed, the offending line printed in the log like a smoking gun that had just murdered its victim? And assuming that the problem was in our code and not in the millions of lines of third-​party code it depended upon, could I filter out all the noise?

The answer, thankfully, was yes; since the debugger itself is written in Perl and designed to be extended or replaced, I could add code at the beginning of our application that intercepted each line as it was run, throw out anything that came from a file outside of our application’s directory folder, and then report the rest (along with helpful line numbers) to the error log. Then turn on the debug” switch on the web server running the application, and voilà, the log would dutifully fill up with (slower, more memory-​consuming) code reported by the debugger.

We set up our staging server to use the branch of code with debugging enabled, and then instructed the application to display the problematic customer’s records. As expected, the error log immediately began filling up with line after line of our application’s code and then bang, crashed right after issuing a particular database query for services tied to the account. I had my smoking gun! After extracting the query and running it on a redacted copy of our database, I found that it was returning some 1.9 million rows of data as it retrieved provisioning, billing, and renewal history for every service owned by the customer. This was far too many than necessary — the application only cares about current status, and it was running out of memory as it created service objects for each row.

The database expert on my team was able to adjust the query to return only current information, and after a quick test on the redacted database, the change is now waiting for quality assurance testing before launching to our production servers. The debugging code branch will be saved until it’s needed again, and our team was once again grateful that we were working in such a powerful programming language as Perl.