Mar 28

Postfix Email Rejections (NOQUEUE)

Tags:

———————————————————————
– OVERVIEW / THOUGHT PROCESS –
———————————————————————

Emails are getting delivered to the addresses on the server, but not after being rejected multiple times and told to ‘try again later’ by postfix. Other servers, such as mac mail, yahoo and google are practically immediate from the time you hit the send button to the time you see the email in your account. I would like to have the same speed for email delivery. It currently takes around fifteen (15) minutes or so to go through the rejection, update and deliver process to receive an email. But let’s see if we can narrow down what’s causing this and fix it. NOTE: the rejection is because of additional security and spam filtering, therefore keep track of what you do while troubleshooting because you may find that you would rather have that security and time lag for receiving emails.

———————————————————————
– TROUBLE SHOOTING –
———————————————————————

The first thing I did was look at the log files (listed below under -THE LOGS- ) to see what was going on. I use ‘$ sudo tail -f /var/log/maillog’ so that I can see things in real-time.  NOTE: you can also replace the -f with a number (-10 or -20) to list the specified last part of the log file.

then, I copy/paste into a text document the sections that will help me troubleshoot this problem. In this case, I isolated one email address that I knew was attempting delivery.

there was no need for extra data, so I only copy/pasted one instance of the rejection… although there were multiples.

I knew it was going to take around fifteen (15) minutes for delivery, so I waited for it to ensure I had the entire picture.

I examined the rejection messages very carefully… word for word, looking for something that stood out

it was easy to see the ‘Please try later’ message, so I decided to work backwards from there

I was thinking that in order for it to tell it to try later, there had to be some sort of policy telling it to do so.

working backwards, I saw ‘Recipient address rejected’

does recipient refer to the sender or the receiver? Is it rejecting yahoo, or the email address on my server?

working further backwards, I saw ‘450 4.7.1’
There are error codes associated with the postfix main.cf file.

———————————————————————
– ANALYZE THE main.cf (/etc/postfix) –
———————————————————————

…one instance of this is: unknown_local_recipient_reject_code = 550
the main.cf file explains: “The default setting is 550 (reject mail) but it is safer to start with 450 (try again later) until you are certain that your local_recipient_maps settings are OK.”

when I did a ctl-f for local_recipient_maps, I found this note:
“NOTE: if you use this feature for accounts not in the UNIX password file, then you must specify “local_recipient_maps =” (i.e. empty) in the main.cf file, otherwise the SMTP server will reject mail for non-UNIX accounts with “User unknown in local recipient table”.

I use mysql to hold all of the email accounts on my server, so if it’s looking for UNIX users, it won’t find any.

Since I use mysql, I wanted to make sure that the domains that I host were being seen and trusted… so I tracked it down further.  I looked at the virtual settings for my domains to make sure:
virtual_alias_domains =
and
virtual_mailbox_domains = proxy:mysql:/etc/postfix/mysql/virtual_mailbox_domains.cf

These are two different settings, but if I added all of my virtual domains into the virtual_alias_domains, it would give me an error when I restarted postfix because it was finding all of the domains twice (also in virtual_mailbox_domains.cf).  I wasn’t fatal, but it was an unnecessary error.  So I went ahead and changed it back to what you see.

One thing that I notices while I was looking through the main.cf file was that the ‘#myhostname = virtual.domain.tld’ variable was commented out

this sparked a tad bit of interest… possibly off topic, but it could be related.

using the 50/50 troubleshooting method, I wanted to eliminate this half of the equation before moving on.

therefore I changed ‘#myhostname = virtual.domain.tld’ to ‘myhostname = mail.domain.com’ and restarted postfix.  It didn’t solve the problem, but it did make me feel better.

———————————————————————
– THE SOLUTION –
———————————————————————

Still working backwards from that code (450 4.7.1), I noticed that the log message from right before the NOQUEUE said greylist=abuse.

This sparked my interest.  The easiest way to try out this theory is to turn off greylisting.  After looking in my favorite forum for greylisting controls, I figured out that you could turn it off by changing the config file:

$ sudo nano /etc/policyd.conf

###########################
# GREYLISTING (functional) #
###########################
#
# enable greylisting default: on
#
# whether greylisting should be enabled or disabled.
#
# 1=on 0=off
GREYLISTING=1

#
# greylist rejection: default: “Please try later”
#
# what error message the connecting host will recieve
# when a new triplet has been created.
#
GREYLIST_REJECTION=”Please try later.”

After changing GREYLISTING=1 to GREYLISTING=0, the greylisting function was turned off.

