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

