Postfix maillog interpretation

[Leer este post en Español]

The logs generated by Postfix are stored in a file called maillog which is usually located under /var/log. Events configuration and location of this file is controlled by /etc/syslog with the following lines:

# Log all the mail messages in one place.
mail.* -/var/log/maillog

The level of debug recorded in this file is controlled by the “-v” (verbose), “-vv” (very verbose) and “-vvv” (very very verbose) parameters located under /etc/postfix/master.cf. The default debug level is set at “normal” which means these parameters are not present in this file. If you need so, you can increase this level by adding the corresponding parameter in the following line which is part of master.cf:

# ==========================================================================
# service type private unpriv chroot wakeup maxproc command + args
# (yes) (yes) (yes) (never) (100)
# ==========================================================================
smtp inet n – n – – smtpd -v

After any modification on the master.cf file you have to restart the whole Postfix engine with “postfix restart” (which is a command present on earlier versions) or with “postfix stop” and “postfix start” (on older versions). After the restart you can verify that postfix now logs more detail of every transaction it performs on the maillog file. Increasing this debug level is only recommended on situations where a problem can’t be easily identified, usually the default level will be enough to troubleshoot almost any problem your Postfix may present, but if you have to, just take in mind not to maintain the “-v” parameters for a very long time as the log will keep increasing and you may lose valuable data.

The maillog interpretation is not that difficult when you have identified the specific sections you want to review. Next, we’ll indicate how to identify each section on the log and the filters you may apply to find useful information faster.

 

General syntax of maillog

The following line represents the basic format in which information is logged into maillog:

Jan 2 11:15:39 tmcent01 postfix/smtpd[17397]: connect from unknown[127.0.0.1]

As you can see, the first section (in bold) indicates only the date and time in which the event was recorded. In production mail servers it is advisable for this information to be the most accurate, since any failure at this point may generate inconsistencies when correlating events.

Jan 2 11:15:39 tmcent01 postfix/smtpd[17397]: connect from unknown[127.0.0.1]

The next field shows the name of the server which is recording the event, in this case it is our own Postfix server.

Jan 2 11:15:39 tmcent01 postfix/smtpd[17397]: connect from unknown[127.0.0.1]

The next field is one of the most critical when troubleshooting mail flow or a Postfix failure. Here, you can see the service / proccess [PID] that was executing the operation recorded. This information can help you diferentiate each of the phases involved when Postfix receives, sends or process a specific mail. For example, from the line above we can assume that the daemon in execution was “smtpd” which is the daemon used by Postfix to receive mail, therefor we can assume we are reviewing an incoming mail transaction and additionally we have the PID of the daemon that received that mail. You can use that same PID for searching all the operation that specific daemon performed on the mail.

Jan 2 11:15:39 tmims8201 postfix/smtpd[17397]: connect from unknown[127.0.0.1]

Finally, the last field is just a description for the recorded event. Here you’ll be able to see status / error codes or textual descriptions for a more detailed interpretation.

With this information you can easily identify each of the steps involved in the receiving, sending and processing of a mail through the Postfix engine. Now let’s get the specific details of each of these sections and the log blocks.

 

Sections of Postfix maillog

The following lines show the maillog block when receiving a brand new mail.

Logs for an incoming mail:

1. Jan 2 20:31:02 tmcent01 postfix/smtpd[26524]: connect from unknown[192.168.75.1]
2. Jan 2 20:31:12 tmcent01 postfix/smtpd[26524]: B58C4330038: client=unknown[192.168.75.1]
3. Jan 2 20:31:17 tmcent01 postfix/cleanup[27426]: B58C4330038: message-id=<20120103023112.B58C4330038@tmcent01.training5.tm>
4. Jan 2 20:31:17 tmcent01 postfix/qmgr[26454]: B58C4330038: from=<asdf@asdf.com>, size=711, nrcpt=1 (queue active)
5. Jan 2 20:31:17 tmcent01 postfix/local[27450]: B58C4330038: to=<root@tmcent01.training5.tm>, orig_to=<postmaster>, relay=local, delay=9.7, delays=9.6/0.03/0/0.02, dsn=2.0.0, status=sent (delivered to mailbox)
6. Jan 2 20:31:17 tmcent01 postfix/qmgr[26454]: B58C4330038: removed