Then I restarted policyd ($ sudo service policyd restart) to have the changes take effect.

After sending several emails to each of my virtually hosted email accounts, I was able to confirm that emails were delivered instantly …instead of taking anywhere from fifteen minutes to a few hours.

As I mentioned in the opening paragraph, there’s more to think about than just getting your emails quickly.  Check out the wikipedia reference page for greylisting to learn more:

https://en.wikipedia.org/wiki/Greylisting

———————————————————————
– THE LOGS (look for NOQUEUE) –
———————————————————————

# CONNECTION LOGS FOR REJECTION FROM INCOMING YAHOO EMAIL (email@yahoo.com)

$ sudo tail -f /var/log/maillog

# FIRST REJECTION WITH POLICY — PLEASE TRY LATER

Feb 22 18:49:29 mail postfix/smtpd[9717]: connect from unknown[98.139.213.151]
Feb 22 18:49:29 mail policyd: rcpt=122, greylist=abuse, host=98.139.213.151 (unknown), from=email@yahoo.com, to=email@domain.com, size=0
Feb 22 18:49:29 mail postfix/smtpd[9717]: NOQUEUE: reject: RCPT from unknown[98.139.213.151]: 450 4.7.1 <email@domain.com>: Recipient address rejected: Policy Rejection- Please try later.; from=<email@yahoo.com> to=<email@domain.com> proto=SMTP helo=<nm7-vm0.bullet.mail.bf1.yahoo.com>
Feb 22 18:49:29 mail postfix/smtpd[9717]: disconnect from unknown[98.139.213.151]

# UPDATE WITH POLICYD — GREYLIST=UPDATE — QUEUE ACTIVE TO DELIVER MESSAGE

Feb 22 18:52:59 mail postfix/smtpd[9999]: connect from unknown[98.139.213.151]
Feb 22 18:53:00 mail policyd: connection from: 127.0.0.1 port: 42793 slots: 0 of 2044 used
Feb 22 18:53:00 mail policyd: rcpt=123, greylist=update, host=98.139.213.151 (unknown), from=email@yahoo.com, to=email@domain.com, size=0
Feb 22 18:53:00 mail postfix/smtpd[9999]: 05C3B4241C: client=unknown[98.139.213.151]
Feb 22 18:53:00 mail postfix/cleanup[10004]: 05C3B4241C: message-id=<1361558778.36681.YahooMailNeo@web161301.mail.bf1.yahoo.com>
Feb 22 18:53:00 mail postfix/qmgr[8414]: 05C3B4241C: from=<email@yahoo.com>, size=3774, nrcpt=1 (queue active)
Feb 22 18:53:00 mail postfix/smtpd[9999]: disconnect from unknown[98.139.213.151]

# DELIVERY OF EMAIL

Feb 22 18:53:04 mail postfix/cleanup[10004]: 3417D424DC: message-id=<1361558778.36681.YahooMailNeo@web161301.mail.bf1.yahoo.com>
Feb 22 18:53:04 mail postfix/qmgr[8414]: 3417D424DC: from=<email@yahoo.com>, size=4427, nrcpt=1 (queue active)
Feb 22 18:53:04 mail postfix/smtpd[10016]: disconnect from mail.domain.com[127.0.0.1]
Feb 22 18:53:04 mail amavis[8547]: (08547-12) Passed CLEAN, LOCAL [98.139.213.151] [78.0.235.63] <email@yahoo.com> -> <email@domain.com>, Message-ID: <1361558778.36681.YahooMailNeo@web161301.mail.bf1.yahoo.com>, mail_id: TBd-2z2oya91, Hits: 1.902, size: 3770, queued_as: 3417D424DC, dkim_id=@yahoo.com,email@yahoo.com, 4193 ms
Feb 22 18:53:04 mail postfix/smtp[10007]: 05C3B4241C: to=<email@domain.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=4.7, delays=0.27/0.02/0/4.4, dsn=2.0.0, status=sent (250 2.0.0 from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 3417D424DC)
Feb 22 18:53:04 mail postfix/qmgr[8414]: 05C3B4241C: removed
Feb 22 18:53:04 mail postfix/pipe[10010]: 3417D424DC: to=<email@domain.com>, relay=dovecot, delay=0.43, delays=0.2/0/0/0.23, dsn=2.0.0, status=sent (delivered via dovecot service)
Feb 22 18:53:04 mail postfix/qmgr[8414]: 3417D424DC: removed

 

—————————————–

Always remember… WHAT IF AND WHY NOT?!?