Blacklisted client: why did Postfix not reject this email?

Question

Answer

The best answer was on the postfix-users mailing list and it is summarized here for the benefit of serverfault's users.

• I had forgotten soft_bounce = yes. Always switch it back to no after validating the configuration
• When asking for help about Postfix configuration, always include the complete output of postconf -n
• Stop accepting mail AT ALL from IPs that have no PTR records. Add reject_unknown_reverse_client_hostname to smtpd_recipient_restrictions AFTER permit_mynetworks and permit_sasl_authenticated

If the reply code is 4xx, it invites the other mail server to retry. The IP address seems to be used by a "snowshoe" spammer, making detection harder. Those IP addresses flicker in and out of the blacklist as blacklist operators (Spamhaus in this case) are working to counter the snowshoers' tactics. It is an ongoing, global arms race. Rejecting mail from IPs that have no PTR records reduces significantly the size of the local battlefield.

Original Question

This is logged on a low usage, personal Postfix server. I believe there should be two reasons to reject emails based on the headers below, but the outcome is a delivery to INBOX. Excerpts of the relevant Postfix configuration follows and my questions are at the end.

Log Exercerpt

Jun  5 09:58:37 x2 postfix/smtpd[8440]: connect from unknown[157.52.162.99]
Jun  5 09:58:37 x2 postfix/smtpd[8440]: NOQUEUE: reject: RCPT from unknown[157.52.162.99]: 454 4.7.1 Service unavailable; Client host [157.52.162.99] blocked using zen.spamhaus.org; from=<newsletter@vacque.com> to=<XXX@XXX> proto=ESMTP helo=<mr99.dgnmkt.com>
Jun  5 09:58:37 x2 postfix/smtpd[8440]: disconnect from unknown[157.52.162.99]
Jun  5 10:01:57 x2 postfix/anvil[8394]: statistics: max connection rate 1/60s for (smtp:198.2.130.200) at Jun  5 09:51:57
Jun  5 10:01:57 x2 postfix/anvil[8394]: statistics: max connection count 1 for (smtp:198.2.130.200) at Jun  5 09:51:57
Jun  5 10:01:57 x2 postfix/anvil[8394]: statistics: max cache size 2 at Jun  5 09:55:18
Jun  5 10:06:39 x2 postfix/smtpd[8507]: connect from unknown[157.52.162.99]
Jun  5 10:06:40 x2 policyd-spf[8513]: None; identity=helo; client-ip=157.52.162.99; helo=mr99.dgnmkt.com; envelope-from=newsletter@vacque.com; receiver=XXX@XXX
Jun  5 10:06:40 x2 policyd-spf[8513]: Pass; identity=mailfrom; client-ip=157.52.162.99; helo=mr99.dgnmkt.com; envelope-from=newsletter@vacque.com; receiver=XXX@XXX
Jun  5 10:06:40 x2 postfix/smtpd[8507]: 49D01C1EDE: client=unknown[157.52.162.99]
Jun  5 10:06:40 x2 postfix/cleanup[8514]: 49D01C1EDE: message-id=messageid-3-M3w1NDIzfDU4fDM3ODk3OTR8eWxlYmF5Y2EwNEBzZmluYS5jb218U2F0LCAwNCBKdW4gMjAxNiAwNToxNDowNyAtMDcwMA==
Jun  5 10:06:40 x2 opendkim[1220]: 49D01C1EDE: [157.52.162.99] [157.52.162.99] not internal
Jun  5 10:06:40 x2 opendkim[1220]: 49D01C1EDE: not authenticated
Jun  5 10:06:43 x2 opendkim[1220]: 49D01C1EDE: no signature data
Jun  5 10:06:43 x2 postfix/qmgr[1337]: 49D01C1EDE: from=<newsletter@vacque.com>, size=91945, nrcpt=1 (queue active)
Jun  5 10:06:43 x2 postfix/smtpd[8507]: disconnect from unknown[157.52.162.99]
Jun  5 10:06:43 x2 dovecot: lmtp(8516): Connect from local
Jun  5 10:06:43 x2 dovecot: lmtp(8516, YYY@XXX): nhVjEfMxVFdEIQAAzX/GXw: msgid=messageid-3-M3w1NDIzfDU4fDM3ODk3OTR8eWxlYmF5Y2EwNEBzZmluYS5jb218U2F0LCAwNCBKdW4gMjAxNiAwNToxNDowNyAtMDcwMA==: saved mail to INBOX
Jun  5 10:06:43 x2 postfix/lmtp[8515]: 49D01C1EDE: to=<YYY@XXX>, orig_to=<XXX@XXX>, relay=XXX[private/dovecot-lmtp], delay=3.6, delays=3.5/0.01/0.02/0.05, dsn=2.0.0, status=sent (250 2.0.0 <YYY@XXX> nhVjEfMxVFdEIQAAzX/GXw Saved)
Jun  5 10:06:43 x2 dovecot: lmtp(8516): Disconnect from local: Successful quit
Jun  5 10:06:43 x2 postfix/qmgr[1337]: 49D01C1EDE: removed

