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.

Example 21-1. warnings.pl

#!/usr/bin/perl -w

use strict;
use Carp ( );
local $SIG{__WARN__} = \&Carp::cluck;

correct( );
incorrect( );

sub correct   { print_value("Perl"); }
sub incorrect { print_value( ); }

sub print_value {
  my $var = shift;
  print "My value is $var\n";
}

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.