8 Logging and Monitoring

Before covering the process of logging to files, consider the format of our log files. One of the benefits of Apache is its flexibility when it comes to log formatting. All this is owed to the LogFormat directive, whose default is the following, referred to as the Common Log Format (CLF):

LogFormat "%h %l %u %t \"%r\" %>s %b" common

The first parameter is a format string indicating the information to be included in a log file and the format in which it should be written; the second parameter gives the format string a name. You can decipher the log format using the symbol table. The table is available from the Apache reference documentation (http://httpd.apache.org/docs-2.0/mod/mod_log_config.html). It is reproduced in Table 8-1.

You have a lot of fields to play with. Format strings support optional parameters, as represented by the “ . . . ” in each format string representation in the table. Optional parameters can be used for the following actions:

Apache modules can collaborate on logging if they create a named note (a text string) and attach it to the request. If the %{note}n format string is used, the contents of the note will be written to the log. A change in the Apache architecture in the second generation allows for modules to collaborate and provide custom format strings. These format strings are available if the module that provides them is included in the configuration. (See Table 8-2.)

With the inclusion of mod_logio, you can measure the number of bytes transferred for every request. This feature allows hosting providers to put accurate billing mechanisms in place. (With Apache 1, you can only record the size of the response body, leaving request headers, request body, and response headers unmeasured.)

Now that you are familiar with format strings, look at commonly used log formats (see Table 8-3). (You will need to define these formats in httpd.conf if they are not already there.)

Though you can create your own log format, you will most likely use one of the formats above since that is what web server log analyzers support. Nevertheless, the ability to create logs with a custom format is convenient for advanced uses, as we shall see later in this chapter.

TransferLog is the basic request logging directive, which creates an access log with the given filename:

TransferLog /var/www/logs/access_log

The filename can be given with an absolute path, as above; if a relative filename is supplied, Apache will create the full path by pre-pending the server home directory (e.g. /usr/local/apache).

By default, the TransferLog directive uses the Common Log Format (CLF), which logs every request on a single line with information formatted (as shown in Section 8.1.1.1). Here is an example of what such a line looks like:

81.137.203.242 - - [29/Jun/2004:14:36:04 +0100] "POST /upload.php 
HTTP/1.1" 200 3229

However, if a LogFormat directive has been used earlier in the configuration file, the TransferLog directive will use the format it defined and not the CLF. This is unexpected and can lead to errors since changing the order in which formats are defined can lead to a different format being used for the log files. I prefer not to use TransferLog, and instead use the CustomLog directive (which forces me to explicitly define the log format).

The real power comes from using the CustomLog directive. The equivalent to the TransferLog usage described above looks like this:

CustomLog /var/www/logs/access_log custom

The explicit naming of the log format helps us avoid mistakes. I like this directive because of its conditional logging features. Have a look at the following configuration fragment:

# determine which requests are static - you may need to
# adjust the regular expression to exclude other files, such
# as PDF documents, or archives
SetEnvIfNoCase REQUEST_URI "\.(gif|png|jpg)$" static_request
   
# only log dynamic requests
CustomLog /var/www/logs/application_log combined env=!static_request

The conditional logging opens the door to many interesting logging opportunities, which really helps in real life. Most commonly, you will use mod_setenvif or mod_rewrite (which can also set environment variables) to determine what gets logged.

I mentioned that, by default, Apache uses the CLF, which does not record many request parameters. At the very least you should change the configuration to use the combined format, which includes the UserAgent and the Referer fields.

Looking at the log format string table shown in the LogFormat section, you can see over twenty different format strings, so even the use of a combined format results in loss of information. Create your own log format based on your information requirements. A nice example can be found at:

In the article, Chris makes a case for a log format that allows for web serving troubleshooting and performance management. At the end, he names the resulting log format Blackbox.

First, the application must make use of HTTP status codes other than 200 (which is used by default) where appropriate. These codes are very useful but not many applications utilize them. There are five code categories (see Table 8-5).

The 4XX category is particularly interesting and is the one we use the most (see Table 8-6).

With the status codes in mind, Table 8-7 presents the codes an application should return, given various events.

At first, I thought using the 401 status would be impossible since it would make the browser ask users to enter their credentials. Having done some tests, I determined that returning the status code alone (without the WWW-Authenticate header) is insufficient to trigger the authentication process. The 401 status can be used after all, and it appears in the access log.

When installed as a module, PHP integrates with Apache and allows direct communication between modules to take place. Other application engines may provide similar support. We will take advantage of the POST request body being available to the PHP code. We can, therefore, take the body and return it to Apache, along with other parameters known to the application (the username and the session identifier). This is possible because Apache has a feature called notes, which was specifically designed for inter-module communication.

The following code fragment sends some of the information from the PHP module to Apache, where the information is available for other modules to use. It creates four Apache notes: x_username, x_sessionid, x_request, and x_log.

function inform_apache($username, $sessionid) {
    // reconstruct the first line of the request
    $request = $_SERVER["REQUEST_METHOD"];
    $request .= " " . $_SERVER["REQUEST_URI"];
   
    // add any available POST parameters
    if (count($_POST) != 0) {
        // some POST requests contain parameters in the URI 
        if (strpos($request, "?") =  = false) $request .= "?";
        else $request .= "&";
   
        $count = 0;
        foreach($_POST as $name => $value) {
            if ($count != 0) $request .= "&";
            $request .= urlencode($name) . "=" . urlencode($value);
            $count++;
        }
    }
   
    $request .= $_SERVER["SERVER_PROTOCOL"];
   
    // send the parameters to Apache through notes
    apache_note("x_username", $username);
    apache_note("x_sessionid", $sessionid);
    apache_note("x_request", $request);
   
    // set an environment variable to trigger
    // conditional logging
    apache_setenv("x_log", "true");
}

Sending a message from the application to the logging module can be useful. This can be done through a warning note:

function warn_apache($warning) {
    apache_note("x_warning", $warning);
}

Finally, we arrive at our new log format:

LogFormat "%h %l %{x_username}n %t \"%{x_request}n\" %>s %b \"%{Referer}i\" \
\"%{User-Agent}i\" %{UNIQUE_ID}n %T %D %{x_sessionid}n %{x_warning}n \
%{error-notes}n" apptrack

Note the following:

We use the new log format together with a conditional logging directive to avoid having bogus lines in the log file:

# log only requests that have the extra PHP-supplied information
CustomLog /var/www/logs/special_log apptrack env=x_log

If you cannot take advantage of the Apache notes mechanism and the PHP integration (you may not be running PHP as a module, for example), the alternative is to use mod_security to recover the POST request body (it will create the x_request note when configured to do so) and to use response headers to transport the information out of the application. In the application code, send out the session identifier and the username, using headers x_sessionid and x_username. These headers can be logged with %{x_sessionid}o and %{x_username}o, respectively.

header("x_sessionid: $sessionid");
header("x_username: $username");

You will not be able to send a warning from the application using response headers though. Outgoing headers will be visible to the client, too, and using them for a warning may result in revealing critical information to an attacker.

The correct procedure to rotate a log from a script is:

Here is the same procedure given in a shell script, with the added logic to keep several previous log files at the same location:

#!/bin/sh
   
cd /var/www/logs
mv access_log.3.gz access_log.4.gz
mv access_log.2.gz access_log.3.gz
mv access_log.1.gz access_log.2.gz
mv access_log accesss_log.1
/usr/local/apache/bin/apachectl graceful
sleep 600
gzip access_log.1

Without the use of piped logging, there is no way to get around restarting the server; it has to be done for it to re-open the log files. A graceful restart (that’s when Apache patiently waits for a child to finish with the request it is processing before it shuts it down) is recommended because it does not interrupt request processing. But with a graceful restart, the wait in step 3 becomes somewhat tricky. An Apache process doing its best to serve a client may hang around for a long time, especially when the client is slow and the operation is long (e.g., a file download). If you proceed to step 4 too soon, some requests may never be logged. A waiting time of at least 10 minutes is recommended.

Many Linux distributions come with a utility called logrotate, which can be used to rotate all log files on a machine. This handy program takes care of most of the boring work. To apply the Apache log rotation principles to logrotate, place the configuration code given below into a file /etc/logrotate.d/apache and replace /var/www/logs/* with the location of your log files, if different:

/var/www/logs/* {
    # rotate monthly
    monthly
   
    # keep nine copies of the log
    rotate 9
   
    # compress logs, but with a delay of one rotation cycle
    compress
    delaycompress
   
    # restart the web server only once, not for
    # every log file separately
    sharedscripts
   
    # gracefully restart Apache after rotation
    postrotate
        /usr/local/apache/bin/apachectl graceful > /dev/null 2> /dev/null
    endscript
}

Use logrotate with the -d switch to make it tell you what it wants to do to log files without doing it. This is a very handy tool to verify logging is configured properly.

The rotatelogs utility shipped with Apache uses piped logging and rotates the file after a specified time period (given in seconds) elapses:

CustomLog "|/usr/local/apache/bin/rotatelogs /var/www/logs/access_log 
300" custom

The above rotates the log every five minutes. The rotatelogs utility appends the system time (in seconds) to the log name to keep filenames unique. For the configuration directive given above, you will get filenames such as these:

access_log.1089207300
access_log.1089207600
access_log.1089207900
...

Alternatively, you can use strftime-compatible (see man strftime) format strings to create a custom log filename format. The following is an example of automatic daily log rotation:

CustomLog "|/usr/local/apache/bin/rotatelogs \
/var/www/logs/access_log.%Y%m%d 86400" custom

Similar to rotatelogs, Cronolog (http://cronolog.org) has the same purpose and additional functionality. It is especially useful because it can be configured to keep a symbolic link to the latest copy of the logs. This allows you to find the logs quickly without having to know what time it is.

CustomLog "|/usr/local/apache/bin/cronolog \
/var/www/logs/access_log.%Y%m%d --link=/var/www/logs/access_log" custom

A different approach is used in Cronolog to determine when to rotate. There is no need to specify the time period. Instead, Cronolog rotates the logs when the filename changes. Therefore, it is up to you to design the file format, and Cronolog will do the rest.

One way to implement periodic monitoring is to use the concept of Artificial Ignorance invented by Marcus J. Ranum. (The original email message on the subject is at http://www.ranum.com/security/computer_security/papers/ai/.) The process starts with raw logs and goes along the following lines:

The idea is to uncover a specific type of event, but without the specifics. The numerical value is used to assess the seriousness of the situation. Here is the same logic implemented as a Perl script (I call it error_log_ai) that you can use:

#!/usr/bin/perl -w
   
# loop through the lines that are fed to us
while (defined($line = <STDIN>)) {
   
    # ignore "noisy" lines
    if (!( ($line =~ /Processing config/)
        || ($line =~ /Server built/)
        || ($line =~ /suEXEC/) )) {
   
        # remove unique features of log entries
        $line =~ s/^\[[^]]*\] //;
        $line =~ s/\[client [^]]*\] //;
        $line =~ s/\[unique_id [^]]*\]//;
        $line =~ s/child pid [0-9]*/child pid X/;
        $line =~ s/child process [0-9]*/child process X/;
   
        # add to the list for later
        push(@lines, $line);
    }
}

  
@lines = sort @lines;
   