Lines 1 and 2 correspond to the reception of a new mail by Postfix. Line 1 records the name of the server and its IP address between brackets. Most of the time you’ll see the hostname as “unknown” when the DNS configured on Postfix is not able to resolve the right name, this is normal. Line 2 is recorded right after Postfix has successfully received the first RCPT TO command. You know a new mail is being received in these lines because the daemon that is recording is “smtpd” which is Postfix’s daemon for reception. All incoming mails in Postfix are saved in the “incoming” queue (/var/spool/postfix/incoming) and they are saved with postfix:postfix as owner and permissions of “600”. Also note that because the mail is being received first by a buffer in memory, the file will remain in “0 bytes” until it is successfully accepted by Postfix. For example:

-rw——-  1 postfix postfix    0 Feb 13 17:35 6AF9EC70400

Line 3 indicates the mail has successfully being received by the “smtpd” daemon and now the mail falls in the hands of the “cleanup”. At this point the mail is saved with its final size in the incoming queue. This daemon is responsible for correcting any syntax error in the mail structure which is not in compliance with RFC 822. These kind of corrections may include some of the following:

Symbols “<” and “>” are added if missing in the original mail. For example:

user@domain.com will be changed to “<user@domain.com>

The “Return-Path” header is added if missing in the original mail. In this case the value for the header is taken from the value of the MAIL FROM command.

The “Date” header is added if missing in the original mail. The value is taken from the actual date and time from the receiving MTA server (Postfix).

The “Message-ID” header is added if missing in the original mail. Its value is generated using the actual algorithms from the receiving MTA server (Postfix).

If the sender and/or recipient mailboxes do not contain a valid domain, cleanup will complete it with the value of the $myorigin variable.

The cleaning process takes place inside the incoming queue. To differentiate from cleaned and not cleaned mails, the cleanup daemon changes the permissions of the cleaned files to “700” as in the example below:

-rwx——  1 postfix postfix  2594 Feb 13 17:41 A945F2B8036

-rwx——  1 postfix postfix  2645 Feb 13 17:41 AB7882B803F

 

Line 4 indicates that syntax corrections are finished and now the mail is RFC 822 compliant, from this moment the mail falls into the hands of the “qmgr” daemon. This daemon is responsible for moving the mails left by qmgr to the appropriate queue. Qmgr is constantly reviewing which mails in the incoming queue have “700” permissions, and it sees a file like this it automatically sends it to the “active” queue. This is because any mail left by cleanup with “700” permissions is assumed to be ready for delivery to its final destination whether it is a local or external mail. In this line we can see the sender’s mailbox, the number of recipients, the total size of the mail (up to this moment, because the final size may change when it is received in the recipient’s mailbox) and the queue it is being moved to.

Line 5 shows the active daemon as “local”, this daemon is used when Postfix finds out that the domain in the recipient’s mailbox matches the value of $mydestination which is the internal domain of Postfix. This line is generated when the daemon has already tried to send the mail and reflects the result of this operation. In our example, the different fields are:

  • The real mailbox to which the mail was delivered to (this mailbox is the value of the RCPT TO command)
  • The type of relayed used (local means that this is an internal mail)
  • “delay” shows the total time spent in processing this mail since it is was received up to the moment the mail left the Postfix engine
  • “delays” shows the time spent by each daemon involved in the process in the following order: smtpd, cleanup, qmgr and local, in such cases where the mail is not internal, you will see the last time is that of the “smtp” daemon instead of “local”,
  • “dsn” indicates the response received by the final SMTP Server when it received or rejected the mail
  • “status” shows what was the result of the operation. Normal values for this field may be “sent”, “bounced” and “deferred”.

 

