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.)
 
(24 intermediate revisions by 3 users not shown)
Line 1: Line 1:
−
The SME server manager provides access to most of the log files maintained by the system.
+
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
 +
 
 +
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</nowiki>
 +
 
 +
==== Recipients in best order for mailing lists ====
 +
<nowiki>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</nowiki>
 +
 
 +
==== Recipients statistics ====
 +
<nowiki>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</nowiki>
 +
 
 +
==== Sender statistics ====
 +
<nowiki>Senders
  
−
=== Recipients in best order for mailing lists ===
+
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.
  
−
=== Recipients statistics ===
+
mess    bytes    sbytes    rbytes  recips  tries        xdelay  sender</nowiki>
  
−
=== Sender statistics ===
+
==== Sender uids ====
 +
<nowiki>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.
  
−
=== Sendmail style log ===
+
mess      bytes    sbytes    rbytes  recips  tries        xdelay  uid</nowiki>
  
−
=== Successful delivery delay distribution ===
+
==== Sendmail style log ====
 +
Process and display the qmail log files in a format similar to sendmail's logs.
  
−
=== Summarize status of mail queue ===
+
Each transaction generates two lines, one with the ''from'' information and one with the ''to'' information.
−
'''Exception'''<br>
+
 
 +
==== Successful delivery delay distribution ====
 +
<nowiki>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</nowiki>
 +
 
 +
==== Summarize status of mail queue ====
 +
'''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.
 +
<nowiki>messages in queue: 0
 +
messages in queue but not yet preprocessed: 0</nowiki>
 +
 +
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]].
 +
 +
----
 +
[[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


Warning.png Warning:
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

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.

Retrieved from "https://wiki.koozali.org/index.php?title=Mail_log_file_analysis&oldid=24043"