Notes About the Log

• @XXX is my domain
• XXX@XXX is an alias
• YYY@XXX is a mailbox
  • My understanding is that the bad sender [157.52.162.99] has been blocked at 9:58:37 based on zen.spamhaus.org, but 8 minutes later it reconnected and delivered successfully what should have not passed through.

Headers of the Mail That Should Have Been Rejected

Return-Path: <newsletter@vacque.com>
Delivered-To: <YYY@XXX>
Received: from XXX
by XXX (Dovecot) with LMTP id nhVjEfMxVFdEIQAAzX/GXw
for <YYY@XXX>; Sun, 05 Jun 2016 10:06:43 -0400
Received-SPF: Pass (sender SPF authorized) identity=mailfrom; client-ip=157.52.162.99; helo=mr99.dgnmkt.com; envelope-from=newsletter@vacque.com; receiver=XXX@XXX
Received: from mr99.dgnmkt.com (unknown [157.52.162.99])
by XXX (Postfix) with ESMTP id 49D01C1EDE
for <XXX@XXX>; Sun,  5 Jun 2016 10:06:39 -0400 (EDT)
Received: from stormmta (unknown [157.52.162.99])
by mr99.dgnmkt.com (Postfix) with ESMTP id DD84AE61F8A
for <XXX@XXX>; Sun,  5 Jun 2016 08:16:33 -0700 (PDT)
From:=?UTF-8?B?VG1hcnQuY29t?=<newsletter@e.ailander.com>
To:XXX@XXX

Postfix Configuration

Relevant main.cf Options

smtpd_recipient_restrictions =
  permit_mynetworks
  permit_sasl_authenticated
  reject_unauth_destination
  reject_invalid_hostname
  reject_non_fqdn_hostname
  reject_non_fqdn_sender
  reject_non_fqdn_recipient
  reject_unknown_sender_domain
  reject_unknown_recipient_domain

  check_recipient_access hash:/etc/postfix/recipients
  # used to have Postgrey here
  # check_policy_service inet:127.0.0.1:10023
  reject_rbl_client zen.spamhaus.org
  check_policy_service unix:private/policy-spf
  permit

smtpd_restriction_classes =
  ebay

ebay =
  check_reverse_client_hostname_mx_access pcre:/etc/postfix/ebay.pcre

/etc/postfix/recipients

XXX@XXX ebay

ebay.pcre

/.ebay.com$/ DUNNO
/(.*)/  REJECT Not allowed to relay from $1.  Please use eBay's contact form if you have legit communication for this email address.

My Comments and Questions

I assign aliases to isolate sources of mail. One such alias is assigned to eBay. eBay leaks buyer's email address to merchants. Not all merchants respect buyers' communication preferences. My solution is to restrict the emails accepted on the eBay alias to emails from eBay and reject all noise.

First, I thought that this email should have been rejected by:

  check_recipient_access hash:/etc/postfix/recipients

because following /etc/postfix/recipients the ebay restriction apply and ebay.pcre would have caught it on the second line.

Second, I thought that this email should have been rejected by:

  reject_rbl_client zen.spamhaus.org

like the attempt a few minutes earlier.

Obviously what I expected did not happen. Why? And how can I fix it?

Answer 1

If you like to block the IP of the sending client, than you will have to set up the RBLs in ...

smtpd_client_restrictions = permit_mynetworks,
        permit_sasl_authenticated,
        reject_unauth_destination,
        reject_rbl_client zen.spamhaus.org,
        reject_rbl_client bl.spamcop.net,
        reject_rbl_client cbl.abuseat.org,
        permit

The sequence in Postfix' restrictions is always

• smtpd_helo_restrictions
• smtpd_client_restrictions
• smtpd_sender_restrictions
• smtpd_recipient_restrictions

Answer 2

From what I see it looks like Spamhouse has answered differently second time. I.e. first answer was "there is a spammer", but 8 minutes later answer was "there is nothing special". Why it was answered it is hard do say.

If you have access do DNS server query logs which is set to resolve your mail server's dns queries, you might find some clues there. For example, Spamhouse provides service according to their policies, which state some limits for how many queries per hour, per month and so on you can make. They even could evaluate to whom they provide service this time and opt to not give meaningful answers to those who they consider as spammers.

Probably, you'd send this log directly to Spamhouse and they could speak for themselves.

But! It is hard to say exactly without seeing detailed debug level 2 where Postfix logs query information for each statement in each XXX_restriction option. The exact rbl reply would have been also logged there.

Also, the way you presended the Postfix config is wrong. You should always give complete output from the "postconf" command. This is what Postfix developers require in their mailing list and there are reasons to do so.