Sendmail 8.14.0: Logging the GreetPause firing time

Following on from yesterday's discussion of new features in Sendmail 8.14.0, today I'm writing about Sendmail's GreetPause feature, and some additional logging for it that's been added in Sendmail 8.14.0.



Sendmail has supported pausing before displaying the greeting as an anti-spam measure since 8.13.0.

To use it, add a line like:

FEATURE(`greet_pause', `10000')

to your sendmail.mc file, and rebuild the sendmail.cf file. The delay is specified in milliseconds, so that example will cause Sendmail to delay for 10 seconds before displaying the greeting banner.

What that feature was introduced, Sendmail would log connections that fell foul of this check with this line:

rejecting commands from host [ip-addr] due to pre-greeting traffic

This is helpful in determining how many times the check fired (and therefore how many connections it's stopping). The hostname and IP address information can also be mined from the logs and used to update any blacklists or firewall rules you're maintaining -- if the site is going to trigger this block then you may as well prevent from connecting, and save some connection slots.

However, it doesn't tell give you any idea of what would happen if you were to increase or decrease the greeting pause time. Suppose you have the delay set to 10 seconds. It may be the case that all the violators are trying to send data within the first second. In which case a 10 second delay is going to penalise all connections for an unnecessary 9 seconds.

On the other hand, it might be the case that blocks because of a 10 second greet pause delay are spread out over the entire 10 seconds. In which case there isn't much opportunity to reduce the delay, and it could be argued that increasing the delay makes sense.

To be able to answer questions like this I sent in a patch, and from Sendmail 8.14.0 (or 8.13.5 if you enabled the _FFR_LOG_GREET_PAUSE feature) Sendmail now reports:

rejecting commands from host [ip-addr] due to pre-greeting traffic after num seconds

This is sufficient information to produce a histogram that shows the frequency of the delay at the time that connections are rejected because they triggered this check. Here's an example of what such a report might look like.

# == 1 connection
 Delay   Count          Histogram
     0  (    12)        ############
     1  (     9)        #########
     2  (    14)        ##############
     3  (     9)        #########
     4  (    11)        ###########
     5  (    27)        ###########################
     6  (     8)        ########
     7  (    13)        #############
     8  (     6)        ######
     9  (    11)        ###########

In this example it's clear that the pre-greeting checks are firing evenly across the range of delays -- with the exception at 5 seconds. There's a definite spike there. That could be inidicative of a particular popular piece of spam-ware that's configured to only wait 5 seconds before sending mail.

Here's the Perl script that produced that report. Happy spam hunting.

#!/usr/bin/perl

use strict;
use warnings;

use List::Util qw(max);

# Read maillog from stdin, produce histogram showing greetpause
# distribution

my %pauses    = ();
my $max_count = 0;

while(<>) {
    next unless $_ =~ /pre-greeting traffic after (\\d+) seconds/;
    $pauses{$1}++;
    $max_count = max($pauses{$1}, $max_count);
}

my $scale = int($max_count / 40) + 1;

print "# == $scale connection", $scale == 1 ? '' : 's', "\n";

print " Delay\\t Count\\t\\tHistogram\n";
foreach my $delay (sort keys %pauses) {
    printf "%6d\\t(%6d)\\t%s\\n", $delay, $pauses{$delay},
        '#' x ($pauses{$delay} / $scale);
}