Copyright Notice

This text is copyright by InfoStrada Communications, Inc., and is used with their permission. Further distribution or use is not permitted.

This text has appeared in an edited form in Linux Magazine magazine. However, the version you are reading here is as the author originally submitted the article for publication, not after their editors applied their creativity.

Please read all the information in the table of contents before using this article.
Download this listing!

Linux Magazine Column 78 (Feb 2006)

[Suggested title: ``Using a database for a web server log (part 2)'']

In [last month's column], I showed how my Apache2 processes are using mod_perl2 to write logging information to a logger process. Let's continue that description with information about the logger process.

The logger is launched with its STDIN connected to a pipe created by the master Apache process. As Apache forks each server child, this pipe is shared, thus making the logger's input available to all children.

During the logging phase, each child writes a line to this shared pipe that looks like:

  <field1=hexvalue field2=hexvalue field3=hexvalue>

where each of the field names correspond to a column in the logging database, and the hexvalues will be their corresponding value.

Each server child process is writing to this pipe asynchronously, without performing any sort of locking. However, most modern Unix-like systems guarantee that such writes under a certain size (typically 4096 bytes) are performed atomically, which means that the logger process should get data with no fear of being intermixed. However, note that each record is bracketed by a less-than and greater-than mark. We can double check that we've gotten a complete record by looking for these marks. In the months that I've been using this system, I have not yet seen a failed record, so I believe this system to be reasonably safe.

The logger process needs to remain alive as long as the Apache children are alive. To stop the logger process, we can simply terminate the program when we finally get EOF on the pipe. But what about errors? If the logger process dies, there's no easy way to replace it (other than restart the Apache server) because the pipe from the parent Apache process is not a named pipe. (Hmm, making the interface through a named pipe might be an interesting idea for a future version of this program.)

Because this input pipe was ``sacred'', and the logger needed to run ``forever'', I decided to implement a watchdog process pattern. The logger program forks a child to do the actual work, and watches for the logger-child to exit. If the child exits cleanly, so does the watchdog (such as when the child reads EOF because Apache is shutting down). However, if the child dies badly, the watchdog respawns a new child. Because the watchdog retains the STDIN from the Apache logging pipe, the new child also inherits this connection, including any unprocessed data, and can pick up where the exited child left off.

As long as the watchdog itself doesn't have any unusual exit conditions, we're guaranteed a fair degree of safety, so it's important to make sure the watchdog does as little as possible. My resulting program that performs both the watchdog and the database writer are found in [listing one, below].

Lines 1-3 create my traditional program start. Because this program is processed as a Template Toolkit file during the server build process, anything marked with [*..*] will be processed and replaced with the appropriate text. In this case, the PERL variable from the environment provides the appropriate ``she-bang'' line. This variable is set in the GNU Makefile as:

  export PERL ?= $(shell which perl)

Thus, by default, an appropriate path to perl is determined. This is important because I've left the Mac OSX Perl alone on my box, preferring instead to install local modules into a local bleading-edge Perl that I've installed in /opt/perl/snap/bin on my machine. However, when I push this code up to the server, I need to use the traditional /usr/bin/perl path instead.

Lines 5 through 8 create a header on the resulting templated file, giving the original file name, processing time, and the modification time. I've discovered that when I generate files that look like source files, it's important to mark the file as such. Otherwise, I might try editing it and then wonder why my changes disappear later.

Lines 11 through 15 provide the database information to connect to my PostgreSQL server. Obviously, the username and password here are fictionalized. These items are used in line 31 to connect to the database.

Line 17 pulls in the DBI module.

Lines 19 to 57 form a loop for the basic watchdog algorithm.

Line 20 attempts to create a child process to do the real work. If this should fail, a message is logged to STDERR. This error message appears in the Apache error log. After 5 seconds, we try again. The five seconds ensures that we don't get into a tight loop of trying to fork, failing, and burning up a lot of CPU trying that again and again immediately.

If we reach line 21, we have both a parent (the watchdog) and the child (the actual logging process) running in parallel. However, $pid will be zero in the child, and non-zero in the parent, so it's time for them to start acting differently. If we're the parent, we'll wait for the child (line 23).

If the child process exits cleanly, then $? will be zero, and the parent process breaks out of the loop (line 24), resulting in a clean exit. However, if the child broke somehow, we reach line 25, triggering a warning message, and an attempt to restart the child. Again, we wait 5 seconds to ensure that there's no thrashing because of something really horribly wrong out there.

The parent code will execute either the last in line 24, or the redo in line 27, so it can never make it down to line 29, which marks the beginning of the child code. Now we can see where the real work gets done.

Lines 31 and 32 set up my database handle (called $dbh for traditional reasons). Because I've set RaiseError, any bad operations (including setting up the initial connection) trigger an exception. Because these exceptions aren't caught (no eval blocks in this code), the entire child process will die, and the watchdog will replace it. Simple, but effective.

Lines 34 through 53 read a line at a time from standard input. Because this child process inherits STDIN from the parent (watchdog) process, and the parent process got its STDIN as the pipe connection to Apache for logging, this loop will execute once for each log record.

Line 35 was useful during debugging to ensure that the right data was being read by the child logger. The Apache error log showed that I was getting the right information at the right time. Of course, in production, this would be excessively noisy (turning the error log into an access log), so I commented the line in case I needed it in the future.

Lines 36 and 37 extract the keyword and hex value payload from the line. If the line doesn't have the proper angle bracket markers, we report it and ignore it. This might happen if the writes weren't atomic, for example.

Line 38 sets up an array to hold the list of fields to be inserted.

Lines 39 to 44 break up the line by whitespace, causing $field to repeatedly contain a column name and hex value for that column. Lines 40 and 41 break up the $field into the column name and hex value as $1 and $2. If that fails, the item is logged and ignored.

Line 42 grabs the column name into $key, and turns the hex value into the original string for $value. Line 43 pushes that into the @fields array for final insertion.

Once we've completed the value extraction, it's time to create the insert handle. Lines 45 to 50 create a string that looks like:

  INSERT INTO requests
  (stamp, url, status)
  VALUES (?, ?, ?)

The number of question marks corresponds to the number of fields that we saw on this request. These question marks are DBI placeholders that will be given values during the execute step.

Line 51 prepares the SQL, using prepare_cached. We hope that most of these inserts will actually use the same column names, so the prepare_cached step will be very fast. However, for maximum flexibility, each request is considered separately. Note that the logger doesn't even have to know the names of the columns.

Once we have a good statement handle in $sth, it's time to perform the insert in line 52. Each of the values extracted from @fields provides the value for the corresponding column selected in the SQL earlier.

When the loop reading from STDIN exits, it means we've seen the end of the input. At this point, the Apache server is no longer talking to us, so our usefulness has ceased, and it's time to leave quietly, in line 56. The 0 exit code ensures that the watchdog will also know to exit quietly as well.

And there you have it: a logging aggregator that can take log information from nearly any number of Apache child processes and write them all to the database using a single connection handle.

Now that this logging agent is in place, I can get near-real-time information from my database about the performance of my webserver.

For convenience, I've created a couple of views to select the front or back server cluster:

  CREATE VIEW front AS
  SELECT requests.* FROM requests
  WHERE server = 'P';
  CREATE VIEW back AS
  SELECT requests.* FROM requests
  WHERE server = 'B';

From these views, I can ask about all front requests that have resulted in 404s in the past 24 hours:

  SELECT referer, url, count(*)
  FROM front
  WHERE stamp > 'yesterday' AND status = 404
  GROUP BY 1, 2 ORDER BY 3 DESC LIMIT 10;

Or, I can see which user agents (types of browsers or robots) have burned the most CPU on my system in the past five minutes (possibly pointing out some badly behaved spider):

  SELECT SUM(cpuuser+cpusys+cpucuser+cpucsys), useragent
  FROM requests
  WHERE stamp > now() - interval '5 minutes'
  GROUP BY 2 ORDER BY 1 DESC LIMIT 10;

I could also implement some bandwidth restrictions by penalizing any heavy downloaders by IP address using a query similar to:

  SELECT SUM(bytes), host
  FROM front
  WHERE stamp > now() - interval '1 minutes'
  GROUP BY 2 ORDER BY 1 DESC LIMIT 10;

Since my pages are dynamically generated, it's nice to know which of my pages could use some optimization:

  SELECT SUM(cpuuser+cpusys+cpucuser+cpucsys), vhost || url
  FROM requests
  WHERE stamp > now() - interval '1 day'
  GROUP BY 2 ORDER BY 1 DESC LIMIT 10;

Lots of useful queries! I'm still discovering more every day.

I hope you find the information useful. Until next time, enjoy!

Listing

        =1=     #![* env.${"PERL"} *] -w
        =2=     use strict;
        =3=     $|++;
        =4=     
        =5=     [* USE date; FILTER format('### %-70s ###') -*]
        =6=     Processed automatically at [* date.format(date.now) *] from
        =7=     [* template.name *] edited at [* date.format(component.modtime) *]
        =8=     [*- END *]
        =9=
        =10=    
        =11=    ## config
        =12=    my $DSN = 'dbi:Pg:dbname=web';
        =13=    my $DB_TABLE = 'requests';
        =14=    my $DB_AUTH = 'Username:Password';
        =15=    ## end config
        =16=    
        =17=    use DBI;
        =18=    
        =19=    {
        =20=      defined (my $pid = fork) or do { warn "can't fork: $!"; sleep 5; redo };
        =21=      if ($pid) {
        =22=        ## parent does...
        =23=        waitpid($pid, 0);
        =24=        last unless $?;             # clean exit means I can go away too
        =25=        warn "logger died with $?, restarting...";
        =26=        sleep 5;                    # do not thrash!
        =27=        redo;
        =28=      }
        =29=      ## child does...
        =30=    
        =31=      my $dbh = DBI->connect($DSN, (split ':', $DB_AUTH),
        =32=                             {RaiseError => 1 });
        =33=    
        =34=      while (<STDIN>) {
        =35=        ## warn "$0 saw $_";
        =36=        s/^<(.*)>$/$1/
        =37=          or warn ("skipping $_\n"), next;
        =38=        my @fields;
        =39=        for my $field (split) {
        =40=          $field =~ /^(\w+)=([0-9a-fA-F]*)$/
        =41=            or warn ("skipping $_ in $field\n"), next;
        =42=          my ($key, $value) = ($1, pack("H*", $2));
        =43=          push @fields, [$key, $value];
        =44=        }
        =45=        my $INSERT =
        =46=          "INSERT INTO $DB_TABLE (".
        =47=            (join ",", map $_->[0], @fields).
        =48=              ") VALUES(".
        =49=                (join ",", ("?") x @fields).
        =50=                  ")";
        =51=        my $sth = $dbh->prepare_cached($INSERT);
        =52=        $sth->execute(map $_->[1], @fields);
        =53=      }
        =54=    
        =55=      $dbh->disconnect;
        =56=      exit 0;
        =57=    }

Randal L. Schwartz is a renowned expert on the Perl programming language (the lifeblood of the Internet), having contributed to a dozen top-selling books on the subject, and over 200 magazine articles. Schwartz runs a Perl training and consulting company (Stonehenge Consulting Services, Inc of Portland, Oregon), and is a highly sought-after speaker for his masterful stage combination of technical skill, comedic timing, and crowd rapport. And he's a pretty good Karaoke singer, winning contests regularly.

Schwartz can be reached for comment at merlyn@stonehenge.com or +1 503 777-0095, and welcomes questions on Perl and other related topics.