Author: hjp Date: Sun Jun 3 01:39:03 2007 New Revision: 747 Added: contrib/charlesb/ contrib/charlesb/logterse/ contrib/charlesb/logterse/README.txt contrib/charlesb/logterse/logterse.pl contrib/charlesb/logterse/qplogsumm.pl Modified: contrib/README.contrib
Log: Added author folder for Charles Butcher and his logterse plugin. Modified: contrib/README.contrib ============================================================================== --- contrib/README.contrib (original) +++ contrib/README.contrib Sun Jun 3 01:39:03 2007 @@ -15,7 +15,6 @@ Current author folders are: -hjp = Peter J. Holzer <[EMAIL PROTECTED]> +hjp = Peter J. Holzer <[EMAIL PROTECTED]> vetinari = Hanno Hecker <[EMAIL PROTECTED]> - - +charlesb = Charles Butcher <[EMAIL PROTECTED]> Added: contrib/charlesb/logterse/README.txt ============================================================================== --- (empty file) +++ contrib/charlesb/logterse/README.txt Sun Jun 3 01:39:03 2007 @@ -0,0 +1,159 @@ +Subject: Annonuncing logterse - a new plugin +Date: Tue, 27 Feb 2007 19:53:55 +1100 + +Here is a new plugin that provides concise, informative log entries for +each message qpsmtpd processes. It is accompanied by a log analysis +tool that takes advantage of multilog's features, although you do not +_have_ to use it with multilog. + +The plugin and its analysis tool are available for the time being at +http://ncc.com.au/qpsmtpd/logterse + +I respectfully submit them for consideration by the All Powerful Ones +for inclusion in the SVN repository :-) + +They have been running in production for the last 150 days under +qpsmtpd 0.32 on my (admittedly lightly loaded) server. + +Enjoy!! + +Charles + + +The Problem: + +I want to know as much as I can about messages processed by qpsmtpd, +but to do so currently means logging at level 9. I do not want to +generate all this debug info in my logs. For one thing it makes it +hard to spot real problems in a production environment. + +For each message I want to log a single line that is easy to parse, +relatively easy to read, and contains as much info as possible about +the message; where it came from, who sent it, to whom it was addressed +and what happened to it. + + +The Solution: + +A plugin called "logterse" is the result. Despite the name it is not a +different logging subsystem, it is a plugin that generates a one-line +log entry when the fate of a message becomes known -- either denied or +queued. It uses John Peacock's idea from logging/adaptive to prefix +the entry with a unique character (backquote) so it can be extracted +easily from the main log, or diverted into a separate logfile using +multilog's selection capabilities. + + +The Advantages: + +Apart from reducing log volume and noise, logterse comes with +qplogsumm.pl which can be run on a logfile and give you cumulative +details of which plugins are doing the majority of the work. +It is also designed to take advantage of multilog; in this case the +feature that calls an external script to process the log file at log +rotation time, plus the ability to retain state across log rotations. +The log file format makes it a no-brainer to do your own log analysis +with anything from awk upwards. + +The Future: + +I would really like to be able somehow to cross-reference the log +entries in the qpsmtpd logs with qmail's logs to see what finally +happened to the queued messages. Right now there is no information I +can get from hook_queue to provide this missing link. I hope that with +0.33/0.40 I will be able to use hook_queue_post to get the code +returned by qmail-queue to add to the log entry. + + +How to use it: + +- invoke logterse from the config/plugins file the same as for any +plugin. + +- turn your log levels right down and enjoy the silence :-) +- if you're using multilog do something like this: + + multilog t !/path/to/qplogsumm ./main + +When the log is rotated qplogsumm will be run and its cumulative +statistics will be stored in ./main/state. The stored log will remain +unchanged. + +If you want a separate logfile with only the logterse entries in it you +can do this: + + multilog t ./main '-*' '+*` *' !/path/to/qplogsumm ./main/summ + +which will create a subdirectory of ./main called ./main/summ +containing only log entries with the backquote character. If you're +used to logging/adaptive its exactly the same approach. + +After your first log rotation the 'state' file in the log directory +will contain something like this (although the cumulative totals +will obviously be the same until further log rotations have been done): + +virus::klez_filter @40000000452a1c8e317e5b54 896 +spamassassin @40000000451d1fba18136614 156477 +tls @40000000451daf7b2a8f7c24 50 +virus::clamav @40000000451d218918e0b0c4 2212 +rcpt_ok @40000000451d20f01248715c 8253 +LOGFILE_EPOCH @40000000451d1f97259095b4 0 +check_earlytalker @40000000451d219e2b7db86c 30516 +require_resolvable_fromhost @40000000451d20472b984d1c 21344 +recipient_exists @40000000451d1fab3b72028c 115315 +count_unrecognized_commands @40000000451db8b1057aa044 141 +queued @40000000451d1f97259095b4 53658 +# +# Most recent logfile +# ------------------- +# +# Start : 2007-02-17 06:21:20 +# Finish : 2007-02-26 19:18:13 +# Elapsed: 9 days, 12 hours, 56 mins, 53 secs +# +# Total transactions : 24313 +# Average tx per hour: 106 +# +# Cumulative Totals +# ----------------- +# +# Start : 2006-09-29 13:28:55 +# Finish : 2007-02-26 19:18:13 +# Elapsed: 150 days, 5 hours, 49 mins, 18 secs +# +# Total transactions : 388862 +# Average tx per hour: 107 +# +# Most Recent Logfile Cumulative +Totals +# Disposition (plugin) Total Avg/Day Total +Avg/Day +# +------------------------------------------------------------------------ +---- +# recipient_exists 8991 36% 942 115315 29% + 767 +# spamassassin 7199 29% 754 156477 40% + 1041 +# queued 3831 15% 401 53658 13% + 357 +# require_resolvable_fromhost 1994 8% 209 21344 5% + 142 +# check_earlytalker 1593 6% 166 30516 7% + 203 +# rcpt_ok 552 2% 57 8253 2% + 54 +# virus::clamav 127 0% 13 2212 0% + 14 +# count_unrecognized_commands 22 0% 2 141 0% + 0 +# virus::klez_filter 4 0% 0 896 0% + 6 +# tls 0 0% 0 50 0% + 0 +# +------------------------------------------------------------------------ +---- +# TOTALS 24313 100% 2548 388862 100% + 2588 + Added: contrib/charlesb/logterse/logterse.pl ============================================================================== --- (empty file) +++ contrib/charlesb/logterse/logterse.pl Sun Jun 3 01:39:03 2007 @@ -0,0 +1,158 @@ +=pod + +=head1 SYNOPSIS + +logterse [prefix char] [loglevel level] + +This plugin is not a logging replacement, but rather an adjunct to the normal logging +plugins or builtin logging functionality. Specify it in config/plugins not +config/logging or you'll get "interesting" results. + +The idea is to produce a one-line log entry that summarises the outcome of a +transaction. A message is either queued or rejected (bizarre failure modes are +not of interest). What is of interest is the details of the sending host and the +message envelope, and what happened to the message. To do this we hook_deny and +hook_queue and grab as much info as we can. + +This info is then passed to the real logging subsystem as a single line with +colon-separated fields as follows: + +=over 4 + +=item 1. remote ip + +=item 2. remote hostname + +=item 3. helo host + +=item 4. envelope sender + +=item 5. recipient (comma-separated list if more than one) + +=item 6. name of plugin that called DENY, or the string 'queued' if message was accepted. + +=item 7. return value of DENY plugin (empty if message was queued). + +=item 8. the DENY message, or the message-id if it was queued. + +=back + +As with logging/adaptive, a distinctive prefix (the backquote character by default) is +used to make it easy to extract the lines from the main logfiles, or to take advantage +of multilog's selection capability as described in the logging/adaptive plugin: + +=head1 TYPICAL USAGE + +If you are using multilog to handle your logging, you can replace the system +provided log/run file with something like this: + + #! /bin/sh + export LOGDIR=./main + + exec multilog t n10 \ + $LOGDIR \ + '-*' '+*` *' $LOGDIR/summary + +which will have the following effects: + +=over 4 + +=item 1. All lines will be logged in ./main as usual. + +=item 2. ./main/summary will contain only the lines output by this plugin. + +=back + + +=head1 AUTHORS + +Written by Charles Butcher who took a lot from logging/adaptive by John Peacock. + +=head1 VERSION + +This is release 1.0 + +=cut + +# +# I chose tab as the field separator to help with human-readability of the logs and hopefully minimal +# chance of a tab showing up _inside_ a field (although they are converted if they do). +# If you change it here, remember to change it in qplogsumm.pl as well. +# +my $FS = "\t"; + + +sub register { + my ( $self, $qp, %args ) = @_; + + $self->{_prefix} = '`'; + if ( defined $args{prefix} and $args{prefix} =~ /^(.+)$/ ) { + $self->{_prefix} = $1; + } + + $self->{_loglevel} = LOGALERT; + if ( defined( $args{loglevel} ) ) { + if ( $args{loglevel} =~ /^\d+$/ ) { + $self->{_loglevel} = $args{loglevel}; + } + else { + $self->{_loglevel} = log_level( $args{loglevel} ); + } + } +} + + +sub hook_deny { + my ( $self, $transaction, $prev_hook, $retval, $return_text ) = @_; + + my $disposition = join($FS, + $prev_hook, + $retval, + $return_text, + ); + + $self->_log_terse($transaction, $disposition); + return DECLINED; +} + +sub hook_queue { + my ( $self, $transaction ) = @_; + + my $msg_id = $transaction->header->get('Message-Id') || ''; + $msg_id =~ s/[\r\n].*//s; # don't allow newlines in the Message-Id here + $msg_id = "<$msg_id>" unless $msg_id =~ /^<.*>$/; # surround in <>'s + my $disposition = "queued$FS$FS$msg_id"; + + $self->_log_terse($transaction, $disposition); + return DECLINED; +} + +sub _log_terse { + my ( $self, $transaction, $disposition ) = @_; + + my $recipients = join(',', $transaction->recipients); + + my $remote_ip = $self->qp->connection->remote_ip() || ''; + my $remote_host = $self->qp->connection->remote_host() || ''; + my $hello_host = $self->qp->connection->hello_host() || ''; + my $tx_sender = $transaction->sender() || ''; + + my @log_message; + + push(@log_message, + $remote_ip, + $remote_host, + $hello_host, + $tx_sender, + $recipients, + ); + + # + # Escape any $FS characters anywhere in the log message + # + map {s/$FS/_/g} @log_message; + + push(@log_message, $disposition); + + $self->log($self->{_loglevel}, $self->{_prefix}, join($FS, @log_message)); +} Added: contrib/charlesb/logterse/qplogsumm.pl ============================================================================== --- (empty file) +++ contrib/charlesb/logterse/qplogsumm.pl Sun Jun 3 01:39:03 2007 @@ -0,0 +1,271 @@ +#!/usr/bin/perl +# + +=pod + +=head1 SUMMARY + +Works with multilog to analyse and summarise log entries generated by the logterse plugin. It is designed +to be invoked by multilog at log-rotation time. This is specified by an argument to multilog similar to: + +=over 4 + +multilog t !/path/to/qplogsumm ./main + +=back + +When qplogsumm is invoked, each line will be echoed, meaning the stored log is unchanged, but summary +information will be written to fd 5 and so stored in the 'state' file by multilog. + +This file is fed in on fd 4 at the beginning of the next log rotation, so running totals, etc can be maintained. + +=head1 State file format: + +One entry per line containing three fields separated by whitespace: + +=over 4 + +=item 1. Disposition (plugin) name. + +=item 2. tai64n timestamp recording the first time it was seen in a log. + +=item 3. long-term running total. + +=back + +A disposition is effectively the plugin name that called DENY or the string 'queued' for +messages that made it through. + +A line containing a disposition name of LOGFILE_EPOCH and a timestamp for the earliest known log entry. + +Other derived data, such as percentages etc. can also appear in the file, commented +by a # character. This will be ignored on the next intake. + +=head1 AUTHOR + +Charles Butcher + +=head1 VERSION + +This is release 1.0 + +=cut + +use strict; +use POSIX qw(strftime); + + +my $FS = "\t"; # field separator used by logterse plugin +my %disp; # hash of dispositions + +if (open PREVIOUS, "<&4") +{ + while (<PREVIOUS>) + { + chomp(); + next if m/^#/; + next if m/^\s*$/; + my ($plug_name, $plug_epoch, $plug_cumulative) = split /\s+/; + my $c = { epoch => $plug_epoch, cum => $plug_cumulative, curr => 0 }; + $disp{$plug_name} = $c; + } + + close PREVIOUS; +} + +my $first_timestamp = 0; +my $last_timestamp = 0; + + +while (<>) +{ + print; + chomp; + next unless m/terse plugin/; + + my ($timestamp_part, $log_part) = split '`'; + my ($current_timestamp) = split /\s/, $timestamp_part; + $first_timestamp = $current_timestamp unless $first_timestamp; + $last_timestamp = $current_timestamp; + + my (@log_items) = split $FS, $log_part; + my $disposition = $log_items[5]; + next unless defined $disposition; + + if ($disp{$disposition}) + { + $disp{$disposition}->{curr} += 1; + } + else # a new plugin -- make a note of when it first appeared + { + my $c = { epoch => $current_timestamp, cum => 0, curr => 1 }; + $disp{$disposition} = $c; + } +} + + +# +# Set overall epoch +# +if (!exists $disp{'LOGFILE_EPOCH'}) +{ + my $c = { epoch => $first_timestamp, cum => 0, curr => 0}; + $disp{'LOGFILE_EPOCH'} = $c; +} + +my $current_total = 0; +my $cumulative_total = 0; + +open HOLDOVER, ">&5" and select HOLDOVER; + +# +# Output cumulative values for intake the next time a log is processed +# +for my $c (keys %disp) +{ + $disp{$c}->{cum} += $disp{$c}->{curr}; + $current_total += $disp{$c}->{curr}; + $cumulative_total += $disp{$c}->{cum}; + + printf "%-30.30s %s %12d\n", $c, $disp{$c}->{epoch}, $disp{$c}->{cum}; +} + +# +# Output current logfile stats +# + +my $current_elapsed = tai64diff($last_timestamp, $first_timestamp); + +printf "# +# Most recent logfile +# ------------------- +# +# Start : %s +# Finish : %s +# Elapsed: %s +# +# Total transactions : %9d +# Average tx per hour: %9d +", + tai64utc($first_timestamp), + tai64utc($last_timestamp), + seconds_to_days($current_elapsed), + $current_total, + $current_total / ($current_elapsed / 3600), + ; + +# +# Output cumulative log stats +# +my $cumulative_elapsed = tai64diff($last_timestamp, $disp{'LOGFILE_EPOCH'}->{epoch}); + +printf "# +# Cumulative Totals +# ----------------- +# +# Start : %s +# Finish : %s +# Elapsed: %s +# +# Total transactions : %12d +# Average tx per hour: %12d +", + tai64utc($disp{'LOGFILE_EPOCH'}->{epoch}), + tai64utc($last_timestamp), + seconds_to_days($cumulative_elapsed), + $cumulative_total, + $cumulative_total / ($cumulative_elapsed / 3600), + ; + + +# +# Output per-plugin stats +# + +print "# +# Most Recent Logfile Cumulative Totals +# Disposition (plugin) Total Avg/Day Total Avg/Day +# ----------------------------------------------------------------------------\n"; + +my $printf_format = "# %-30.30s %6d %3d%% %8d %10d %3d%% %8d\n"; + +foreach my $c (sort { $disp{$b}->{curr} <=> $disp{$a}->{curr} } keys %disp) +{ + next if ($c eq 'LOGFILE_EPOCH'); + + printf $printf_format, + $c, + $disp{$c}->{curr}, + $disp{$c}->{curr} / $current_total * 100, + $disp{$c}->{curr} / ($current_elapsed / 86400), + $disp{$c}->{cum}, + $disp{$c}->{cum} / $cumulative_total * 100, + $disp{$c}->{cum} / (tai64diff($last_timestamp, $disp{$c}->{epoch}) / 86400), + ; +} + +print "# ----------------------------------------------------------------------------\n"; +printf $printf_format, + 'TOTALS', + $current_total, + 100, + $current_total / ($current_elapsed / 86400), + $cumulative_total, + 100, + $cumulative_total / ($cumulative_elapsed / 86400), + ; + +exit 0; + + +sub tai64utc { + my ($s) = @_; + + # @400000003f6c7bc5253bf98c + # 0123456789012345678901234 + # 0 1 2 + # |-------------||------| + if (substr($s, 0, 2) eq '@4') { + my $ts = hex(substr($s, 2, 15)); + $s = strftime('%Y-%m-%d %H:%M:%S', gmtime($ts)); + } + return $s; +} + +# +# Return difference in seconds +# +sub tai64diff +{ + my ($s1, $s2) = @_; + + # @400000003f6c7bc5253bf98c + # 0123456789012345678901234 + # 0 1 2 + # |-------------||------| + if (substr($s1, 0, 2) eq '@4' and substr($s2, 0, 2) eq '@4') + { + my $ts1 = hex(substr($s1, 2, 15)); + my $ts2 = hex(substr($s2, 2, 15)); + return $ts1 - $ts2; + } + else + { + return 0; + } +} + + +# +# Return an english phrase representing a number of seconds +# +sub seconds_to_days +{ + my ($secs) = @_; + + my $phrase = sprintf "%d days, ", ($secs / 86400); + $secs %= 86400; + $phrase .= sprintf "%d hours, ", ($secs / 3600); + $secs %= 3600; + $phrase .= sprintf "%d mins, %d secs", ($secs / 60), ($secs % 60); +}