This information can be used to diagnosis a successful delivery or rejected transaction.

Line 6 indicates that it is no longer necessary to keep the original mail as it has been successfully sent, so now the “qmgr” daemon will drop the actual copy that is inside the “active” queue. At this point you can assume that the reception process was completed successfully.

Now let’s analyze the maillog lines when Postfix delivers a mail to external domains.

Outgoing mail logs

1. Jan 2 20:28:55 tmcent01 postfix/smtp[26597]: 1ED09330038: to=<administrator@training.tm>, relay=192.168.75.5[192.168.75.5]:25, delay=9.4, delays=9.2/0.02/0.02/0.2, dsn=2.6.0, status=sent (250 2.6.0 <20120103022852.1ED09330038@tmcent01.training5.tm> Queued mail for delivery)
2. Jan 2 20:28:55 tmcent01 postfix/qmgr[26454]: 1ED09330038: removed

When delivering mail, Postfix only logs two lines.

Line 1 corresponds to the “smtp” daemon which is used by Postfix to deliver mail. Here you can see all data transaction states. First of all we see the recipients’ mailbox. The “relay” field shows information about the MTA server that received the mail, it contains the server name and port in the following syntax: hostname[IP]:port.

The “delay” field indicates the total time Postfix spent in processing the mail since it was received up to its final delivery.  “Delays” shows the time spent by each daemon in the following order: smtpd, cleanup, qmgr and smtp. The “dsn” field shows the SMTP code received from the SMTP Server. The “status” field shows the actual response received by the SMTP Server when receiving our mail.

Line 2 confirms that our mail was successfully delivered to all recipients so now Postfix is free to drop its original copy of this mail. The “qmgr” daemon is responsible from deleting the mail from the “active” queue.

This information is useful to confirm a successfully mail delivery.

Based on the previous description let’s see now what filters we can use in order to identify more efficiently relevant information in our maillog.

 

Filtering Postfix maillog

In this section we’ll show you some filters that can help you find precise and specific information in your maillog file.

Identifying all connections made to Postfix

To identify all IP addresses that have connected to our Postfix servers just execute one or all of the following commands:

cat /var/log/maillog | grep ” connect from ”

This command will show you a complete list of all lines containing the IP addresses of all servers that have connected to our Postfix server.

cat /var/log/maillog | grep ” connect from ” | wc -l

The output of this command gives you the number of connections made to Postfix.

Both commands will give you the total number of connections that have been made to your Postfix server, however, in such cases where you’re using Postfix as a security layer for your real internal server, you may want to exclude such connections from the list above. In this case you can exclude such connections with the following command:

cat /var/log/maillog | grep ” connect from ” |grep -v 192.168.75.5

This command will give you all lines of Postfix containing a record of all the IP addresses that have connected to Postfix except for your internal mail server, in this case our internal mail server has IP 192.168.75.5, just change this IP to reflect your own server.

cat /var/log/maillog | grep ” connect from ” |grep -v 127.0.0.1 |grep –v 192.168.75.5

This command gives you the same result except that it also excludes the local address of Postfix. This is useful when you are using Postfix as part of your Gateway security solution. Trend Micro’s IMSVA solution for example uses Postfix as its MTA so it is useful to filter the localhost and your internal mail addresses in order to get only external connections.

cat /var/log/maillog |grep ” connect from “|grep -v 192.168.75.5|wc -l

The output of this command gives you the number of lines instead of the whole list.

 

Identifying incoming mail in Postfix maillog

If you only need to identify your incoming mail, you can use the following commands.

cat /var/log/maillog |grep “relay=local” |grep “status=sent”

This command will give all lines of maillog where mail has been delivered locally in your Postfix server. If you add the “|wc –l” parameter at the end, you will get the number of lines instead of the whole list.