# replace multiple occurences of the same line
$count = 0;
$prevline = "";
foreach $line (@lines) {
    next if ($line =~ /^$/);
   
    if (!($line eq $prevline)) {
        if ($count != 0) {
            $prefix = sprintf("%5i", $count);
            push @outlines, "$prefix $prevline";
        }
        $count = 1;
        $prevline = $line;
    } else {
        $count++;
    }
}
undef @lines;

 
@outlines = sort @outlines;
print "--httpd begin------\n";
print reverse @outlines;
print "--httpd end--------\n";

The script is designed to take input from stdin and send output to stdout, so it is easy to use it on the command line with any other script:

# cat error_log | error_log_ai.pl | mail ivanr@webkreator.com

From the following example of daily output, you can see how a long error log file was condensed into a few lines that can tell you what happened:

--httpd begin------
  38 [notice] child pid X exit signal Segmentation fault (11)
  32 [info] read request line timed out
  24 [error] File does not exist: /var/www/html/403.php
  19 [warn] child process X did not exit, sending another SIGHUP
   6 [notice] Microsoft-IIS/5.0 configured -- resuming normal operations
   5 [notice] SIGHUP received.  Attempting to restart
   4 [error] File does not exist: /var/www/html/test/imagetest.GIF
   1 [info] read request headers timed out
