Chapter 21. Error Handling and Debugging

21.1.1. The Importance of Warnings

• There is no added value in having the same warning showing up, again and again, triggered by thousands of script invocations. If your code isn't very clean and generates even a single warning per script invocation, on the heavily loaded server you will end up with a huge error_log file in a short time.

  The warning-elimination phase is supposed to be a part of the development process and should be done before the code goes live.

• In any Perl script, not just under mod_perl, enabling runtime warnings has a performance impact.

mod_perl provides a very simple solution to handling warnings, so you should avoid enabling warnings in the scripts themselves unless you really have to. Let mod_perl control this mode globally. All you need to do is put the directive:

PerlWarn On

in httpd.conf on your development machine and the directive:

PerlWarn Off

on the live machine.

{
    local $^W = 0;
    # some code that generates innocuous warnings
}

{
    no warnings;
    # some code that generates innocuous warnings
}

The diagnostics pragma can shed more light on errors and warnings, as we will see in the following sections.

21.1.2. Curing "Internal Server Error" Problems

Figure 21-1. Internal Server Error

How can you find out what the problem is, before you actually attempt to solve it?

The first problem is determining the location of the error message.

You have been coding in Perl for years, and whenever an error occurred in the past it was displayed in the same terminal window from which you started the script. But when you work with a web server, the errors do not show up in a terminal. In many cases, the server has no terminal to which to send the error messages.

ErrorLog logs/error_log

where logs/error_log is appended to the value of the ServerRoot directive.

If you've followed the convention we've used in this book and your ServerRoot is:

ServerRoot /home/httpd/httpd_perl

the full path to the file will be /home/httpd/httpd_perl/logs/error_log.

Whenever you see "Internal Server Error" in a browser it's time to look at this file.

Apache/1.3.24 (Unix) mod_perl/1.26 configured

won't appear in the error_log file. Also, any startup warnings will be printed to the console, since in this mode the server redirects its STDERR stream to the error_log file only at a later stage.

The first problem is solved: we know where the error messages are.

The usefulness of the error message depends to some extent on the programmer's coding style. An uninformative message might not help you spot and fix the error.

For example, let's take a function that opens a file passed to it as a parameter for reading. It does nothing else with the file. Here's the first version of the code:

my $r = shift;
$r->send_http_header('text/plain');

sub open_file {
    my $filename = shift;
    die "No filename passed" unless defined $filename;
    open FILE, $filename or die;
}

open_file("/tmp/test.txt");

Let's assume that /tmp/test.txt doesn't exist, so the open( ) call will fail to open the file. When we call this script from our browser, the browser returns an "Internal Server Error" message and we see the following error appended to error_log:

Died at /home/httpd/perl/test.pl line 9.

If we have only one function call, as in the example above, the task of finding the problematic filename is trivial. Now let's add one more open_file( ) function call and assume that of the two, only the file /tmp/test.txt exists:

open_file("/tmp/test.txt");
open_file("/tmp/test2.txt");

When you execute the above call, you will see:

Died at /home/httpd/perl/test.pl line 9.

Based on this error message, can you tell what file your program failed to open? Probably not. Let's improve it by showing the name of the file that failed:

sub open_file {
    my $filename = shift;
    die "No filename passed" unless defined $filename;
    open FILE, $filename or die "failed to open $filename";
}

open_file("/tmp/test2.txt");

When we execute the above code, we see:

failed to open /tmp/test2.txt at
    /home/httpd/perl/test.pl line 9.

which obviously makes a big difference, since now we know what file we failed to open.

By the way, if you append a newline to the end of the message you pass to die( ), Perl won't report the line number at which the error has happened. If you write:

open FILE, $filename or die "failed to open $filename\n";

the error message will be:

failed to open /tmp/test2.txt

which gives you very little to go on. It's very hard to debug with such uninformative error messages.

You might want to use warn( ) instead of die( ) if the failure isn't critical. Consider the following code:

