Postfix before-queue spam reject with amavis without sending out a bounce on OS X Server

amavisdsnemail-bouncesmac-osx-serverpostfix

This is a stock OS X 5.2 Server mail configuration which I'm trying to change to make it reject a spam message with a "554 5.7.0 Reject" before accepting it without sending out any additional non-delivery notifications to the sender. It's configured to accept spam with a "250 2.7.0 Ok" and later discard or quarantine it out of the box. That is usually done with

$final_spam_destiny       = D_REJECT;
$warnspamsender = 0; (probably not necessary)

and can be fine-tuned using

$sa_dsn_cutoff_level = X;
$sa_crediblefrom_dsn_cutoff_level = X;

The problem I'm having is that despite those cutoff levels being way less than the actual spam score for a particular message, the DSN/bounce still gets through. It looks like this:

Oct 25 11:52:18 mailbox postfix/smtpd[52962]: 1CD504D13C96: client=mail.informark.co.ua[85.25.13.92]
Oct 25 11:52:18 mailbox postfix/cleanup[53010]: 1CD504D13C96: message-id=<11a201d22e97$126f7740$2adb3d4f@ynmyfnj>
Oct 25 11:52:19 mailbox postfix/qmgr[52740]: 1CD504D13C96: from=<ynmyfnj@informark.co.ua>, size=145530, nrcpt=1 (queue active)
Oct 25 11:52:20 mailbox postfix/smtp[53011]: 1CD504D13C96: to=<xxx@xxx.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.2, delays=1.1/0/0.02/1, dsn=5.7.0, status=bounced (host 127.0.0.1[127.0.0.1] said: 554 5.7.0 Reject, id=52765-01 - spam (in reply to end of DATA command))
Oct 25 11:52:20 mailbox postfix/bounce[53022]: 1CD504D13C96: sender non-delivery notification: 4B9804D13CB0
Oct 25 11:52:20 mailbox postfix/qmgr[52740]: 1CD504D13C96: removed

Oct 25 11:52:20 mailbox postfix/cleanup[53010]: 4B9804D13CB0: message-id=<20161025085220.4B9804D13CB0@xxx.xxx.com>
Oct 25 11:52:20 mailbox postfix/qmgr[52740]: 4B9804D13CB0: from=<>, size=3019, nrcpt=1 (queue active)
Oct 25 11:52:20 mailbox postfix/bounce[53022]: 1CD504D13C96: sender non-delivery notification: 4B9804D13CB0
Oct 25 11:52:20 mailbox postfix/smtp[53015]: 4B9804D13CB0: to=<ynmyfnj@informark.co.ua>, relay=mail.informark.co.ua[85.25.13.92]:25, delay=0.58, delays=0/0/0.26/0.32, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 9145D8C8CCC)
Oct 25 11:52:20 mailbox postfix/qmgr[52740]: 4B9804D13CB0: removed

and the relevant part from amavis.log (debug level 5) looks like so:

lookup [forward_method] => true,  "xxx@xxx.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)"
delivery method is 1, recips: xxx@xxx.com
get_deadline quar+notif - deadline in 479.0 s, set to 288.000 s
prolong_timer quar+notif: timer 288, was 288, deadline in 479.0 s
DSN: sender NOT credible, SA: 15.417, <ynmyfnj@informark.co.ua>
lookup: (scalar) matches, result="-100"
lookup [spam_dsn_cutoff_level_bysender] => true,  "ynmyfnj@informark.co.ua" matches, result="-100", matching_key="(constant:-100)"
dsn: . 554 Spam <ynmyfnj@informark.co.ua> -> <xxx@xxx.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=, destiny=-3, mta_resp: "554 5.7.0 Reject, id=52765-01 - spam"
DSN: FAIL . 554 Spam, status propagated back: <ynmyfnj@informark.co.ua> -> <xxx@xxx.com>
delivery_status_notification: notif 0 bytes, suppressed: no
one_response_for_all, per_recip_capable: N, suppressed: N
one_response_for_all <ynmyfnj@informark.co.ua>: REJECTs, '554 5.7.0 Reject, id=52765-01 - spam'
notif=N, suppressed=0, ndn_needed=, exit=69, 554 5.7.0 Reject, id=52765-01 - spam
get_deadline delivery-notification - deadline in 479.0 s, set to 288.000 s
prolong_timer delivery-notification: timer 288, was 288, deadline in 479.0 s
status counters: InMsgsStatus{Rejected,RejectedInbound}
get_deadline snmp-counters - deadline in 479.0 s, set to 288.000 s
prolong_timer snmp-counters: timer 288, was 288, deadline in 479.0 s
orcpt_encode rfc822, xxx@xxx.com, smtputf8
oldest_public_ip_addr_from_received: 178.17.170.60
Blocked SPAM {RejectedInbound}, [85.25.13.92]:44462 [178.17.170.60] <ynmyfnj@informark.co.ua> -> <xxx@xxx.com>, Queue-ID: 1CD504D13C96, Message-ID: <11a201d22e97$126f7740$2adb3d4f@ynmyfnj>, mail_id: N0710n9hpdxw, Hits: 15.417, size: 145530, 1021 ms
get_deadline main_log_entry - deadline in 479.0 s, set to 288.000 s
prolong_timer main_log_entry: timer 288, was 288, deadline in 479.0 s
TIMING-SA total 817 ms - parse: 8 (1.0%), extract_message_metadata: 55 (6.7%), get_uri_detail_list: 1.42 (0.2%), tests_pri_-1000: 32 (3.9%), tests_pri_-950: 1.05 (0.1%), tests_pri_-900: 1.13 (0.1%), tests_pri_-400: 26 (3.1%), check_bayes: 24 (2.9%), b_tokenize: 11 (1.3%), b_tok_get_all: 3.5 (0.4%), b_comp_prob: 4.4 (0.5%), b_tok_touch_all: 0.80 (0.1%), b_finish: 1.12 (0.1%), tests_pri_0: 665 (81.4%), check_dkim_adsp: 479 (58.6%), check_spf: 43 (5.3%), poll_dns_idle: 0.28 (0.0%), check_pyzor: 0.25 (0.0%), tests_pri_500: 5 (0.7%), get_report: 0.77 (0.1%)
updating snmp variables in BDB
get_deadline check done - deadline in 479.0 s, set to 288.000 s
prolong_timer check done: timer 288, was 288, deadline in 479.0 s
sending SMTP response: "554 5.7.0 Reject, id=52765-01 - spam"
ESMTP> 554 5.7.0 Reject, id=52765-01 - spam
...
ESMTP< QUIT\r\n
...
ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel

As a result despite explicitly telling amavis/postfix NOT to send out a bounce to a faked email address and even amavis acknowledging my wish there, the bounces still get sent out. I presume the key in the logs is the word "suppressed" which is "no" and "0" instead of "yes" and "1" as I have seen in the amavis logs elsewhere on the internet.

So the question is what I'm doing wrong and whether there could be something else interfering with the setup and I'd also like to know the best way to debug this. Obviously the statements in the amavis log are contradictory.

Best Answer

The problem here is that it's amavis, not postfix, that's rejecting the message. Here's the standard flow for incoming messages:

  1. postfix receives the message from the sending MTA (or spambot)
  2. postfix forwards (or attempts to forward) the message to amaviz (on port 10024)
  3. amaviz forwards the message back to postfix
  4. postfix delivers the message to cyrus (which handles the mailboxes on OS X server)

What's going on in your case is that postfix is receiving the message (step 1), but amaviz rejects it (at step 2), so postfix generates a bounce message. See the log entries like "to=<xxx@xxx.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.2, delays=1.1/0/0.02/1, dsn=5.7.0, status=bounced (host 127.0.0.1[127.0.0.1] said: 554 5.7.0 Reject, id=52765-01 - spam (in reply to end of DATA command))". Note that it's postfix sending to localhost:10024 (amaviz), and postfix is the MTA getting the 554 reject.

Once postfix has received the message, it's too late to reject it; you can really only drop it or pass it. This is why black- and grey-listing are useful; they're not as precise as a content scanner, but they get applied by postfix before it's received the message, and therefore allow a true reject.