Email Statistics

From SME Server
Revision as of 15:31, 10 May 2019 by Mmccarn (talk | contribs) (→‎Display messages that would have been blocked via DNSBL: fix typo)
(diff) ← Older revision | Latest revision (diff) | Newer revision → (diff)
Jump to navigation Jump to search

Various options for monitoring your mail server performance

Built-In Email Reports

Some email statistics can be seen from server-manager under "Administration", "Mail log file analysis"

qpsmtpd: Incoming SMTP traffic

SME 7.2 and later include the 'logterse' plugin to qpsmtpd as well as the 'qplogsumm.pl' statistics script.

All in-bound SMTP connections are handled by qpsmtpd. In addition to the qplogsumm summary information described here, you can view the raw qpsmtpd logs as described in Mail_log_file_analysis.

qplogsumm.pl

qplogsumm.pl updates /var/log/qpsmtpd/state with per-plugin statistics for any qpsmtpd plugin that appears in a qpsmtpd logterse entry each time the qpsmtpd log is rotated.

Sample output here

e-smith-viewlogfiles-1.8.0-4 (released Nov 28 2007) or later will allow you to 'View' /var/log/qpsmtpd/state from 'View log files' in the server-manager (earlier versions conceal all files named "state" - Bug 3416).

Enable qplogsumm

qplogsumm.pl is disabled by default in smeserver-qpsmtpd-1.2.1-52.el4.sme and later (Bug 3727). Enable it with 

config setprop qpsmtpd qplogsumm enabled
signal-event email-update

Force first log rotation

qplogsumm.pl only updates its statistics when the qpsmtpd log file is rotated. This can take several days on a moderately busy server, and could take weeks or months on some servers.

You can force a rotation of the qpsmtpd log files in order to generate initial data in /var/log/qpsmtpd/state using 

sv alarm /service/qpsmtpd/log

Potential Problems

/var/log/qpsmtpd/state missing

qplogsumm.pl will completely lock all in-bound email if /var/log/qpsmtpd/state is missing when multilog attempts to rotate the qpsmtpd log file (Bug 3393). This will never happen under normal circumstances - only in the event of a disk error or if the administrator moves or deletes the existing file. If this does happen, the problem can be resolved using 

 touch /var/log/qpsmtpd/state
 sv restart /var/log/qpsmtpd
Unprocessed Log Files

If qpsmtpd is terminated abnormally (due to a power failure, for example), the log files may not be completely "processed". If this happens, you will have files in /var/log/qpsmtpd with names like the one shown below, ending in .u: @4000000048ec03873b1a841c.u

The transactions in these .u log files will not be included in the summary information in /var/log/qpsmtpd/state

Configure number of Log Files kept for qmail

Allow for individual configuration for the number of qmail logfiles See Bugzilla:6292 

db configuration setprop qmail KeepLogFiles 7

db configuration show qmail 
qmail=service
   FilterOrder=enabled
   FilterType=maildrop
   KeepLogFiles=7
   MaxMessageSize=25000000
   status=enabled

signal-event post-upgrade; signal-event reboot

Enforce qmail logrotate via: 

sv alarm /service/qmail/log

qmail: Outgoing SMTP traffic

qmail log file analysis and some statistics are described in Mail_log_file_analysis

Note that since all spam filtering is done by qpsmtpd, qmail log files or analysis tools will contain spam filtering statistics.

Contribs & Addons

Brian Read's spamfilter-stats-7.pl

Brian Read's mailstats contrib analyzes your qpsmtpd log files and sends an email to the specified email address summarizing your SME server activity.

Full details can be found at mailstats

Qmail_Statistics_(AWStats)

Michael Weinberger has assembled a script that allows you to easily install awstats and configure it to provide email delivery statistics.

Full details can be found at Qmail_Statistics_(AWStats)

qplogtail

qplogtail is a script intended to help monitor /var/log/qpsmtpd/current and extract a concise but meaningful display of what the server is up to.

