How to debug Postfix?

If you’ve read about my tutorial on setting up Postfix, you should be able to send and receive emails now. But life never goes smooth always.  You may encounter this or that problem in using the email system. To solve problems quickly, you need some tips of debugging postfix. The log file (/var/log/maillog) is the main source to find useful information about problems. If you cannot find maillog on CentOS 7, you need to install rsyslog first. You can read this article on analyzing the log file. This is an in-depth article which is much better than the lengthy/tedious/not accurate  Q&As on stackoverflow. To get more information, you can add the following lines in main.cf

Postfix will generate more logs when it handles emails with the peer(xx.xx.xx.xx is the ip address of the peer). You can send an email from the ip address you specify as the debug_peer_list parameter, then read /var/log/maillog to see what happened. If you’ve known which specific daemon is making trouble, you can turn the verbose mode on for that daemon in master.cf. For example, the following will make smtpd to generate even more logs in /var/log/maillog.

Here are some tips on reading the log file:

1. First, find the line “connect from…” is where email receiving/relaying begins.
2. Second, the lines containing “>”  are where postfix sends messages to the peer. You can see the messages postfix sends in those lines.
3. Third, the lines containing “<” are where posfix receives messages from the peer. Also you can check what messages are being received on those lines.
4. Fourth, the lines containing “>>>…<<<” are where postfix checks the rules in main.cf. For example, the following line indicates postfix is verifying the rule:smtpd_recipient_restrictions =xxxx

>>> START Recipient address RESTRICTIONS <<<

Finally, I recommend you read this official debug guide .

Analyzing the mail log is sometimes an interesting work. For example, if you use postfix to send massive emails, your ip may get blacklisted. How do you know your Ip has been blacklisted? You can check it in the mail log.  The following line in /var/log/maillog indicates the sending ip has already been on the black list.