if (open FILE, $filename) {
    # do something with the file
    close FILE;
}
else {
    warn "failed to open $filename";
}
# more code here...

However, unless you have a really good reason to do otherwise, you should generally die( ) when your code encounters any problem whatsoever. It can be very hard to catch a problem that manifests itself only several hundred lines after the problem was caused.

Carp::cluck( ) is assigned as a warnings signal handler. Whenever a warning is triggered, this function will be called. When we execute the script, we see:

My value is Perl
Use of uninitialized value at ./warnings.pl line 15.
  main::print_value( ) called at ./warnings.pl line 11
  main::incorrect( ) called at ./warnings.pl line 8
My value is

Take a moment to understand the stack trace in the warning. The deepest calls are printed first. So the second line tells us that the warning was triggered in print_value( ) and the third line tells us that print_value( ) was called by the subroutine incorrect( ):

script -> incorrect( ) -> print_value( )

When we look at the source code for the function incorrect( ), we see that we forgot to pass the variable to the print_value( ) function. Of course, when you write a subroutine like print_value( ), it's a good idea to check the passed arguments before starting execution. We omitted that step to contrive an easily debuggable example.

You can also call Carp::cluck( ) directly in your code, and it will produce the call-stack backtrace for you. This is usually very useful during the code development phase.

When using the warn( ) and die( ) functions, be aware of the following pitfall. Here the message passed to die( ) is printed with no problems, assuming the file /does_not_exist actually doesn't exist:

panic% perl -e 'open F, "/does_not_exist" or die "cannot open the file"'

But now try the same code using the equivalent || operator:

panic% perl -e 'open F, "/does_not_exist" || die "cannot open the file"'

Nothing happens! The pitfall lies in the precedence of the || operator. The above call is equal to:

panic% perl -e 'open F, ("/does_not_exist" || die "cannot open the file")'

where the left part returns true, and makes this call equivalent to:

panic% perl -e 'open F, "/does_not_exist"'

So the die( ) part has effectively disappeared. Make sure you always use the low-precendence logical OR operator or in this situation. Alternatively, you can use parentheses, but this is less visually appealing:

panic% perl -e 'open(F, "/does_not_exist") || die("cannot open the file")'

Only the first pair of parentheses is really needed here, but to be consistent we use them through the whole statement.

Now let's return to improving the warning and error messages. The failing code reports the names of the problematic files, but we still don't know the real reason for the failure. Let's try to improve the warn( ) example. The -r operator tests whether the file is readable:

if (-r $filename) {
    open FILE, $filename;
    # do something with file
}
else {
    warn "Couldn't open $filename - doesn't exist or is not readable";
}

Now if we cannot read the file we do not even try to open it. But we still see a warning in error_log:

Couldn't open /tmp/test.txt - doesn't exist or is not readable
at /home/httpd/perl/test.pl line 9.

The warning tells us the reason for the failure, so we don't have to go to the code and check what it was trying to do with the file.

It could be quite a coding overhead to explain all the possible failure reasons that way, but why reinvent the wheel? We already have the reason for the failure stored in the $! variable. Let's go back to the open_file( ) function:

sub open_file {
    my $filename = shift;
    die "No filename passed" unless defined $filename;
    open FILE, $filename or die "failed to open $filename: $!";
}

open_file("/tmp/test.txt");

This time, if open( ) fails we see:

failed to open /tmp/test.txt: No such file or directory
at /home/httpd/perl/test.pl line 9.

Now we have all the information we need to debug these problems: we know what line of code triggered die( ), we know what file we were trying to open, and we also know the reason, provided by Perl's $! variable.

Note that there's a big difference between the following two commonly seen bits of Perl code:

open FILE, $filename or die "Can't open $filename: $!";
open FILE, $filename or die "Can't open $filename!";

The first bit is helpful; the second is just rude. Please do your part to ease human suffering, and use the first version, not the second.

To show our useful error messages in action, let's cause an error. We'll create the file /tmp/test.txt as a different user and make sure that it isn't readable by Apache processes:

panic% touch /tmp/test.txt
panic% chmod 0600 /tmp/test.txt # -rw-------

Now when we execute the latest version of the code, we see:

failed to open /tmp/test.txt: Permission denied
at /home/httpd/perl/test.pl line 9.

Here we see a different reason: we created a file that doesn't belong to the user the server runs as (usually nobody). It does not have permission to read the file.

Now you can see that it's much easier to debug your code if you validate the return values of the system calls and properly code arguments to die( ) and warn( ) calls. The open( ) function is just one of the many system calls Perl provides.

Second problem solved: we now have useful error messages.

21.1.3. Making Use of the error_log

panic% tail -f /home/httpd/httpd_perl/logs/error_log

or less -S:

panic% less -S /home/httpd/httpd_perl/logs/error_log

You can use whichever one you prefer (the latter allows you to navigate around the file, search, etc.). This will ensure that you see all the errors and warnings as they happen.

panic% alias err "tail -f /home/httpd/httpd_perl/logs/error_log"

In a Bourne-style shell, use:

panic% alias err='tail -f /home/httpd/httpd_perl/logs/error_log'

From now on, in the shell you set the alias in, executing:

panic% err

will execute tail -f /home/httpd/httpd_perl/logs/error_log. If you are using a C-style shell, put the alias into your ~/.cshrc file or its equivalent. For setting this alias globally to all users, put it into /etc/csh.cshrc or similar. If you are using a Bourne-style shell, the corresponding files are usually ~/.bashrc and /etc/profile.

21.1.4. Displaying Errors to Users

If you set a file-upload limit to 1 MB and a user tries to upload a file bigger than the limit, it is a user error. You should report this error to the user, explain why the error has happened, and tell the user what to do to resolve the problem. Since we are talking about the Web, the error should be sent to the user's browser. A system administrator usually doesn't care about this kind of error, and therefore probably shouldn't be notified, but it may be an indication of an attempt to compromise the server, so that may be a reason to notify the administrator.

If the user has successfully uploaded a file, but the server has failed to save this file for some reason (e.g., it ran out of free disk space), the error should be logged in error_log if possible and the system administrator should be notified by email, pager, or similar means. Since the user couldn't accomplish what she was trying to do, you must tell her that the operation failed. The user probably doesn't care why the operation has failed, but she would want to know how to resolve it (e.g., in the worst case, tell her to try again later). The actual reason for the error probably shouldn't be displayed—if you do, it will probably only confuse the user. Instead, you should nicely explain that something went wrong and that the system administrator has been notified and will take care of the problem as soon as possible. If the service is very mission-critical, you probably need to provide the user with some problem tracking number and a way to contact a human, so she will be able to figure out when the problem has been resolved. Alternatively, you may want to ask for the user's email address and use this to follow up on the problem.

Some applications use:

use CGI::Carp qw(fatalsToBrowser);

eval {
    # do something
};
if ($@) {
    # decide what to do about the error stored in $@
}

which is equivalent to the C++/Java/other languages concept of:

try {
    # do something
}
catch {
    # do something about errors
}

$SIG{_ _DIE_ _} = sub {
    print STDERR "error: ", join("\n", @_), "\n";
    exit;
};

When die( ) is called, this anonymous function will be invoked and the argument list to die( ) will be forwarded to it. So if later in the code you write:

die "good bye, cruel world";

the code will print to STDERR (which under mod_perl usually ends up in error_log):

error: good bye, cruel world

and the normal program flow will be aborted, since the handler has called exit( ).

If you don't localize this setting as:

local $SIG{_ _DIE_ _} = sub {...};

it affects the whole process. It also interferes with Perl's normal exception mechanism, shown earlier; in fact, it breaks Perl's exception handling, because a signal handler will be called before you get the chance to examine $@ after calling the eval block.

You can attempt to work around this problem by checking the value of $^S, which is true when the code is running in the eval block. If you are using Apache::Registry or a similar module, the code is always executed within an eval block, so this is not a good solution.