qplogtail extracts 6 kinds of information:

  1. Normal connections:
    28545 Accepted connection 4/30 from 86.139.2.73 ...
  2. Errors in violation of Instances:
    5146 Too many connections: 40 >= 40. Waiting one second.
  3. Errors in violation of InstancesPerIP:
    5320 hosts_allow plugin: Too many connections from 212.100.229.201: 6 > 5Denying connection.
  4. Messages blocked by any qpsmtpd plugin:
    15751 logging::logterse plugin: ` 82.210.181.241 241-pra-6.acn.waw.pl 241-pra-6.acn.waw.pl <Glasteinzhza@ask-it-here.com> dnsbl 903 http://www.spamhaus.org/query/bl?ip=82.210.181.241 msg denied before queued
  5. Messages queued for delivery:
    15587 logging::logterse plugin: ` 128.220.32.40 miami.deuvis.com miami.deuvis.com <aapple@deuvis.com> <c.wolf@ncxr.org> queued <200709270344.l8R3iq0b010299@deuvis.com> No, hits=-2.6 required=5.0_
  6. Connection time values from the connection_time plugin (if present)
    @4000000048641d5c0951f6a4 15110 connection_time plugin: Connection time from 209.74.246.66: 1.566 sec.

Each normal smtp transaction will generate two lines of output containing: 

msgid   remote_ip   x/40
msgid   remote_ip   dispostion   details

If you have the connection_time plugin installed, you will also get: 

msgid   remote_ip   timeconnected

Sample output: 

# qplogtail
14868   209.74.246.66   0/40
14868   209.74.246.66   check_basicheaders      msg denied before queued
14868   209.74.246.66   1.622 sec.
14879   200.127.59.114  0/40
14879   200.127.59.114  dnsbl   msg denied before queued
14879   200.127.59.114  2.874 sec.
14890   69.147.64.214   0/40
14890   69.147.64.214   queued  No, hits=-2.6 required=5.0_
14890   69.147.64.214   7.433 sec.


To install: 

cd /usr/local/bin
wget -O qplogtail http://bugs.contribs.org/attachment.cgi?id=2035
chmod 755 qplogtail

To run: 

qplogtail


Direct comments or questions to Bugzilla:3418

qploggrep

qploggrep allows you to search your existing qpsmtpd logs as though they had been generated by qplogtail, then display matching results.

To install: 

cd /usr/local/bin
wget -O qploggrep http://bugs.contribs.org/attachment.cgi?id=2034
chmod 755 qploggrep

Program Notes:

  • qploggrep cannot locate information that is not there. For example, since the dnsbl plugin drops the incoming connection before the remote server specifies the addressee, you cannot find any addressee information for messages blocked by dnsbl.
  • qploggrep uses a case-insensitive search, so qploggrep abc will locate lines containing abc, ABC, aBc, etc.
  • qploggrep outputs the original TAI64N timestamp for each log entry. You can convert the result to human readable format by piping the results through tai64nlocal

Examples:

  • Search all existing qpsmtpd logs for email to or from user@domain.tld and convert the output timestamp from TAI64N to a human readable format:
qploggrep user@domain.tld |tai64nlocal
  • Search for email to or from user@domain.tld that was denied by spamassassin:
qploggrep spamassassin | grep user@domain.tld
  • Display all qpsmtpd transactions denied due to dnsbl:
qploggrep dnsbl
  • Display the total connection time for all connections, sorted by connection time (assumes that you have installed and enabled the connection_time plugin):