Mar  1 16:08:18 mailserver postfix/smtp[997]: 5B3B765EBD8: to=<sales@somecomapny.com>, relay=smtp.secureserver.net[68.178.213.37]:25, delay=118832, delays=118832/0.16/32/0, dsn=4.0.0, status=deferred (host smtp.secureserver.net[68.178.213.37] refused to talk to me: 554 p3plibsmtp02-07.prod.phx3.secureserver.net bizsmtp IB233. Connection refused. xx.xx.xx.xx has a poor reputation on Cloudmark Sender Intelligence (CSI). Please visit http://csi.cloudmark.com/reset-request/?ip=xx.xx.xx.xx to request a delisting.)

The line says: on Mar  1 16:08:18, on host mailserver, the service postfix, the process smtp(the process id 997), was delivering an email destined to sales@somecomapny.com, the next-stop smtp server (the relay) is smtp.secureserver.net, the delay of this email after it is received by postfix is 118832, the delays in various modules of postfix(smtpd, cleanup, qmgr and smtp) are 118832/0.16/32/0. The next-stop smtp server replies with  code 4.0.0 and an message saying the sending ip is blacklisted,and refuses to receive this email. So the email is now in deferred status.

We can find other sending failures in the mail log:

Mar  1 16:35:53 mailserver postfix/smtp[959]: 1F9ED12EDC0: to=<info@somecomapny.com>, relay=somecompany.com[174.127.110.121]:25, delay=112114, delays=112173/0.12/20/20, dsn=5.0.0, status=bounced (host somecompany.com[174.127.110.121] said: 550-Verification failed for <apache@mail.domainhostseotool.com> 550-The mail server could not deliver mail to apache@mail.domainhostseotool.com.  The account or domain may not exist, they may be blacklisted, or missing the proper dns entries. 550 Sender verify failed (in reply to RCPT TO command))

Here, you can see the email is rejected after our postfix sends the “RCPT TO” command to the peer smtp server. Why is the email rejected? Because the domain of the sender email mail.domainhostseotool.com does not exist. If you are confused about the difference between bounced email and deferred email, here you can find the answer. An email gets bounced because it has non-fixable error(in this case, the sender email is wrong). An email is deferred because of temporary issue(in our case, the sending ip is blacklisted). The common reasons why email is deferred are:

• recipient address does not exists(no route to host)
• recipient  host exists but can not connect(Connection timed out)
•  Sender address rejected: Domain not found
•  Client host rejected: cannot find your hostname(PTR not set)
• sender ip on blacklist
• Helo command rejected: Host not found
• too many connections from sending ip
• Name service error for name=recipient domain type=MX: Host not found, try again
•  server has reached its limit for processing requests from your host
• Sender address could not be verified

 

Postfix will continue to deliver the deferred emails until success or timed out. Postfix won’t waste time to send bounced email repeatedly as it is doomed to fail.

To understand the meanings of the messages in /var/log/maillog, you need to understand the roles of each postfix component(smtpd, cleanup, qmgr, lmtp, smtp, bounce, etc.) in delivering an email. The name of some components is rather confusing. For example, cleanup seems the last stop of the message as it “cleans up” something. But it is actually among the first components along the delivering chain. For email relay, the path of delivering an email is smtpd->cleanup->qmgr->smtp. For emails destined to local address, the path is smtpd->cleanup->qmgr->lmtp. We will analyze the whole process of delivering an email to a non-existed local mailbox(thus bounced).

May  7 06:57:08 myhost postfix/smtpd[19331]: connect from unknown[126.167.135.43]
May  7 06:57:59 myhost postfix/smtpd[19331]: warning: 43.135.167.126.dnsbl.njabl.org: RBL lookup error: Host or domain name not found. Name service error for name=43.135.167.126.dnsbl.njabl.org type=A: Host not found, try again
May  7 06:57:59 myhost postfix/smtpd[19331]: A62721C05DC: client=unknown[126.167.135.43]
May  7 06:58:30 myhost postfix/cleanup[19379]: A62721C05DC: message-id=<>
May  7 06:58:31 myhost postfix/qmgr[6304]: A62721C05DC: from=<support@domainhostseotool.com>, size=305, nrcpt=2 (queue active)
May  7 06:58:31 myhost postfix/local[19384]: warning: dict_nis_init: NIS domain name not set – NIS lookups disabled
May  7 06:58:31 myhost postfix/lmtp[19385]: A62721C05DC: to=<VIRTUAL@mail.domainhostseotool.com>, orig_to=<admin@domainhostseotool.com>, relay=mail.domainhostseotool.com[/var/lib/imap/socket/lmtp], delay=47, delays=46/0.01/0/0.33, dsn=5.1.1, status=bounced (host mail.domainhostseotool.com[/var/lib/imap/socket/lmtp] said: 550-Mailbox unknown.  Either there is no mailbox associated with this 550-name or you do not have authorization to see it. 550 5.1.1 User unknown (in reply to RCPT TO command))
May  7 06:58:32 myhost postfix/lmtp[19385]: A62721C05DC: to=<admin@domainhostseotool.com>, relay=mail.domainhostseotool.com[/var/lib/imap/socket/lmtp], delay=47, delays=46/0.01/0.33/0.21, dsn=5.1.1, status=bounced (host mail.domainhostseotool.com[/var/lib/imap/socket/lmtp] said: 550-Mailbox unknown.  Either there is no mailbox associated with this 550-name or you do not have authorization to see it. 550 5.1.1 User unknown (in reply to RCPT TO command))
May  7 06:58:32 myhost postfix/cleanup[19379]: 2EF901C05DE: message-id=<20200507065832.2EF901C05DE@mail.domainhostseotool.com>
May  7 06:58:32 myhost postfix/qmgr[6304]: 2EF901C05DE: from=<>, size=3151, nrcpt=1 (queue active)
May  7 06:58:32 myhost postfix/bounce[19387]: A62721C05DC: sender non-delivery notification: 2EF901C05DE
May  7 06:58:32 myhost postfix/qmgr[6304]: A62721C05DC: removed
May  7 06:58:32 myhost postfix/lmtp[19388]: 2EF901C05DE: to=<root@mail.domainhostseotool.com>, orig_to=<support@domainhostseotool.com>, relay=mail.review78.com[/var/lib/imap/socket/lmtp], delay=0.42, delays=0.17/0/0/0.25, dsn=5.1.1, status=bounced (host mail.domainhostseotool.com[/var/lib/imap/socket/lmtp] said: 550-Mailbox unknown.  Either there is no mailbox associated with this 550-name or you do not have authorization to see it. 550 5.1.1 User unknown (in reply to RCPT TO command))
May  7 06:58:32 myhost postfix/qmgr[6304]: 2EF901C05DE: removed

The line containing “connect from” is the beginning of the whole process. The line indicates connection from a remote ip address has been set up by the smtpd daemon. The smtpd associates an id A62721C05DC to this message. Using this id, you can track how the message flows through each component of postfix: smtpd->cleanup->qmgr->lmtp. postfix/lmtp talks to cyrus-imap server through a socket: /var/lib/imap/socket/lmtp. cyrus-imap server cannot find the mailbox corresponding to the recipient email address so it responds with dsn=5.1.1. postfix calls postfix/bounce to generate a sender non-delivery notification. postfix/bounce also attaches an id 2EF901C05DE to this notification message. This message goes through cleanup, qmgr, lmtp in order. Because the sender support@domainhostseotool.com also has not a mailbox in cyrus-imap, lmtp fails again. But this time, it won’t trigger the sending of the failure notification email as that would cause an endless loop. postfix/qmgr is responsible to remove all messages from the queue.

Occasionally, you may suspect somebody else is using your email system to send bulk spam emails. You can verify this by checking the mail log:

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

This will list all ips trying to connect to your email server to send emails. You should notice the time stamp in front of each line. If there are large number of connections in a short period, your email server is most likely abused by malicious guys.

How to find all successfully received incoming emails?

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

How to find all successfully delivered outgoing emails?

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

How to find all emails that are failed to deliver?

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

How to find all internal emails that are not delivered successfully?

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

How to find all outgoing emails that are failed to deliver?

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

Postfix maintains different queues for emails. The current ready-t0-go emails go to /var/spool/postfix/active; the deferred emails go to /var/spool/postfix/deferred. To delete all queued emails including active and deferred ones, use “postsuper -d ALL”; to just delete deferred emails from queue, use “postsuper -d ALL deferred”. To see all emails in queues, use “mailq” or “postqueue -p” (http://www.tech-g.com/2012/07/15/inspecting-postfixs-email-queue/). Postfix has other queues in /var/spool/postfix/ such as incoming queue, hold queue,maildrop queue, etc. This post details the usage of these queues. But I still have questions about the exact aim of these queues, for example, what is the difference between incoming queue and maildrop queue? How to clean up the emails in /var/spool/postfix/maildrop?