Read Mail Logs

From Postmaster Administration Wiki
Jump to: navigation, search

Mail server logs can be a dense mass of information – sometimes terse, other times verbose. On high-volume mail servers, the logs can grow very quickly and related information is spaced sparsely apart. Typically mail servers will log two or more lines of information for every SMTP, POP, or IMAP connection. For our purposes, we will focus on SMTP logs since they tend to be the most interesting.

A mail server logs information when a new client connection arrives, whether it was accepted, rejected, or disconnected, and logs information when the client connection terminates cleanly or drops a connection. With SMTP, the client connection details contain SMTP session information, while each mail transaction logs information such as sender address, each recipient address, and whether the message was accepted, rejected, discarded, or other. Each MTA varies in what it logs and when.

In the case of Sendmail, with standard log level settings, for each mail transaction log one line with the sender address, the from= line, and one line per mail recipient, the to= line. In Sendmail and all other MTAs, log lines from multiple simultaneous transactions can interleave with each other, making it hard to find related lines visually. However, each log line contains a message transaction or queue ID, which can be used to thread related transaction lines from the mail log file using a text search tool like grep(1). Text searching, grep(1), and regular expressions are together a vast subject and won't be covered here.

A transaction ID is often found in the first Received header of a message following the id word. A Received header is prepended to every message by each mail server through which a message traverses.

A message's Received headers.

Return-Path: <>
Received: from ( [])
    by (8.14.5/8.14.3) with ESMTP id r3UJYYZr022013;
    Tue, 30 Apr 2013 21:34:34 +0200 (CEST)
Received: from ( [])
    by ( []) envelope-from <>
    with ESMTPS (TLSv1/SSLv3 cipher=RC4-SHA bits=128/128 valid=PASS) id p3YLYY1922249260ia; Tue, 30 Apr 2013 21:34:34 +0200
Received: by with SMTP id oi10so764104obb.10
        for <multiple recipients>; Tue, 30 Apr 2013 12:34:32 -0700 (PDT)

In our sample above, the message transaction ID is r3UJYYZr022013. We can use this ID to extract all the related log lines for the message using grep(1).

Threading Sendmail log lines.

# grep r3UJYYZr022013 /var/log/maillog
Apr 30 21:35:06 mx sendmail[22013]: r3UJYYZr022013: from=<>,
    size=2575, class="0", nrcpts=2, msgid=<>,
    proto=ESMTP, daemon=MTA, []
Apr 30 21:35:07 mx sendmail[21358]: r3UJYYZr022013: to=<>, delay=00:00:33,
    xdelay=00:00:00, mailer=local, pri=62737, dsn=2.0.0, stat=Sent
Apr 30 21:35:07 mx sendmail[21358]: r3UJYYZr022013: to=<>, delay=00:00:33,
    xdelay=00:00:00, mailer=local, pri=62737, dsn=2.0.0, stat=Sent

Pretty much every MTA, be it Sendmail, Postfix, Exim, BarricadeMX, etc., will generate multiple log lines per session and/or transaction. Some will use the session ID, which includes connection-related information, and thread all the mail transactions of the session together. Others will use the transaction ID to thread just one mail transaction and may or may not have additional session related information that could be used to thread multiple related transactions together.

The content of mail logs varies widely between different MTA software, though typically one can expect the connected client IP address, the sender mail address, and each recipient address to be logged. However, when diagnosing mail delivery problems, the information available depends on MTA implementation and how far mail delivery progressed before failing.