Mail log file analysis
The SME server manager provides access to almost all of the log files maintained by the system (a very few files are excluded that contain no useful information)
This document describes the email-related log files and what they tell you.
qpsmtpd: Incoming SMTP traffic
All in-bound SMTP connections are handled by qpsmtpd.
View log files
You can examine the qpsmtpd log files using View log files in the server-manager.
Raw qpsmtpd logs
Raw qpsmtpd logs are quite verbose, including a separate line of output for each process that is involved in receiving and analyzing the incoming message. The basic format of each log line is
timestamp processid log_information
At the default logging level (LogLevel 6) for qpsmtpd, there can easily be up to 28 lines of logged information for a single email message.
On a busy server handling up to 40 simultaneous in-bound email connections, this can result in highly interleaved and hard-to-read log files.
view only logterse entries
SME 7.2 and later include the 'logterse' plugin to qpsmtpd. logterse creates a one-line summary of each qpsmtpd transaction and writes it to the log file.
In order to view only these one-line-per-message summaries from the qpsmtpd log:
- Select View log files in server-manager
- Specify qpsmtpd/current (or another qpsmtpd log file) under Choose a log file to view
- Specify ` (a single back-tick) under "Filter Pattern (optional)"
- Click Next
- Sample results are shown below
- hopefully you will actually have some real email arriving at your server (not all dnsbl entries as shown here)
- results are <tab> delimited, so you can easily Copy and Paste Special / Text into Excel for further analysis
2008-11-08 06:32:46.354761500 26318 logging::logterse plugin: ` 89.223.216.72 apn-89-223-216-72.vodafone.hu apn-89-223-216-72.vodafone.hu <toshiter@donin.com> rhsbl 901 Not supporting null originator (DSN) msg denied before queued 2008-11-08 06:33:17.924158500 26331 logging::logterse plugin: ` 208.99.214.236 mx22.ecreditchoices7.com mx22.ecreditchoices7.com <moneydiet2@mx22.ecreditchoices7.com> dnsbl 903 http://www.spamhaus.org/SBL/sbl.lasso?query=SBL69049 msg denied before queued 2008-11-08 06:34:53.318459500 26358 logging::logterse plugin: ` 84.58.57.150 dslb-084-058-057-150.pools.arcor-ip.net rpemgmu.arcor-ip.net <sundered@ancientinc.com> dnsbl 903 http://www.spamhaus.org/query/bl?ip=84.58.57.150 msg denied before queued 2008-11-08 06:35:41.724563500 26375 logging::logterse plugin: ` 58.126.113.198 Unknown [58.126.113.198] <benny@surecom.com> rhsbl 901 Not supporting null originator (DSN) msg denied before queued 2008-11-08 06:37:31.730609500 26398 logging::logterse plugin: ` 87.103.146.91 pmsn.91.146.103.87.sable.dsl.krasnet.ru pmsn.91.146.103.87.sable.dsl.krasnet.ru <dwweem@wee.com> dnsbl 903 http://www.spamhaus.org/query/bl?ip=87.103.146.91 msg denied before queued 2008-11-08 06:37:41.211401500 26409 logging::logterse plugin: ` 87.103.146.91 pmsn.91.146.103.87.sable.dsl.krasnet.ru pmsn.91.146.103.87.sable.dsl.krasnet.ru <dwtrupsm@trups.com> dnsbl 903 http://www.spamhaus.org/query/bl?ip=87.103.146.91 msg denied before queued
Monitor simultaneous in-bound SMTP connections
The command below will show the maximum number of simultaneous in-bound SMTP connections to your server since the last time the qpsmtpd log was rotated. Replace "/current" with "/*" to get the maximum connection count in all existing qpsmtpd log files.
awk -v INSTANCES="/"$(config getprop smtpd Instances) \
' $0 ~ INSTANCES { if(max=="") {max=1}; if(substr($5,0,length($5)-length(INSTANCES))>max)\
{max=substr($5,0,length($5)-length(INSTANCES))}} END {print max}' /var/log/qpsmtpd/current
Allow for individual configuration of qpsmtpd and sqpsmtpd log file retention
Some users find that they want to be able to research email problems further back in time than the window covered by the default qpsmtpd logfile retention settings (10 logfiles retained, 5,000,000 bytes each). See Bugzilla: 6293 and Bugzilla: 2862
Beginning with smeserver-qpsmtpd-2.2.0-12.el5.sme (SME 8) you can increase the number of logfiles retained by qpsmtpd (to 20 in the examples below) using:
config setprop qpsmtpd KeepLogFiles 20 sv stop qpsmtpd kill -HUP `cat /var/service/qpsmtpd/log/supervise/pid` sv start qpsmtpd
The same method will work to change the logfile rentention for sqpsmtpd:
config setprop sqpsmtpd KeepLogFiles 20 sv stop sqpsmtpd kill -HUP `cat /var/service/sqpsmtpd/log/supervise/pid` sv start sqpsmtpd
qmail: Outgoing SMTP traffic
Once a message has been accepted by qpsmtpd it is handed to qmail for delivery.
- If the message is addressed to an email account hosted on your SME server, qmail delivers the file to the local mailbox.
- If the message is addressed to an email on a domain hosted on your SME that is configured to use an Internal MailServer, qmail delivers the message to the designated server.
- If the message is addressed to a remote email address, qmail either delivers the message directly to the recipient's mail server, or to the relay mail server value configured at server-manager::email::Address of internet provider's mail
Important: Since incoming messages will not reach qmail if they have been denied by any of the qpsmtpd spam-fighting features, you cannot get any spam blocking information from the qmail logs.
Mail log file analysis
Mail log file analysis in the server-manager provides access to several reports regarding qmail.
All of the reports below except for Summarize status of mail queue examine all of the current qmail log files (/var/log/qmail/@* and /var/log/qmail/current).
Basic Statistics
qtime is the time spent by a message in the queue. ddelay is the latency for a successful delivery to one recipient---the end of successful delivery, minus the time when the message was queued. xdelay is the latency for a delivery attempt---the time when the attempt finished, minus the time when it started. The average concurrency is the total xdelay for all deliveries divided by the time span; this is a good measure of how busy the mailer is. Completed messages: 213 Recipients for completed messages: 213 Total delivery attempts for completed messages: 250 Average delivery attempts per completed message: 1.17371 Bytes in completed messages: 4282486 Bytes weighted by success: 4282486 Average message qtime (s): 145.726 Total delivery attempts: 250 success: 213 failure: 0 deferral: 37 Total ddelay (s): 31039.462344 Average ddelay per success (s): 145.725175 Total xdelay (s): 36.762560 Average xdelay per delivery attempt (s): 0.147050 Time span (days): 0.700722 Average concurrency: 0.000607221
List outgoing messages and recipients
Reasons for deferral
Reasons for deferral One line per reason for deferral. Information on each line: * del is the number of deliveries that ended for this reason. * xdelay is the total xdelay on those deliveries.
Reasons for failure
Reasons for failure One line per reason for delivery failure. Information on each line: * del is the number of deliveries that ended for this reason. * xdelay is the total xdelay on those deliveries. del xdelay reason
Reasons for success
Reasons for success One line per reason for successful delivery. Information on each line: * del is the number of deliveries that ended for this reason. * xdelay is the total xdelay on those deliveries. del xdelay reason
Recipient hosts
Recipient hosts One line per recipient host. Information on each line: * sbytes is the number of bytes successfully delivered to this host. * mess is the number of messages sent to this host (success plus failure). * tries is the number of delivery attempts (success, failure, deferral). * xdelay is the total xdelay incurred by this host. sbytes mess tries xdelay host
Recipients in best order for mailing lists
Recipients in the best order for mailing lists One line per recipient, sorted by avg. Information on each line: * avg is the _average_ xdelay for the recipient. * tries is the number of deliveries that avg is based on. avg tries recipient
Recipients statistics
Recipients One line per recipient. Information on each line: * sbytes is the number of bytes successfully delivered to this recipient. * mess is the number of messages sent to this recipient (success plus failure). * tries is the number of delivery attempts (success, failure, deferral). * xdelay is the total xdelay incurred by this recipient. sbytes mess tries xdelay recipient
Sender statistics
Senders One line per sender. Information on each line: * mess is the number of messages sent by this sender. * bytes is the number of bytes sent by this sender. * sbytes is the number of bytes successfully received from this sender. * rbytes is the number of bytes from this sender, weighted by recipient. * recips is the number of recipients (success plus failure). * tries is the number of delivery attempts (success, failure, deferral). * xdelay is the total xdelay incurred by this sender. mess bytes sbytes rbytes recips tries xdelay sender
Sender uids
Sender uids One line per sender uid. Information on each line: * mess is the number of messages sent by this uid. * bytes is the number of bytes sent by this uid. * sbytes is the number of bytes successfully received from this uid. * rbytes is the number of bytes from this uid, weighted by recipient. * recips is the number of recipients (success plus failure). * tries is the number of delivery attempts (success, failure, deferral). * xdelay is the total xdelay incurred by this uid. mess bytes sbytes rbytes recips tries xdelay uid
Sendmail style log
Process and display the qmail log files in a format similar to sendmail's logs.
Each transaction generates two lines, one with the from information and one with the to information.
Successful delivery delay distribution
Distribution of ddelays for successful deliveries Meaning of each line: The first pct% of successful deliveries all happened within doneby seconds. The average ddelay was avg. doneby avg pct
Summarize status of mail queue
Exception!
This report does not process the log files, but instead examines and reports on the actual contents of the qmail queues.
messages in queue: 0 messages in queue but not yet preprocessed: 0
There should only be messages in the queues for a brief time while they are being processed, or longer if the destination mail server is down or if the destination email account has a temporary problem of some sort.
Email Statistics
More information on obtaining email performance statistics for your SME Server can be found in Email_Statistics.