cat /var/log/maillog |grep “relay=192.168.75.5″ |grep “status=sent”

If you use Postfix as a relay for your internal server you can filter maillog using the IP of the internal mail server. In this example, the value “192.168.75.5” represents the IP of our internal server. Again, if you use the “|wc –l” parameter at the end of the command you’ll get the number of lines instead of the whole list.

Identifying outgoing mail in Postfix maillog

If you want to filter only your outgoing mail, you can use the same command used for incoming mail, you just have to exclude the records of your internal mail server as shown in the following examples.

cat /var/log/maillog |grep -v “relay=local” |grep “relay=” |grep “status=sent”

This command will give you a list of all outgoing mail successfully sent. If you add the “|wc –l” parameter at the end of the command you’ll get the number of mails instead of the list of records.

cat /var/log/maillog |grep -v “relay=192.168.75.5″ |grep “relay=” |grep “status=sent”

If you use Postfix as a relay for your internal domain, you can use this command to exclude the lines where Postfix successfully delivers mail to your internal server. You can use the “|wc –l” parameter at the end of this command to get a numeric value instead of a list of records.

 

Identifying mail not delivered by Postfix

You can use the following commands to identify any errors at the moment of a delivery transaction whether they be Postfix problems or external SMTP Server problems.

cat /var/log/maillog |grep -v “status=sent” |grep “relay=”

The output of this command will give you all lines of maillog where there was a problem for both internal and external delivery.

cat /var/log/maillog |grep -v “status=sent” |grep “relay=” |wc -l

This gives you the same result but with a numeric value.

cat /var/log/maillog |grep -v “status=sent” |grep “relay=local”

This command will show you all the maillog records where there was a problem with internal delivery only.

cat /var/log/maillog |grep -v “status=sent” |grep “relay=local” |grep wc -l

We get the same result with this command as the previous but with a numeric value.

cat /var/log/maillog |grep -v “status=sent” |grep -v “relay=local” |grep “relay=”

This command will give you a list of all outgoing mails that were not successfully delivered.

cat /var/log/maillog |grep -v “status=sent” |grep -v “relay=local” |grep “relay=” |wc -l

We get the same result with this command as the previous but with a numeric value.

cat /var/log/maillog |grep -v “status=sent” |grep -v “relay=192.168.75.5″ |grep “relay=”

If you use Postfix as a relay for your internal domain, you can exclude the IP address of your internal mail server with this command, just change the IP “192.168.75.5” for your own.

cat /var/log/maillog |grep -v “status=sent” |grep -v “relay=192.168.75.5″ |grep “relay=” |wc -l

Again, this command has the same result with a numeric value.

 

Identifying how many times the Postfix configuration has been reloaded

You can use this filters if you want to know how many times or the moment a postfix configuration has been reloaded. These lines don’t imply a service interruption because they are only a configuration reload.

cat /var/log/maillog |grep “reload”

This command will give a list of all records where the configuration of the main.cf file has been reloaded. This list can be useful to identify the date and time the engine has reloaded a configuration either manually or automatically. This list can also be used to identify the moment a potential change to your Postfix configuration has been made.

cat /var/log/maillog |grep “reload” |wc -l

You get the same result with this command but with a numerical value.
Identifying how many times Postfix has been restarted

You can use this filter if you want to know how many times and the exact moment of a Postfix restart. This line indicates that there was in fact a service interruption because Postfix was actually stopped.

cat /var/log/maillog |grep stopping

The output of this command will give a list of records that shows Postfix was stopped, so the availability of the service was in fact interrupted.

cat /var/log/maillog |grep stopping |wc -l

This command gives you the same result but with a numerical value.

cat /var/log/maillog |grep -e stopping -e starting

