home January 01, 2017

Web Access Log Sentry


email status reports for Apache, Nginx and Lighthttpd

If you support, design or own a web server you are always interested in the users and abusers of your service. You want to keep an eye on traffic load, what the users are doing and the errors they trip. The problem is, you can not be sitting there watching the logs all day and night. What you really need is an automated web sentry watching the access logs and notifing you of problems.

What does it do?

The moneyslow.com "Web Access Log Sentry" will watch your web logs and send mail to the listed recipients. The mail output is Blackberry friendly and since it is so small will not take up much bandwidth or air time. Lets take a look a two of the example emails you could receive. This email is an example of a client requesting pages/files beyond our set server limit.

From: web_admin@your_hostname.com (web guy)
To: web_support@your_hostname.com web_developers@your_hostname.com
Date: Mon, 10 Jan 2020 10:20:30 -0600 (EDT)
Subject: Report from calomel web access sentry

  219.112.31.170 generated 503 errors during the past 10 minutes.
  219.112.31.170 requested /files/example_file.txt 261 times during the past 10 minutes.
  219.112.31.170 requested /files/another_file.bz2 242 times during the past 10 minutes.
This email shows the web server has not seen access in the last 3 minutes and 12 seconds.
From: web_admin@your_hostname.com (web guy)
To: web_support@your_hostname.com web_developers@your_hostname.com
Date: Mon, 10 Jan 2020 10:20:30 -0600 (EDT)
Subject: Report from calomel web access sentry

  3 minutes and 12 seconds have elapsed since the last logged request.

What the script will look for?

The "Web Access Log Sentry" script, which is fully cusomizable and commented, will monitor the current web log (access_log) for the past ten(10) minutes and send email on the following conditions:

Starting the install

Step 1: is getting the script and looking at the options. Below you can download the web_access_sentry.pl as a file and you can also browse the same script in a scrollable text window. Both are provided so you can easily review the Perl script.

You can download calomel_web_access_sentry.pl here by doing a cut a paste of the code in the scrollable window. Before using the config file take a look it below or download it and look at the options. moneyslow.com

#!/usr/bin/perl
#
#######################################################
###  moneyslow.com web_access_sentry.pl  BEGIN
#######################################################

use Time::Local;

my %mon = qw/Jan 0 Feb 1 Mar 2 Apr 3 May  4 Jun  5
             Jul 6 Aug 7 Sep 8 Oct 9 Nov 10 Dec 11/;

# USER CONFIGURABLE OPTIONS - Web log target
my $log = '/var/log/web_server/access_log';

# USER CONFIGURABLE OPTIONS - email sender and recipients
my $return_addr = 'web_admin@your_hostname.com';
my $recipients = join ',',qw/
                 web_support@your_hostname.com
                 web_developers@your_hostname.com
                 /;
my $sendmail = "/usr/lib/sendmail -f$return_addr -t";

# USER CONFIGURABLE OPTIONS - Thresholds
# Choose some thresholds designed to separate the
# miscreants from the well-behaved web users.
my $max_requests_per_host = 2000;
my $max_bytes_per_host = 2_000_000_000;
my $max_errors_per_host = 200;
my $max_duplicate_urls_per_host = 120;

my %dns;

open LOG,$log or die "Could not open $log ($!)";

my $inode = (stat LOG)[1];

my @rec = ();
my $most_recent = $^T;

for(;;){        # Keep doing this until someone kills this process.

# USER CONFIGURABLE OPTIONS - Amount of time to watch the logs
  my $start = time - 600;               # Look at the past 10 minutes.

  @rec = grep $_->[0] >= $start, @rec;  # Remove any previously read log
                                        # records that are more than 10
                                        # minutes old.

  # Read and parse the next batch of access log records.
  while(<LOG>){

    my ($host, $ident_user, $auth_user, $day,$mon,$year, $hour,$min,$sec,
    $time_zone, $method, $url, $protocol, $status,
    $bytes, $referer, $agent) =
    /                 # regexp begins
    ^               # beginning-of-string anchor
    (\S+)           # assigned to $host
    \               # literal space
    (\S+)           # assigned to $ident_user
    \               # literal space
    (\S+)           # assigned to $auth_user
    \               # literal space
    \[              # literal left bracket
    (\d\d)          # assigned to $day
    \/              # literal solidus
    ([A-Z][a-z]{2}) # assigned to $mon
    \/              # literal solidus
    (\d{4})         # assigned to $year
    :               # literal colon
    (\d\d)          # assigned to $hour
    :               # literal colon
    (\d\d)          # assigned to $min
    :               # literal colon
    (\d\d)          # assigned to $sec
    \               # literal space
    ([^\]]+)        # assigned to $time_zone
    \]\ "           # literal string '] "'
    (\S+)           # assigned to $method
    \               # literal space
    (.+?)           # assigned to $url
    \               # literal space
    (\S+)           # assigned to $protocol
    "\              # literal string '" '
    (\S+)           # assigned to $status
    \               # literal space
    (\S+)           # assigned to $bytes
    \               # literal space
    "([^"]+)"       # assigned to $referer
    \               # literal space
    "([^"]+)"       # assigned to $agent
    $               # end-of-string anchor
    /x              # regexp ends, with x modifier
    or next;