qploggrep connection_time | sort -k 3 -n
  • Display all info from /var/log/qpsmtpd/* (note the space and dot)
qploggrep .
  • Show all lines recording "connection x of y", sorted by the number of concurrent connections
qploggrep "/`config getprop smtpd Instances` " | sort -k4

Qpsmtpd_connection_time

See qpsmtpd_connection_time

Useful Commands

Count messages denied by DNSBL Block Lists

This command:

  • asks you how many days of logfiles to scan
  • scans the logfiles closed in the days specified
  • counts the number of messages blocked by each DNS list that blocked an email.

The count (and the displayed value) is based on the content after "http://" and before the third "/" in the message section of the the log entry (which frequently differs from the value specified in the config db). 

if [ -z $DAYS ]; then DAYS=1; fi; \
echo -n "Days of logfiles to scan [$DAYS]: "; read NEWDAYS; \
if [ $NEWDAYS ]; then DAYS=$NEWDAYS; fi; \
awk -F"[\t]" ' /logterse.*dnsbl/ \
{                                \
split($8,msg,"/");               \
svc=msg[3];                      \
count[svc]++;                    \
count["Total"]++;                \
}                                \
END                              \
{                                \
for (j in count)                 \
print count[j] "\t" j;           \
}'                               \
$(find /var/log/qpsmtpd /var/log/sqpsmtpd -ctime -$DAYS -type f -name "@*" -o -name current)

Sample Output: 

19867	Total
3336	bbl.barracudacentral.com
369	www.dnsbl.manitu.net
27	www.nosolicitado.org
1859	www.spamcop.net
10918	www.spamhaus.org
3358	www.gbudb.com

Count messages by qpsmtpd disposition

Scan the qpsmtpd logfiles closed in the last X days and display counts of messages for each disposition (plugin name or 'queued') 

if [ -z $DAYS ]; then DAYS=1; fi; \
echo -n "Days of logfiles to scan [$DAYS]: "; read NEWDAYS; \
if [ $NEWDAYS ]; then DAYS=$NEWDAYS; fi; \
awk -F"[\t]" ' /logterse/ { svc=$6; count[svc]++; count["Total"]++; }  END  \
{ for (j in count) print count[j] "\t" j; }' \
$(find /var/log/qpsmtpd /var/log/sqpsmtpd -ctime -$DAYS -type f -name "@*" -o -name current) \
|sort -nr

Sample output: 

4213	Total
1830	dnsbl
1773	queued
524	tls
37	check_earlytalker
18	spamassassin
10	check_badmailfrom_patterns
9	check_goodrcptto
6	check_spamhelo
6	auth::auth_cvm_unix_local

I extended the above script to show % of each one: 

if [ -z $DAYS ]; then DAYS=1; fi; \
echo -n "Days of logfiles to scan [$DAYS]: "; read NEWDAYS; \
if [ $NEWDAYS ]; then DAYS=$NEWDAYS; fi; \
awk -F"[\t]" ' /logterse/ { svc=$6; count[svc]++; count["Total"]++; }  END \
{ for (j in count) print count[j] "\t" j "\t" expr count[j]/count["Total"]*100"%" ; }' \
$(find /var/log/qpsmtpd /var/log/sqpsmtpd -ctime -$DAYS -type f) \
|sort -n

Sample output of extended version: 

1       headers 0.00769468%
2       auth::auth_cvm_unix_local       0.0153894%
33      earlytalker     0.253924%
355     spamassassin    2.73161%
401     naughty 3.08556%
698     tls     5.37088%
774     rhsbl   5.95568%
1127    check_goodrcptto        8.6719%
1359    queued  10.4571%
8246    resolvable_fromhost     63.4503%
12996   Total   100%

Display messages that would have been blocked via DNSBL

This command has two objectives -

  1. Testing a new dnsbl service
    Show you what emails would have been blocked by a new dnsbl service.
    From time to time I try out new DNSBL services. Some of these generate instant complaints from my users about correspondents who can no longer send us email.
  2. Review queued messages from servers that are now listed
    Reviewing recently received emails that were queued by the mail server from hosts that are *now* listed on a dnsbl can be used to look for patterns that might help you tune your spam filter settings.

The command below will:

  • ask you how many days of logfiles to scan (logfiles closed in the last "x" days)
  • ask you for the DNSBL service to test (the dns domain used by the service)
  • scan your logs for messages NOT denied due to a dnsbl entry
  • look up the sending IP in the DNSBL service you are testing
  • output the following info for each matching entry:
    • Date and time of the email was logged by your server
    • The original disposition ("queued", or the denying plugin name)
    • The spamassassin score assigned to the message when it was logged (if available)*
    • The sender's email address (if available)*
    • The recipient email address (if available)*
    • The CURRENT** DNSBL results for the sending IP using the DNSBL service you specified
      • A Record
      • TXT Record

* The sender email, recipient email and spamassassin score can only be included if your mail server logged this information. For example, a message denied by "check_earlytalker" will not have a spamassassin score, sender email, or recipient email. A message denied by "check_smtp_forward" (if you use an internal mail server) will not have a spamassassin score, but will have sender and recipient.

** You may see emails that were queued by your mail server in the past that would be denied by DNSBL services you already use in the present. This indicates that your DNSBL service lists the indicated IP now, but did not list it when the email was received. You will also see some messages that were denied by a plugin that is processed by qpsmtpd before the dnsbl plugin, like "check_earlytalker", "require_resolvable_fromhost", etc.

You can use the output to decide if the new DNSBL service is appropriate for your users, or if it is too aggressive. 

if [ -z $DAYS ]; then DAYS=1; fi; \
if [ -z $TESTBL ]; then TESTBL=zen.spamhaus.org; fi; \
echo -n "Days of logfiles to scan [$DAYS]: "; read NEWDAYS; \
echo -n "DNSBL to test [$TESTBL]: "; read NEWTESTBL; \
if [ $NEWDAYS ]; then DAYS=$NEWDAYS; fi; \
if [ $NEWTESTBL ]; then TESTBL=$NEWTESTBL; fi; \
grep -h logging::logterse  $(find /var/log/qpsmtpd /var/log/sqpsmtpd -ctime -$DAYS -name "@*" -o -name current) \
|grep -v dnsbl.903 \
|tai64nlocal \
|awk -v DNSBL=$TESTBL -F"\t" '{split($1,intro," "); \
 intro[6] == "`" ? split(intro[7],ip,".") : split(intro[8],ip,"."); split($9,hits," "); \
 split( intro[2],time,"."); \
 print \
  "echo -ne \"" intro[1] " " time[1] \
  "\t" $6 \
  "\t" ip[1] "." ip[2] "." ip[3] "." ip[4] \
  "\t" (hits[2]) \
  "\tFrom: " gensub("[<>]","","g",$4) \
  "\tTo: " gensub("[<>]","","g",$5) \
  "\tA: `dig +short " ip[4] "." ip[3] "." ip[2] "." ip[1] "." DNSBL " |tr \"\n\" \",\" |sed \"s/,$//\" `"\
  "\tTXT: \" ; echo -e \"`dig +short txt " ip[4] "." ip[3] "." ip[2] "." ip[1] "." DNSBL "`\""}'\
 |bash\
 |grep 127\.0

List Recent Emails with sending IP

This command will list recently received emails and the IP address of the host that delivered them to your server. (I plan to expand this into a script I can run to mark email after it has been received if the sending server has been freshly listed in a DNSBL service.) 

DAYS=1; echo -n "Days of email to scan [$DAYS]: "; read NEWDAYS; \
find /home/e-smith/files/users -name *$(config get SystemName):* -ctime -$DAYS -exec egrep -H "^Received:\ from\ " "{}" \; |\
grep -v "$(config get LocalIP)" |\
egrep "HELO|EHLO" |\
awk -F"[():]" '{ print $1 "\t" $7}'

List email disposition by TLD

This command will look at your qpsmtpd log files for entries related to the TLD you enter, then tell you how those emails were handled. This can be useful to see how your server is processing emails with From or HELO fields using TLDs like ".faith", ".win", ".xyz", etc, which are being used by spammers to bypass some spamassassin tests.

This command requires qploggrep 

echo -n "TLD to review: "; read TLD; qploggrep $TLD\> |tai64nlocal |awk '{print $1 " "  $2 "\t" $4 "\t" $5 "\t" $6 "\t" $7}'

Count emails by TLD and disposition for today and yesterday

This command will scan all qpsmtpd log files closed in the last day, pull out entries dated today or yesterday, then count the dispositions applied to each message by TLD (".com", ".org", etc):

Place the entire command below in your clipboard then paste it into command shell on your server. Adding "|sendmail -t emailuser@yourserver.tld" will email the report to the selected email address. 

export LC_ALL=C;  \
mydate=$(date "+%Y-%m-%d")\|$(date -d "yesterday" "+%Y-%m-%d"); \
cat -v $(find /var/log/qpsmtpd /var/log/sqpsmtpd/ -ctime -1 -type f -name "@*" -o -name current) \
|tai64nlocal |egrep $mydate | grep -v ^# | \
awk -v date="$mydate" -v tots="                                   {{Total}}           " -F"[\t]" ' \
/logterse/ {split($4,ss,"."); ssn=0; for (i in ss) { ssn++}; \
sendtld=tolower( ss[ssn]); sub(">","",sendtld); \
tld=sprintf("%-20s",sendtld); plugin=sprintf("%-35s",$6); \
plugint=sprintf("%35s%-20s",$6" ","{Total}");\
countem=plugin tld; count[countem]++; count[plugint]++; count[tots]++; }  \
END  \
{ORS=""; print "Subject: Email Disposition on " date "\n\n\
Denying plugin or \"queued\"         TLD                     Count   Pct\n\
=================================  ====================  =======  =====\n";  \
for (j in count) { pct=sprintf("%2.1f",(count[j]/count[tots])*100); \
j ~ /Total/ ?  myORS= " (" pct "%)\n": myORS="\n"; \
printf "%s%9s%s",j,count[j],myORS |"sort -b" } }'

Sample output: 

Subject: Email Disposition on 2015-11-27|2015-11-26

Denying plugin or "queued"         TLD                     Count   Pct
=================================  ====================  =======  =====
check_badmailfrom_patterns         com                        23
check_badmailfrom_patterns         download                    1
check_badmailfrom_patterns         info                        1
check_badmailfrom_patterns         net                         2
check_badmailfrom_patterns         top                       120
check_badmailfrom_patterns         xyz                         2
        check_badmailfrom_patterns {Total}                   149 (8.4%)
check_earlytalker                                              5
                 check_earlytalker {Total}                     5 (0.3%)
check_goodrcptto                   com                        10
check_goodrcptto                   email                       1
                  check_goodrcptto {Total}                    11 (0.6%)
check_spamhelo                                                 3
                    check_spamhelo {Total}                     3 (0.2%)
dnsbl                              <                           5
dnsbl                              com                       104
dnsbl                              in                          2
dnsbl                              jp                          1
dnsbl                              net                         2
dnsbl                              top                        76
dnsbl                              za                          1
                             dnsbl {Total}                   191 (10.8%)
queued                             com                       183
queued                             net                        11
queued                             org                         2
queued                             za                          2
                            queued {Total}                   198 (11.2%)
rhsbl                              bid                        16
rhsbl                              biz                        10
rhsbl                              cc                          2
rhsbl                              com                       902
rhsbl                              date                       14
rhsbl                              download                   25
rhsbl                              in                          1
rhsbl                              info                        1
rhsbl                              net                        10
rhsbl                              org                         3
rhsbl                              racing                     12
rhsbl                              top                       198
rhsbl                              win                         1
rhsbl                              xyz                        12
                             rhsbl {Total}                  1207 (68.4%)
                                   {{Total}}                1764 (100.0%)
Retrieved from "https://wiki.koozali.org/index.php?title=Email_Statistics&oldid=38054"