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
