Tech Notes

Tech Note #20140006

When using a program to rewrite URLs under the Apache RewriteMap directive of the mod_rewrite engine, debugging the program's logic can be difficult since it runs as a task under Apache in such a way as to preclude the use of the usual debugging tools.

Not only that but the Apache mod_rewrite documentation is particularly circumspect on the subject of how to debug such a program. Nor is there much information available on the Internet as to how mod_rewrite programs can be debugged. About the only helpful advice that is given is, "make a mistake inside this program and Apache will hang."

Funnily enough, it turns out that debugging can be easily facillitated through direct logging to the Apache error log, if only one knows how to do it. This Tech Note describes how to go about it.

Logging From a Mod_rewrite Program:

We could not find any reference to the fact that any text written to stderr from within the mod_rewrite program is written to the Apache error log but this is, indeed, the case. Consequently, to use the error log as an assist in debugging, one simply needs to sprinkle the appropriate print statements throughout the program, as needed.

From a C program, one can use the pre-opened handle stderr. Writes to this handle can be done using fprintf, like this:

fprintf(stderr, "At line %d!\n", __LINE__);

The same kind of thing can be done in Perl like this:

print(STDERR "At line ", __LINE__, "!\n");

In Perl, beware of the fact that there is no comma between STDERR and the literal that follows. Also, beware that __LINE__ is a token that isn't interpolated as a string so it must be used in the print statement as shown, separated from the strings by commas.

While this simple techinique works, if you are planning on leaving your logging code in the mod_rewrite program, you will probably want to format what is written to the log so that it matches the standard error log entries that Apache writes. When Apache writes the log entries, written by a mod_rewrite program, to its error log, it does nothing to timestamp them, identifiy them or tag them in any way shape or form.

In order to fit in, the entries written to the Apache error log should look something like this:

[Sat Sep 20 14:30:05.773302 2014] [rewrite:notice] [pid 15102] Message text

The timestamp includes the time in microseconds but is, otherwise, a typical timestamp. We have chosen to identify the log entry with the string "rewrite" and mark it as a "notice". Most log entries written by Apache come from a worker task so they include a task ID or tid but, since the rewrite program doesn't run under an Apache worker task, we only include the process ID or pid in the log stamp.

The following Perl function can be included in a Perl version of the mod_rewrite program to write suitable log entries:


#
# Module tag to be added to each Apache log file entry.  Since Apache error
# log entries can be generated under many circumstances, they need to be
# identified as to their origin and type, to facillitate easy debugging.
#
use constant MODULE_TAG => "rewrite:notice";

############################################################################

sub WriteLog
#
# LogMsg                                Message to be written to the logfile.
#
# Routine to write log messages to the Apache logfile.
#
# The mod_rewrite program can write whatever it likes to STDERR, in which
# case it will be logged by Apache to its error log.  However, it behooves
# us to format the message written to the log file in the same way that
# Apache formats its error messages, using the same kind of identifying
# information that Apache uses, so that our messages will fit in.
#
# That being the case, this routine stamps the logged message with an
# appropriate timestamp, module tag, message type and PID before it writes
# it to STDERR.
#
{
my ($LogMsg) = @_;

my ($Seconds, $MicroSecs);              # Timestamps in usecs
my ($Sec, $Min, $Hour, $MDay, $Mon, $Year, $WDay);
                                        # Printable timestamp info
my ($LogStamp);                         # Log stamp string
#
# Make up a timestamp for the logging porpoises.  Identify it with our tag
# plus the PID, for tracking porpoises.
#
($Seconds, $MicroSecs) = gettimeofday();
($Sec, $Min, $Hour, $MDay, $Mon, $Year, $WDay) = localtime($Seconds);

$LogStamp = sprintf("[%s %s %d %02d:%02d:%02d.%06d %04d] [%s] [pid %d] ",
    (Sun,Mon,Tue,Wed,Thu,Fri,Sat)[$WDay],
    (Jan,Feb,Mar,Apr,May,Jun,Jul,Aug,Sep,Oct,Nov,Dec)[$Mon],
    $MDay, $Hour, $Min, $Sec, $MicroSecs, $Year+1900,
    MODULE_TAG, $$);
#
# Log the message to the Apache logfile.
#
$LogMsg =~ s/\n$//; print(STDERR $LogStamp.$LogMsg."\n");
#
# Close up shop.
#
return;
}