# USER CONFIGURABLE OPTIONS - Ignore internal hosts
    $host eq '::1' and next; # Ignore Apache generated requests from localhost.
    $host =~ /^192\.168\./ and next;    # Ignore the local net example #1
    $host =~ /^10\.10\.10/ and next;    # Ignore another net example #2

    # Parse the $time_zone variable.
    my $tz = 0;
    my ($tzs,$tzh,$tzm) = $time_zone =~ /([\-+ ])(\d\d)(\d\d)/;
    if(defined $tzs){
      $tzs = $tzs eq '-' ? 1 : -1;
      $tz = $tzs * (3600*$tzh + 60*$tzm);
    }

    my $time = timegm($sec,$min,$hour,$day,$mon{$mon},$year-1900) + $tz;
    $most_recent = $time if $time > $most_recent;

    next if $time < $start;

    #         [  0  ,  1  ,  2 ,   3   ,   4  ]
    push @rec,[$time,$host,$url,$status,$bytes];
  }

  my $report;

# USER CONFIGURABLE OPTIONS - Report if no client access has been seen for 180 seconds
  my $seconds_since_last_request = time - $most_recent;
  if($seconds_since_last_request > 180){
    # If too much time has elapsed, then report that something may be wrong.
    my $elapsed = delta_time($seconds_since_last_request);
    $report .=
    "$elapsed have elapsed since the last logged request.\n";
  }

  # Accumulate the statistics for the most recent X minutes' worth of logs.
  my %requests_per_host;
  my %bytes_per_host;
  my %errors_per_host;
  my %duplicate_urls_per_host;
  foreach(@rec){
    $requests_per_host{$_->[1]}++;
    $bytes_per_host{$_->[1]} += $_->[4];
    $errors_per_host{$_->[1]}++ if $_->[3] =~ /^[45]/;
    $duplicate_urls_per_host{$_->[1]}{$_->[2]}++;
  }

  # Report on IP addresses that exceed predefined thresholds.
  foreach my $host (keys %requests_per_host){
    my $name;
    my $n;
    if($requests_per_host{$host} > $max_requests_per_host){
      if($requests_per_host{$host} > $max_requests_per_host){
        $name = dns($host);
        $n = add_commas($requests_per_host{$host});
        $report .=
        "$host$name made $n requests during the past 10 minutes.\n";
      }
    }
    if($bytes_per_host{$host} > $max_bytes_per_host){
      $name = dns($host);
      $n = add_commas($bytes_per_host{$host});
      $report .=
      "$host$name downloaded $n bytes during the past 10 minutes.\n";
    }
    if($errors_per_host{$host} > $max_errors_per_host){
      $name = dns($host);
      $n = add_commas($errors_per_host{$host});
      $report .=
      "$host$name generated $n errors during the past 10 minutes.\n";
    }
    foreach my $url (keys %{$duplicate_urls_per_host{$host}}){
      if($duplicate_urls_per_host{$host}{$url} > $max_duplicate_urls_per_host){

        next if $url =~ m#^/ICONS/#
        and     $duplicate_urls_per_host{$host}{$url} < 250;

        $name = dns($host);
        $n = add_commas($duplicate_urls_per_host{$host}{$url});
        $report .=
        "$host$name requested $url $n times during the past 10 minutes.\n";
      }
    }
  }

  if($report){
    open P,"|$sendmail" or die "Could not open pipe to $sendmail ($!)";

    print P
    "From: $return_addr\n",
    "To: $recipients\n",
    "Errors-To: $return_addr\n",
    "Subject: Report from calomel web access sentry\n",
    "\n",
    $report;

    close P or die "Error executing $sendmail ($!)";
  }

# USER CONFIGURABLE OPTIONS - time before the next log check and email alert
  sleep 120;

  if($inode != (stat $log)[1]){
    # If the inode number of the log file has changed, then assume that the
    # logs have been rotated and reopen the log file to pick up the new one.
    close LOG;
    open LOG,$log or die "Could not open $log ($!)";
    $inode = (stat LOG)[1];
  }
  else{
    # Otherwise just reset the end-of-file condition.
    seek LOG,0,1;
  }
}

sub dns{
  my $ip = shift;
  return $dns{$ip} if defined $dns{$ip} && $dns{$ip};
  my $lookup = `/usr/bin/host $ip 2>/dev/null`;
  my $name;

  if($lookup =~ /NXDOMAIN/
  or $lookup =~ /SERVFAIL/
  or $lookup =~ /timed out/
  ){
    $name = '';
  }
  else{
    $name = (split ' ',$lookup)[-1];
    $name =~ s/\.$//;
    $name = " ($name)";
  }
  $dns{$ip} = $name if $name;
  $name;
}

