Difference between revisions of "Mail log file analysis"
From SME Server
Jump to navigationJump to search (use split() instead of substr() (old script always reported max=9). Add example showing how to scan "x" days of log files.) |
|||
| (15 intermediate revisions by 3 users not shown) | |||
| Line 1: | Line 1: | ||
| − | The SME server manager provides access to | + | 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. | This document describes the email-related log files and what they tell you. | ||
| Line 18: | Line 18: | ||
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. | 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. | ||
| − | === logterse === | + | ==== 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. | 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. | ||
| Line 24: | Line 24: | ||
* Select ''View log files'' in server-manager | * Select ''View log files'' in server-manager | ||
* Specify '''qpsmtpd/current''' (or another qpsmtpd log file) under ''Choose a log file to view'' | * Specify '''qpsmtpd/current''' (or another qpsmtpd log file) under ''Choose a log file to view'' | ||
| − | * Specify '''`''' (a single back-tick) under ''Filter Pattern (optional)'' | + | * Specify '''`''' (a single back-tick) under ''"Filter Pattern (optional)"'' |
* Click ''Next'' | * Click ''Next'' | ||
* Sample results are shown below | * Sample results are shown below | ||
| Line 36: | Line 36: | ||
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</nowiki> | 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</nowiki> | ||
| + | ==== 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. | ||
| + | |||
| + | (The single quotes on the first and last line make this a single command): | ||
| + | <nowiki>awk -v INSTANCES="/"$(config getprop smtpd Instances) 'BEGIN {max=0} | ||
| + | $0 ~ INSTANCES {split($5, count, "/"); count[1]>max?max=count[1]:max} | ||
| + | END {print max}' /var/log/qpsmtpd/current</nowiki> | ||
| + | |||
| + | Show the maximum connections in any log file closed in the last 3 days, and include the configured "qpsmtpd Instances" for your system: | ||
| + | <nowiki>awk -v INSTANCES="/"$(config getprop smtpd Instances) 'BEGIN {max=0} | ||
| + | $0 ~ INSTANCES {split($5, count, "/"); count[1]>max?max=count[1]:max} | ||
| + | END {print max INSTANCES}' $(find /var/log/qpsmtpd/ -name "@*" -ctime -3)</nowiki> | ||
| + | |||
| + | ===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: | ||
| + | <nowiki>config setprop qpsmtpd KeepLogFiles 20 | ||
| + | sv stop qpsmtpd | ||
| + | kill -HUP `cat /var/service/qpsmtpd/log/supervise/pid` | ||
| + | sv start qpsmtpd</nowiki> | ||
| + | |||
| + | The same method will work to change the logfile rentention for sqpsmtpd: | ||
| + | <nowiki>config setprop sqpsmtpd KeepLogFiles 20 | ||
| + | sv stop sqpsmtpd | ||
| + | kill -HUP `cat /var/service/sqpsmtpd/log/supervise/pid` | ||
| + | sv start sqpsmtpd</nowiki> | ||
| + | |||
| + | {{Warning box|Using a KeepFiles setting of 1 is an extreme setting only to be used for a specific test system with a low volume of emails.}} | ||
== qmail: Outgoing SMTP traffic == | == qmail: Outgoing SMTP traffic == | ||
| Line 46: | Line 75: | ||
'''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. | '''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''. | ''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''). | 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 === | + | ==== Basic Statistics ==== |
<nowiki>qtime is the time spent by a message in the queue. | <nowiki>qtime is the time spent by a message in the queue. | ||
| Line 80: | Line 110: | ||
Average concurrency: 0.000607221</nowiki> | Average concurrency: 0.000607221</nowiki> | ||
| − | === List outgoing messages and recipients === | + | ==== List outgoing messages and recipients ==== |
| − | === Reasons for deferral === | + | ==== Reasons for deferral ==== |
<nowiki>Reasons for deferral | <nowiki>Reasons for deferral | ||
| Line 89: | Line 119: | ||
* xdelay is the total xdelay on those deliveries.</nowiki> | * xdelay is the total xdelay on those deliveries.</nowiki> | ||
| − | === Reasons for failure === | + | ==== Reasons for failure ==== |
<nowiki>Reasons for failure | <nowiki>Reasons for failure | ||
| Line 99: | Line 129: | ||
</nowiki> | </nowiki> | ||
| − | === Reasons for success === | + | ==== Reasons for success ==== |
<nowiki>Reasons for success | <nowiki>Reasons for success | ||
| Line 108: | Line 138: | ||
del xdelay reason</nowiki> | del xdelay reason</nowiki> | ||
| − | === Recipient hosts === | + | ==== Recipient hosts ==== |
<nowiki>Recipient hosts | <nowiki>Recipient hosts | ||
| Line 119: | Line 149: | ||
sbytes mess tries xdelay host</nowiki> | sbytes mess tries xdelay host</nowiki> | ||
| − | === Recipients in best order for mailing lists === | + | ==== Recipients in best order for mailing lists ==== |
<nowiki>Recipients in the best order for mailing lists | <nowiki>Recipients in the best order for mailing lists | ||
| Line 128: | Line 158: | ||
avg tries recipient</nowiki> | avg tries recipient</nowiki> | ||
| − | === Recipients statistics === | + | ==== Recipients statistics ==== |
<nowiki>Recipients | <nowiki>Recipients | ||
| Line 139: | Line 169: | ||
sbytes mess tries xdelay recipient</nowiki> | sbytes mess tries xdelay recipient</nowiki> | ||
| − | === Sender statistics === | + | ==== Sender statistics ==== |
<nowiki>Senders | <nowiki>Senders | ||
| Line 153: | Line 183: | ||
mess bytes sbytes rbytes recips tries xdelay sender</nowiki> | mess bytes sbytes rbytes recips tries xdelay sender</nowiki> | ||
| − | === Sender uids === | + | ==== Sender uids ==== |
<nowiki>Sender uids | <nowiki>Sender uids | ||
| Line 167: | Line 197: | ||
mess bytes sbytes rbytes recips tries xdelay uid</nowiki> | mess bytes sbytes rbytes recips tries xdelay uid</nowiki> | ||
| − | === Sendmail style log === | + | ==== Sendmail style log ==== |
Process and display the qmail log files in a format similar to sendmail's logs. | 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. | Each transaction generates two lines, one with the ''from'' information and one with the ''to'' information. | ||
| − | === Successful delivery delay distribution === | + | ==== Successful delivery delay distribution ==== |
<nowiki>Distribution of ddelays for successful deliveries | <nowiki>Distribution of ddelays for successful deliveries | ||
| Line 180: | Line 210: | ||
doneby avg pct</nowiki> | doneby avg pct</nowiki> | ||
| − | === Summarize status of mail queue === | + | ==== Summarize status of mail queue ==== |
'''Exception!'''<br> | '''Exception!'''<br> | ||
This report does not process the log files, but instead examines and reports on the actual contents of the qmail queues. | This report does not process the log files, but instead examines and reports on the actual contents of the qmail queues. | ||
| Line 190: | Line 220: | ||
== Email Statistics == | == Email Statistics == | ||
More information on obtaining email performance statistics for your SME Server can be found in [[Email_Statistics]]. | More information on obtaining email performance statistics for your SME Server can be found in [[Email_Statistics]]. | ||
| + | |||
| + | ---- | ||
| + | [[Category:Howto]] | ||
| + | [[Category:Administration:Monitoring]] | ||
| + | [[Category:Mail]] | ||
Latest revision as of 14:05, 12 April 2014
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.
(The single quotes on the first and last line make this a single command):
awk -v INSTANCES="/"$(config getprop smtpd Instances) 'BEGIN {max=0}
$0 ~ INSTANCES {split($5, count, "/"); count[1]>max?max=count[1]:max}
END {print max}' /var/log/qpsmtpd/current
Show the maximum connections in any log file closed in the last 3 days, and include the configured "qpsmtpd Instances" for your system:
awk -v INSTANCES="/"$(config getprop smtpd Instances) 'BEGIN {max=0}
$0 ~ INSTANCES {split($5, count, "/"); count[1]>max?max=count[1]:max}
END {print max INSTANCES}' $(find /var/log/qpsmtpd/ -name "@*" -ctime -3)
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.
