Milter-greylist

On Dec 4, 2015, at 11:55 PM, manu@... [milter-greylist] <milter-greylist@yahoogroups.com> wrote:
> 
> Would you be able to rebuild from sources? It would be interesting to
> add a few log statements to see where the program goes: 
> 
> ACL evaluation is done by acl_filter(), and it is called for DATA stage
> ACL in real_eom(). It would be interesting to add a mg_log(LOG_ERR, "I
> was here") just before acl_filter() there to check we actually reach
> that point.

rpm -q milter-greylist
milter-greylist-4.5.12-2.1t.el7.centos.x86_64

The “.1t” is my patched version (built as an RPM replacing the one from EPEL).

The log output appears, but not in the “default greylist” case:

Initial attempt:

Dec  5 12:14:55 xxx sendmail[14293]: NOQUEUE: connect from xxx [xxx]
Dec  5 12:14:55 xxx sendmail[14293]: AUTH: available mech=ANONYMOUS, allowed mech=PLAIN
Dec  5 12:14:55 xxx sendmail[14293]: STARTTLS: internal error: tls_verify_cb: ssl == NULL
Dec  5 12:14:55 xxx sendmail[14293]: STARTTLS: internal error: tls_verify_cb: ssl == NULL
Dec  5 12:14:55 xxx sendmail[14293]: STARTTLS: internal error: tls_verify_cb: ssl == NULL
Dec  5 12:14:55 xxx sendmail[14293]: STARTTLS=server, relay=xxx [xxx], version=TLSv1/SSLv3, verify=NOT, cipher=DHE-RSA-AES256-GCM-SHA384, bits=256/256
Dec  5 12:14:55 xxx sendmail[14293]: STARTTLS=server, cert-subject=, cert-issuer=, verifymsg=ok
Dec  5 12:14:55 xxx sendmail[14293]: AUTH: available mech=LOGIN PLAIN ANONYMOUS, allowed mech=PLAIN
Dec  5 12:14:56 xxx milter-greylist: qid: addr xxx[xxx] from <rm55@xxx> to <rm55@xxx> delayed for 00:30:00 (ACL )
Dec  5 12:14:56 xxx sendmail[14293]: qid: Milter: to=<rm55@xxx>, reject=451 4.7.1 Greylisting in action, please come back later
Dec  5 12:14:56 xxx sendmail[14293]: qid: from=<rm55@xxx>, size=1533, class=0, nrcpts=0, proto=ESMTP, daemon=MTA, relay=xxx [xxx]

Retry:

Dec  5 12:46:23 xxx sendmail[14609]: NOQUEUE: connect from xxx [xxx]
Dec  5 12:46:23 xxx sendmail[14609]: AUTH: available mech=ANONYMOUS, allowed mech=PLAIN
Dec  5 12:46:23 xxx sendmail[14609]: STARTTLS: internal error: tls_verify_cb: ssl == NULL
Dec  5 12:46:23 xxx sendmail[14609]: STARTTLS: internal error: tls_verify_cb: ssl == NULL
Dec  5 12:46:23 xxx sendmail[14609]: STARTTLS: internal error: tls_verify_cb: ssl == NULL
Dec  5 12:46:23 xxx sendmail[14609]: STARTTLS=server, relay=xxx [xxx], version=TLSv1/SSLv3, verify=NOT, cipher=DHE-RSA-AES256-GCM-SHA384, bits=256/256
Dec  5 12:46:23 xxx sendmail[14609]: STARTTLS=server, cert-subject=, cert-issuer=, verifymsg=ok
Dec  5 12:46:23 xxx sendmail[14609]: AUTH: available mech=LOGIN PLAIN ANONYMOUS, allowed mech=PLAIN
Dec  5 12:46:23 xxx sendmail[14609]: qid: from=<rm55@xxx>, size=1502, class=0, nrcpts=1, msgid=<56631b8f.T2jqHJHt4YxwfAKL%rm55@xxx>, proto=ESMTP, daemon=MTA, relay=xxx [xxx]
Dec  5 12:46:25 xxx mimedefang.pl[13133]: qid: MDLOG,qid,spam,999.889,xxx,<rm55@xxx>,<rm55@xxx>,test from xxx
Dec  5 12:46:25 xxx mimedefang.pl[13133]: qid: MDLOG,qid,mail_in,,,<rm55@xxx>,<rm55@xxx>,test from xxx
Dec  5 12:46:25 xxx sendmail[14609]: qid: Milter add: header: X-Spam-Status: Yes, hits=999.889 required=2.5 tests=DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,GTUBE,SPF_PASS,T_RP_MATCHES_RCVD checker=SpamAssassin version=3.004000
Dec  5 12:46:25 xxx sendmail[14609]: qid: Milter add: header: X-Spam-Level: ****************************************
Dec  5 12:46:25 xxx sendmail[14609]: qid: Milter add: header: X-Scanned-By: MIMEDefang 2.78 on 69.164.221.125
Dec  5 12:46:25 xxx milter-greylist: I was here
Dec  5 12:46:25 xxx milter-greylist: found X-Spam-Level header
Dec  5 12:46:25 xxx milter-greylist: found subject header ()
Dec  5 12:46:25 xxx milter-greylist: found test string in body
Dec  5 12:46:25 xxx milter-greylist: message size is > 0
Dec  5 12:46:25 xxx sendmail[14609]: qid: Milter add: header: X-Greylist: Delayed for 00:31:27 by milter-greylist-4.5.12 (xxx.xxx [69.164.221.125]); Sat, 05 Dec 2015 12:46:25 -0500 (EST)
Dec  5 12:46:25 xxx opendkim[29590]: qid: DKIM verification successful
Dec  5 12:46:25 xxx sendmail[14609]: qid: Milter insert (1): header: Authentication-Results:  xxx.xxx;\n\tdkim=pass (1024-bit key) header.d=xxx header.i=@xxx header.b=Zy2/mWOA
Dec  5 12:46:25 xxx sendmail[14609]: qid: Milter insert (1): header: DKIM-Filter:  OpenDKIM Filter v2.10.3 xxx.xxx qid
Dec  5 12:46:25 xxx sendmail[14614]: qid: alias <rm55@xxx> => rm55@xxx
…

Note that ordinarily egregious spam would be rejected, but I’m still in a testing setup here, and the spam in this case is simulated.

I’m now running sendmail with confMILTER_LOG_LEVEL at 14 to see what additional details pop up.  Here’s some spam that was just greylisted:

Dec 05 13:10:09 xxx sendmail[14944]: NOQUEUE: connect from [103.17.60.125]
Dec 05 13:10:09 xxx sendmail[14944]: AUTH: available mech=ANONYMOUS, allowed mech=PLAIN
Dec 05 13:10:09 xxx sendmail[14944]: xxx: Milter (mimedefang): init success to negotiate
Dec 05 13:10:09 xxx sendmail[14944]: xxx: Milter (milter-greylist): init success to negotiate
Dec 05 13:10:09 xxx sendmail[14944]: xxx: Milter (opendkim): init success to negotiate
Dec 05 13:10:09 xxx sendmail[14944]: xxx: Milter: connect to filters
Dec 05 13:10:09 xxx sendmail[14944]: xxx: milter=mimedefang, action=connect, continue
Dec 05 13:10:09 xxx sendmail[14944]: xxx: milter=milter-greylist, action=connect, continue
Dec 05 13:10:09 xxx sendmail[14944]: xxx: milter=opendkim, action=connect, continue
Dec 05 13:10:09 xxx sendmail[14944]: xxx: milter=mimedefang, action=helo, continue
Dec 05 13:10:09 xxx sendmail[14944]: xxx: milter=milter-greylist, action=helo, continue
Dec 05 13:10:10 xxx sendmail[14944]: xxx: milter=mimedefang, action=mail, continue
Dec 05 13:10:10 xxx sendmail[14944]: xxx: milter=milter-greylist, action=mail, continue
Dec 05 13:10:10 xxx sendmail[14944]: xxx: milter=opendkim, action=mail, continue
Dec 05 13:10:11 xxx sendmail[14944]: xxx: milter=mimedefang, action=rcpt, continue
Dec 05 13:10:11 xxx milter-greylist[9422]: xxx: addr [103.17.60.125][103.17.60.125] from <zonnderr@...> to <webmaster@...> delayed for 00:23:14 (ACL )
Dec 05 13:10:11 xxx sendmail[14944]: xxx: milter=milter-greylist, action=rcpt, reject=451 4.7.1 Greylisting in action, please come back later
Dec 05 13:10:11 xxx sendmail[14944]: xxx: Milter: to=<webmaster@...>, reject=451 4.7.1 Greylisting in action, please come back later
Dec 05 13:10:12 xxx sendmail[14944]: xxx: lost input channel from [103.17.60.125] to MTA after rcpt
Dec 05 13:10:12 xxx sendmail[14944]: xxx: from=<zonnderr@...>, size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=[103.17.60.125]

That just shows what we already know—that milter-greylist is taking action in the rcpt phase.  It does not show mimedefang, in particular, taking any action that would interfere with milter-greylist.

This should have matched:

dacl "DGNOKC" greylist not list "ok countries" delay 16m autowhite 46m

Thanks,
Rudy