sub add_commas{
  # Add commas to a number string (e.g. 1357924683 => 1,357,924,683)
  my $num = reverse shift;
  $num =~ s/(...)/$1,/g;
  chop $num if $num =~ /,$/;
  reverse $num;
}

sub delta_time{
  my $sec = shift;
  my $day = int($sec/86400);
  $sec -= 86400 * $day;
  my $hour = int($sec/3600);
  $sec -= 3600 * $hour;
  my $min = int($sec/60);
  $sec -= 60 * $min;

  my %s;
  $s{d} = $day  == 1 ? '' : 's';
  $s{h} = $hour == 1 ? '' : 's';
  $s{m} = $min  == 1 ? '' : 's';
  $s{s} = $sec  == 1 ? '' : 's';

  my $interval;

  if($day > 0){
    $interval =
    "$day day$s{d} $hour hour$s{h} $min minute$s{m} and $sec second$s{s}";
  }
  elsif($hour > 0){
    $interval =
    "$hour hour$s{h} $min minute$s{m} and $sec second$s{s}";
  }
  elsif($min > 0){
    $interval =
    "$min minute$s{m} and $sec second$s{s}";
  }
  else{
    $interval = "$sec second$s{s}";
  }

  $interval;
}

#######################################################
###  moneyslow.com  calomel_web_sentry.pl  END
#######################################################

User Configurable Options

Step 2: Now, we need to look at the variables of the script that you can change to suit your environment. The example server this script is set to is going to have different timings and limits than you may, so lets look at each of the variables and explain what they mean. Keep in mind that all of the options you can change are superseded by the line, "USER CONFIGURABLE OPTIONS" and commented so you can find them easily.

The $log is the target access_log your web server is writing to.

# USER CONFIGURABLE OPTIONS - Web log target
my $log = '/var/log/web_server/access_log';

The following are the email sender and recipients. The $return_addr will set the mail header as the From: address. The $recipients are the people who will be receiving the sentry alert emails.

# USER CONFIGURABLE OPTIONS - email sender and recipients
my $return_addr = 'web_admin@your_hostname.com';
my $recipients = join ',',qw/
                 web_support@your_hostname.com
                 web_developers@your_hostname.com
                 /;

These are the timing thresholds. Rememer that these are the number of events that must occur with in the 600 seconds (10 minutes) of the rolling window to invoke an alert email. Take a look at the varable names as they describe the actions of the value associated with them.

# USER CONFIGURABLE OPTIONS - Thresholds
# Choose some thresholds designed to separate the
# miscreants from the well-behaved web users.
my $max_requests_per_host = 2000;
my $max_bytes_per_host = 2_000_000_000;
my $max_errors_per_host = 200;
my $max_duplicate_urls_per_host = 120;

This is the amount of time in seconds to sample the logs. Here we are looking at the past 600 seconds (10 minutes) of logs for our sample. Remember, this script looks the latest rolling 10 minute window of logs.

# USER CONFIGURABLE OPTIONS - Amount of time to watch the logs
  my $start = time - 600;               # Look at the past 10 minutes.

The $host varable will tell the script to ignore client ips listed here. For the example we have the script ignoring log entries from the internal LAN 192.168/16 and the ips from 10.10.10/24.

# USER CONFIGURABLE OPTIONS - Ignore internal hosts
    $host eq '::1' and next; # Ignore Apache generated requests from localhost.
    $host =~ /^192\.168\./ and next;    # Ignore the local net example #1
    $host =~ /^10\.10\.10/ and next;    # Ignore another net example #2

The $seconds_since_last_request varable will tell us the last time an ip hit the server that is _not_ on the ignore list. Our example server always expect to see a client request at least every 180 seconds as we are a very busy site. If we do not then something might be wrong. The problem might be access though a firewall is closed or the web daemon might have died or anything else. Either way we want to hear about it.

# USER CONFIGURABLE OPTIONS - Report if no client access has been seen for 180 seconds
  my $seconds_since_last_request = time - $most_recent;
  if($seconds_since_last_request > 180){
    # If too much time has elapsed, then report that something may be wrong.

This is the time the script will wait before looking at the newest log lines. Adjust this sleep time if you would like to reduce the amount of email alerts you get for a given amount of time. For example, the sleep time of 120 seconds means that if an offender is hitting your server you will get an alert every 120 seconds. Adjust for your level of paranoia and diligence.

# USER CONFIGURABLE OPTIONS - time before the next log check and email alert
  sleep 120;

Executing the daemon

Step 3: We now need to start the daemon. All you need to do is execute the calomel_web_access_sentry.pl perl script you downloaded from above and it will run in the background. You should run the daemon with a user who has the least amount of permissions, but can still read the web logs. This is just practicing safe system administration.

In Conclusion

You will now be notified of trouble makers abusing your server or if the normal amount of client access is down below expected levels. We suggest watching the email and logs for a week or so and formulating the patterns of traffic. Then you can edit the variables to better reduce the amount of false alarm emails you will get after first setting up the script.