Learning to use the httpd error log to debug CGI programs

This month, we will examine the error log to see what it contains, look through several errors and how they appear in the error log, and finally consider some ways in which we can use the error log to make debugging easier.
Premature Program Termination

A typical idiom in Perl might be:

open(FILE, "$filename") ||
        die "Cannot open $filename";

The above line means that $filename should be opened for reading, and that the opened file should be accessed via the descriptor named FILE. If the program cannot open the file for some reason the program should terminate, producing a message. Let's look at how that works within a CGI program:

#!/usr/local/bin/perl5 -w
  use strict;      # Check our syntax strictly
  use diagnostics; # Tell us how to fix mistakes
  use CGI;         # Import the CGI module
  # Create an instance of CGI
  my $query = new CGI;
  # Set this to a file
  my $filename = "/foo/bar/blah.txt";
  # Send the MIME header
  print $query->header("text/html");
  # Begin the HTML
  print $query->start_html(-title =>
        "Hello, world!");
  # Print the contents of $filename
  open (FILE, "$filename") ||
        die "Cannot open $filename ";
  print while (<FILE>);
  close (FILE);
  # End the HTML
  print $query->end_html();
Looks good, right? Well, the above will indeed work just fine, assuming that $filename exists. But if and when it doesn't, or if the program doesn't have permission to read the file, the second half of the statement is executed—and the program terminates, producing an error message.

If $filename doesn't exist, and you run the program from the command line, you get the following output:

Content-type: text/html
<HTML><HEAD><TITLE>Hello, world!</TITLE>
</HEAD><BODY>Uncaught exception from user code:
Cannot open /tmp/blah.txt at ./test-8.pl line 20.

But if you run it from your web browser, you get nothing at all—no error message, and no response, because the error message “Cannot open /tmp/blah.txt” was sent to stderr, rather than stdout. The error log, however, contains the following:

Uncaught exception from user code:
Cannot open /tmp/blah.txt at /home/reuven/Text/Websmith/test-8.pl line 20.
Note that the error message is inserted into the log without date or time information, since the text was sent directly by the Perl program (or by the Perl binary), rather than the web server. The web server automatically stamps its own error messages with the current time and date, but your programs don't enjoy that feature—unless, of course, you include the Carp library included with CGI.pm, which redefines the die routine, as well as several others, such that error messages are preceded by the relevant time and date. Thus, if you include the line:
use CGI::Carp;
at the top of the above program, the program still fails as expected, but your error log now contains the following entry:
[Tue Dec 3 11:55:14 1996] test-8.pl:
Cannot open /tmp/blah.txt at
/home/reuven/Text/Websmith/test-8.pl line 21.
Now we know not only what went wrong, but also when it happened. The Carp library can be very useful when debugging CGI programs, especially if you find yourself running the same program repeatedly. This way, there isn't any question whether the error occurred the first or fifth time that you ran the program, since the time at which the program ran is written right next to the error message.

Once you have installed Carp, you can use it for recording non-fatal errors, as well. For example, if you are trying to keep track of the value of a particular variable, you can include the line:

carp 'variablename = "'. $variablename . '"';

Because it includes the time and date information, this is better than:

print STDERR 'variablename = "', $variablename,
        '"';
Although using Perl's built-in syntax checkers and warnings (with the -w flag and the strict and diagnostics modules) is a great idea, realize that loading the CGI::Carp module will set off warning bells because it redefines several subroutines. You can ignore these warnings, but don't be surprised when they appear.

What About the User?

All this time, we have ignored our users, who are really supposed to be the focus of our efforts. It's all well and good that we are improving error messages for the purpose of debugging programs, but none of the ideas that we have looked at until now have done much for what the user sees.

The problem is that if you use die to output a message to the error log, the program dies off before it has a chance to produce any sort of “whoops” message for the user. If you're building an interactive web site, the last thing you want to do is present a user with a blank results page; at the very least, you should tell him that something has gone wrong, and that you are trying to fix the problem.

One easy way to do this is to replace the line:

open (FILE, "$filename") ||
        die "Cannot open $filename ";

with the following:

open (FILE, "$filename") ||
        &log_and_die ("Cannot open $filename ");
This new version opens the file as necessary, but invokes a subroutine named log_and_die, if the file cannot be opened. You can then define the subroutine as follows:
sub log_and_die
  {
        # Get arguments
        my $string = shift;
        # Begin the HTML
        print $query->start_html(-title => "Error");
        # Give a message
        print "<P>Sorry, but this program ";
        print "has encountered an error. The system ";
        print "administrator has been ";
        print "informed.</P>\n";
        print "<P>Would you like to return to the;
        print "<a href=\"/\">home page</a>?\n";
        # End the HTML
        print $query->end_html();
    # Now die with the error message
    die $string;
  }
The above routine is obviously a bit Spartan for most tastes, but the point is obvious: By wrapping errors into a separate routine, you can have our cake and eat it, too. The user gets an error message directing him or her to another site, and apologizing profusely for the program's errors. And the system administrator or web master gets a note in the error log describing exactly what went wrong, making it possible to fix the program more easily.

You could obviously add to this routine. For starters, a good idea might be to e-mail the system administrator or programmer to let him or her know that an error had occurred. If the program were part of a critical system, then perhaps it would even be a good idea to send e-mail to a system tied into an alphanumeric paging system.

______________________

White Paper
Linux Management with Red Hat Satellite: Measuring Business Impact and ROI

Linux has become a key foundation for supporting today's rapidly growing IT environments. Linux is being used to deploy business applications and databases, trading on its reputation as a low-cost operating environment. For many IT organizations, Linux is a mainstay for deploying Web servers and has evolved from handling basic file, print, and utility workloads to running mission-critical applications and databases, physically, virtually, and in the cloud. As Linux grows in importance in terms of value to the business, managing Linux environments to high standards of service quality — availability, security, and performance — becomes an essential requirement for business success.

Learn More

Sponsored by Red Hat

White Paper
Private PaaS for the Agile Enterprise

If you already use virtualized infrastructure, you are well on your way to leveraging the power of the cloud. Virtualization offers the promise of limitless resources, but how do you manage that scalability when your DevOps team doesn’t scale? In today’s hypercompetitive markets, fast results can make a difference between leading the pack vs. obsolescence. Organizations need more benefits from cloud computing than just raw resources. They need agility, flexibility, convenience, ROI, and control.

Stackato private Platform-as-a-Service technology from ActiveState extends your private cloud infrastructure by creating a private PaaS to provide on-demand availability, flexibility, control, and ultimately, faster time-to-market for your enterprise.

Learn More

Sponsored by ActiveState