--httpd end--------

Swatch (http://swatch.sourceforge.net) is a program designed around Perl and regular expressions. It monitors log files for events and evaluates them against expressions in its configuration file. Incoming events are evaluated against positive (take action on event) and negative (ignore event) regular expressions. Positive matches result in one or more actions taking place.

A Swatch configuration file designed to detect DoS attacks by examining the error log could look like this:

# Ignore requests with 404 responses
ignore /File not found/
   
# Notify me by email about mod_security events
# but not more than once every hour
watchfor /mod_security/
    throttle 1:00:00
    mail ivanr@webkreator.com,subject=Application attack
   
# Notify me by email whenever the server
# runs out of processes - could be a DoS attack
watchfor /MaxClients reached/
    mail ivanr@webkreator.com,subject=DOS attack

Swatch is easy to learn and use. It does not offer event correlation, but it does offer the throttle keyword (used in the previous example), which prevents too many actions from taking place.

Simple Event Correlator (SEC, available from http://www.estpak.ee/~risto/sec/) is the tool to use when you want to implement a really secure system. Do not let the word “simple” in the name fool you; SEC is a very powerful tool. Consequently, it can be a bit difficult to configure.

It works on the same principles as Swatch, but it keeps track of events and uses that information when evaluating future events. I will give a few examples of SEC to demonstrate its capabilities.

SEC is based around several types of rules, which are applied to events. The rule types and their meanings are:

Do not worry if this looks confusing. Read it a couple of times and it will start to make sense. I have prepared a couple of examples to put the rules above in the context of what we do here.

The following two rules cause SEC to wait for a nightly backup and alert the administrator if it does not happen:

# At 01:59 start waiting for the backup operation
# that takes place at 02:00 every night. The time is
# in a standard cron schedule format.
type = Calendar 
time = 59 1 * * *
desc = WAITING FOR BACKUP
action = event %s
   
# This rule will be triggered by the previous rule
# it will wait for 31 minutes for the backup to
# arrive, and notify the administrator if it doesn't
type = PairWithWindow
ptype = SubStr
pattern = WAITING FOR BACKUP
desc = BACKUP FAILED
action = shellcmd notify.pl "%s"
ptype2 = SubStr 
pattern2 = BACKUP COMPLETED
desc2 = BACKUP COMPLETED
action2 = none
window = 1860

The following rule counts the number of failed login attempts and notifies the administrator should the number of attempts become greater than six in the last hour. The shell script could also be used to disable login completely from that IP address.

type = SingleWithThreshold
ptype = RegExp
pattern = LOGIN FAILED, IP=([0-9.]+)
window = 3600
thresh = 6
desc = Login failed from IP: $1
action = shellcmd notify.pl "Too many login attempts from: $1"

SEC uses the description of the event to distinguish between series of events. Because I have included the IP address in the preceding description, the rule, in practice, monitors each IP address. Therefore, it may be a good idea to add another rule to watch the total number of failed login attempts during a time interval:

type = SingleWithThreshold
ptype = RegExp
pattern = LOGIN FAILED, IP=([0-9.]+)
window = 3600
thresh = 24
desc = Login failed (overall)
action = shellcmd notify.pl "Too many login attempts"

This rule would detect a distributed brute-force hacking attempt.

We need to understand what data we have available. Looking at the screenshot (Figure 8-2), the first nine fields are easy to spot since each is presented on its own line. Then comes the scoreboard, which lists all processes (or threads) and tells us what each process is doing. The legend can be seen in the first screenshot, Figure 8-1. The scoreboard is not useful to us in the given format but we can count how many times each activity occurs in the scoreboard and create 10 more variables for storing this information. Therefore, we have a total of 19 variables that contain information obtained from the mod_status machine-parsable output.

First, we write the part of the Perl program that fetches and parses the mod_status output. By relying on existing Perl libraries for HTTP communication, our script can work with proxies, support authentication, and even access SSL-protected pages. The following code fetches the page specified by $url:

# fetch the page
my $ua = new LWP::UserAgent;
$ua->timeout(30);
$ua->agent("apache-monitor/1.0");
   
my $request = HTTP::Request->new(GET => $url);
my $response = $ua->request($request);

Parsing the output is fairly simple. Watch out for the incompatibility between the mod_status output in Apache 1 and Apache 2.

# Fetch the named fields first
# Set the results associative array. Each line in the file
# results in an element in the array. Each element
# has a key that is the text preceding the colon in a line 
# of the file, and a value that is whatever appears after
# any whitespace after the colon on that line.
my %results = split/:\s*|\n/, $response->content;

# There is a slight incompatibility between
# Apache 1 and Apache 2, so the following makes
# the results consistent between the versions. Apache 2 uses
# the term "BusyWorkers" where Apache 1 uses "BusyServers".
if ($results{"BusyServers"}) {
    $results{"BusyWorkers"} = $results{"BusyServers"};
    $results{"IdleWorkers"} = $results{"IdleServers"};
}

# Count the occurrences of certain characters in the scoreboard
# by using the translation operator to find and replace each
# particular character (with itself) and return the number of
# replacements.
$results{"s_ _"} = $results{"Scoreboard"} =~ tr/_/_/;
$results{"s_s"} = $results{"Scoreboard"} =~ tr/S/S/;
$results{"s_r"} = $results{"Scoreboard"} =~ tr/R/R/;
$results{"s_w"} = $results{"Scoreboard"} =~ tr/W/W/;
$results{"s_k"} = $results{"Scoreboard"} =~ tr/K/K/;
$results{"s_d"} = $results{"Scoreboard"} =~ tr/D/D/;
$results{"s_c"} = $results{"Scoreboard"} =~ tr/C/C/;
$results{"s_l"} = $results{"Scoreboard"} =~ tr/L/L/;
$results{"s_g"} = $results{"Scoreboard"} =~ tr/G/G/;
$results{"s_i"} = $results{"Scoreboard"} =~ tr/I/I/;

After writing this code, I realized some of the fields mod_status gave me were not very useful. ReqPerSec, BytesPerSec, and BytesPerReq are calculated over the lifetime of the server and practically remain constant after a certain time period elapses. To get around this problem, I decided to keep the output from the previous run and manually create the statistics by comparing the values of the Total Accesses and Total kBytes fields, as appropriate, in relation to the amount of time between runs. The code for doing this can be seen in the program (apache-monitor) on the book’s web site.

Next, we store the data into an RRD file so that it can be processed by an RRD tool. We need to test to see if the desired RRD file (specified by $rrd_name in the following) exists and create it if it does not:

if (! -e $rrd_name) {
  # create the RRD file since it does not exist
  RRDs::create($rrd_name,
    # store data at 60 second intervals
    "-s 60",
    # data fields. Each line defines one data source (DS)
    # that stores the measured value (GAUGE) at maximum 10 minute
    # intervals (600 seconds), and takes values from zero.
    # to infinity (U).
    "DS:totalAccesses:GAUGE:600:0:U",
    "DS:totalKbytes:GAUGE:600:0:U",
    "DS:cpuLoad:GAUGE:600:0:U",
    "DS:uptime:GAUGE:600:0:U",
    "DS:reqPerSec:GAUGE:600:0:U",
    "DS:bytesPerSec:GAUGE:600:0:U",
    "DS:bytesPerReq:GAUGE:600:0:U",
    "DS:busyWorkers:GAUGE:600:0:U",
    "DS:idleWorkers:GAUGE:600:0:U",
    "DS:sc_ _:GAUGE:600:0:U",
    "DS:sc_s:GAUGE:600:0:U",
    "DS:sc_r:GAUGE:600:0:U",
    "DS:sc_w:GAUGE:600:0:U",
    "DS:sc_k:GAUGE:600:0:U",
    "DS:sc_d:GAUGE:600:0:U",
    "DS:sc_c:GAUGE:600:0:U",
    "DS:sc_l:GAUGE:600:0:U",
    "DS:sc_g:GAUGE:600:0:U",
    "DS:sc_i:GAUGE:600:0:U",
    # keep 10080 original samples (one week of data,
    # since one sample is made every minute)
    "RRA:AVERAGE:0.5:1:10080", 
    # keep 8760 values calculated by averaging every
    # 60 original samples (Each calculated value is one
    # day so that comes to one year.) 
    "RRA:AVERAGE:0.5:60:8760" 
  }
);

Finally, we add the data to the RRD file:

RRDs::update($rrd_name, $time
    . ":" . $results{"Total Accesses"}
    . ":" . $results{"Total kBytes"}
    . ":" . $results{"CPULoad"}
    . ":" . $results{"Uptime"}
    . ":" . $results{"ReqPerSec"}
    . ":" . $results{"BytesPerSec"}
    . ":" . $results{"BytesPerReq"}
    . ":" . $results{"BusyWorkers"}
    . ":" . $results{"IdleWorkers"}
    . ":" . $results{"s_ _"}
    . ":" . $results{"s_s"}
    . ":" . $results{"s_r"}
    . ":" . $results{"s_w"}
    . ":" . $results{"s_k"}
    . ":" . $results{"s_d"}
    . ":" . $results{"s_c"}
    . ":" . $results{"s_l"}
    . ":" . $results{"s_g"}
    . ":" . $results{"s_i"}
);

Creating graphs from the information stored in the RRD file is the really fun part of the operation. Everyone loves the RRDtool because no skills are required to produce fabulous graphs. For example, the Perl code below creates a graph of the number of active and idle servers throughout a designated time period, such as the third graph shown in Figure 8-3. The graph is stored in a file specified by $pic_name.

RRDs::graph($pic_name,
    "-v Servers",
    "-s $start_time",
    "-e $end_time",
    # extracts the busyWorkers field from the RRD file
    "DEF:busy=$rrd_name:busyWorkers:AVERAGE",
    # extracts the idleWorkers field from the RRD file
    "DEF:idle=$rrd_name:idleWorkers:AVERAGE",
    # draws a filled area in blue
    "AREA:busy#0000ff:Busy servers",
    # draws a line in green
    "LINE2:idle#00ff00:Idle servers"
);

Figure 8-3. Graphs representing web server activity

I decided to create four graphs out of the available data:

The graphs are shown in Figure 8-3. You may want to create other graphs, such as ones showing the uptime and the CPU load. Note: The live view of the web server statistics for apache.org are available at http://www.apachesecurity.net/stats/, where they will remain for as long as the Apache Foundation keeps their mod_status output public.

Two scripts, parts of which were shown above, are used to record the statistics and create graphs. Both are available from the web site for this book. One script, apache-monitor, fetches statistics from a server and stores them. It expects two parameters. The first specifies the (RRD) file in which the results should be stored, and the second specifies the web page from which server statistics are obtained. Here is a sample invocation:

$ apache-monitor /var/www/stats/apache.org http://www.apache.org/server-status/

For a web page that requires a username and password, you can embed these directly in the URL (e.g., http://username:password@www.example.com/server-status/). The script is smart enough to create a new RRD file if one does not exist. To get detailed statistics of the web server activity, configure cron to execute this script once a minute.

The second script, apache-monitor-graph, draws graphs for a given RRD file. It needs to know the path to the RRD file (given as the first parameter), the output folder (the second parameter), and the duration in seconds for the time period the graphs need to cover (the third parameter). The script calculates the starting time by deducting the given duration from the present time. The following invocation will create graphs for the last six hours:

$ apache-monitor-graph /var/www/stats/apache.org /var/www/stats/ 21600

Four files will be created and stored in the output folder, each showing a single graph:

$ cd /var/www/stats
$ ls
apache.org_servers-21600.gif
apache.org_hits-21600.gif
apache.org_transfer-21600.gif
apache.org_scoreboard-21600.gif

You will probably want to create several graphs to monitor the activity over different time periods. Use the values in seconds from Table 8-9.

Calling the graphing script every five minutes is sufficient. Having created the graphs, you only need to create some HTML code to glue them together if you want to show multiple graphs on a single page (see Figure 8-3).

mod_status was designed to allow for web server monitoring. If you need more granularity, you will have to turn to mod_watch, a third-party module available from http://www.snert.com/mod_watch/. This module can provide information for an unlimited number of contexts, where each context can be one of the following:

For each context, mod_watch provides the following values:

Since this module comes with utility scripts to integrate it with MRTG (a monitoring and graphing tool described at http://people.ee.ethz.ch/~oetiker/webtools/mrtg/), it can be of great value if MRTG has been deployed.