This command will show you a full Postfix restart because it is filtering both conditions “stopping” and “starting”. You can verify the exact time in between this pair of lines if you want to know how much time your mail service was down. Another interpretation could be this one: if you see two consecutive “starting” lines, then it means Postfix crashed unexpectedly  and was started either manually or automatically at the time indicated by the second line.

Clearing the maillog

If you need to clear the records of Postfix maillog to make some tests or just for mantainance, you can execute the following command.

# > /var/log maillog

This command will clear all the contents of maillog. This command can be executed without restarting Postfix.

 

 

Debugging the maillog

Postfix maillog file is the one that records all events related with the Postfix daemons, so if you need a debug, you don’t actually debug Postfix but the daemon you need debug information from. You need to know exactly which daemon you need to debug in order to get the appropiate information, once you know this you can make the proper configuation in the master.cf file. The following is a list of recommendation about the daemons and its uses.

  • smtpd. This daemon’s debug will give you more details about all incoming mails received by Postfix.
  • smtp. This daemon’s debug will give you more details about all outgoing mails delivered by Postfix.
  • cleanup. This daemon will give you more information about the clearing (protoco hygiene) performed on the processed mail.
  • qmgr. This daemon is the one that moves all mails within the several Postfix queues.

The debug is enabled by adding a “-v” at the end of the daemon defined in the configuration file /etc/postfix/master.cf. You can also use “-vv” and “-vvv” each of them increasing the debug information of the daemon.

Example:

smtp      inet  n       –       n       –       200       smtpd -v

 

 

Modify the behavior of maillog

There will be some times when you need to increase the amount of information recorded in the /var/log/maillog file, in these cases you can modify the /etc/logrotate.conf file with the right paremeters. By default, maillog rotates weekly or when a single maillog file reaches 10MB (10240k), the one that occurs first. If you want to keep information beyond these limits, for example, if you want records for more days or months then you can make one of the following configurations in /etc/logrotate.conf

The first option is to change the behavior of ALL logs managed by the syslog daemon, this configuration is the first one that appears on this file and will affect not only the maillog but all of them.

# rotate log files weekly
weekly
# keep 4 weeks worth of backlogs
rotate 4

The first field may receive the following values: daily, weekly, monthly and yearly. The field “rotate” indicates how many files can rotate, by default the maillog will generate 4 files:

maillog -> The actual log

maillog.1, maillog.2, maillog.3 y maillog.4 these contain the las rotated information.

The second option is to change only the configuration of the maillog without affecting the other ones. This method is the recommended and to apply it you have to locate the section of the maillog, the following lines show the default configuration.

/var/log/maillog{
size 10240k
postrotate
/usr/bin/killall -HUP syslogd
endscript
}

If you want this log to generate 10 files with past information and to rotate daily, you can apply this configuration instead.

/var/log/maillog{
   daily
   rotate 10  
   size 10240k
   postrotate
      /usr/bin/killall -HUP syslogd
  endscript
}

This configuration will save information for the last 10 days or at least the information contained in 10 files of 10MB each, whatever that happens first, giving a maximum of 100MB of information. If this is not enough you can increase the number of logs by adjusting the “rotate” parameter or increase the size of each file. The following configuation shows how to configure a maillog that saves information that rotates weekly with 5 files and that can handle a size of 100MB each. This configuration will save a maximum of 500MB of data.

/var/log/maillog{
   daily
   rotate 10   
   size 102400k
   postrotate
      /usr/bin/killall -HUP syslogd
  endscript
}

With this configuration you can adjust the information recorded by maillog by increasing or decreasing the amount of data saved in each rotated file.

 

For more information about the rules to create, transmit and process an email you can check out our publication on The SMTP Protocol Fundamentals.

Remember to send us your questions and comments to our Twitter account:@redinskala where you can find more information and security tips.

Thanks for your visit!

 

One thought on “Postfix maillog interpretation

  1. Pingback: Interpretación de maillog en Postfix | RedinSkala

Comments are closed.