Milter-greylist

Hello,

I’ve been using milter-greylist for just over a week.  It’s part of my sendmail configuration alongside MIMEDefang and OpenDKIM.  This is on a CentOS 7 box using packages provided by CentOS:

sendmail-8.14.7-4.el7.x86_64
milter-greylist-4.5.12-2.el7.x86_64

Everything seems to be working well, apart from my attempts to make use of the X-Spam-Level header I set in my MIMEDefang filter.  My first attempt was just a dacl greylist header /…/ delay xxx autowhite xxx statement but it never altered the delay of matched messages.  The regex was matching though because when I put a log statement there I saw the log.  I also noticed that when I tried to log the matched substrings I got empty values instead.

My current attempt is below, this time trying to make use of a variable.  But messages come in, MIMEDefang sets the X-Spam-Level header, and the messages do not get the delay and autowhite settings from the match on line 301 (below) as I would expect.  They’re matching on line 306 (showing that my country lookup is working in these cases).

What am I doing wrong?

Once I get this figured out I’ll do further tuning.  In case you are curious, my MIMEDefang filter calls SpamAssassin to determine whether messages are spam and only rejects spam at a high confidence level.  Below that threshold I just want to tune my greylisting parameters for now, but the spam I’m fighting here does retry so I might have to do tuning elsewhere to get rid of it.  It’s bothering me that I can’t get the dacl greylist header /…/ action to do anything apart from logging.

Thanks,
-Rudy

sendmail.mc:
define(`confINPUT_MAIL_FILTERS', `mimedefang,milter-greylist,opendkim’)dnl

greylist.conf:
   293	racl continue set $is_spam="no"
   294	dacl greylist header /^X-Spam-Level:[ ]*(.*)$/ set $is_spam="yes"
   295	
   296	racl whitelist list "my network"
   297	racl whitelist list "broken mta"
   298	racl whitelist list "known good servers"
   299	racl blacklist list "blacklist users" flushaddr
   300	
   301	racl greylist $is_spam "yes" delay 30m autowhite 90m
   302	
   303	racl whitelist list "whitelist users"
   304	
   305	#racl continue not list "ok countries" log "%i geoip country = %C"
   306	racl greylist not list "ok countries" delay 15m autowhite 45m
   307	
   308	racl greylist default

'Rudolph T. Maceyko' rm55@... [milter-greylist]
<milter-greylist@yahoogroups.com> wrote:

>    294        dacl greylist header /^X-Spam-Level:[ ]*(.*)$/ set $is_spam="yes"
(...)   
>    301        racl greylist $is_spam "yes" delay 30m autowhite 90m

DATA-stage ACL are evaluated after RCPT-stage ACL. therefore line 301
here can never see the variable set afterwards in line 294.

Generally speaking it is a good idea to have dacl after racl in the
file: it prevents such confusion.

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

> On Nov 27, 2015, at 11:26 PM, manu@... [milter-greylist] <milter-greylist@yahoogroups.com> wrote:
> 
> DATA-stage ACL are evaluated after RCPT-stage ACL. therefore line 301
> here can never see the variable set afterwards in line 294.
> 
> Generally speaking it is a good idea to have dacl after racl in the
> file: it prevents such confusion.
> 

Thanks—in hindsight that should have been obvious.

Now that I’m doing DATA-phase checks in dacls (or trying to), I’ve run into a different problem: how does one structure the greylist.conf file so that dacls actually have a chance to affect the disposition of the message?

This comes directly from the greylist.conf man page:

spamdsock inet "127.0.0.1:783"
racl whitelist default
dacl blacklist spamd > 15 msg "Your message is considered spam."
dacl greylist  spamd > 10 delay 2h
dacl greylist  spamd > 5  delay 1h

In my testing the greylisting decision is always made based on the last (matching) racl (or if there is none, on the default greylist and autowhitelist settings).  Even using a “continue” action as the last racl results in the default action taking place.

Here are the results of some focused testing on this problem.  In each case the message is coming in from a non-trusted relay and contains a string that causes SpamAssassin to give the message a very high score.  My MIMEDefang filter triggers to add an X-Spam-Level header, which I’m trying to use in my greylist.conf to do something different with such messages.  The mimedefang milter is called before milter-greylist.

All of the configuration other than racl and dacl is boilerplate or unused lists (for this configuration anyway), so I’m just providing the racl and dacl statements.

Case #1 - default racl action is to whitelist (dacl is never consulted)

# cleared database
racl “DEF” whitelist default
dacl “XSL” greylist header /^X-Spam-Level:[ ]*(.*)$/ delay 30m autowhite 90m

Nov 29 13:14:00 xxx milter-greylist[30633]: tATIDxm8030639: skipping greylist because this is the default action, (from=<rm55@xxx>, rcpt=<rm55@xxx>, addr=xxx) ACL DEF

Case #2 - default racl action is to greylist (dacl is never consulted)

# cleared database 
racl "DEF" greylist default delay 1m autowhite 5m
dacl "XSL" greylist header /^X-Spam-Level:[ ]*(.*)$/ delay 30m autowhite 90m

Nov 29 13:18:06 xxx milter-greylist[30711]: qid: addr xxx from <rm55@xxx> to <rm55@xxx> delayed for 00:01:00 (ACL DEF)

# retry
Nov 29 13:19:15 xxx sendmail[30735]: qid: Milter add: header: X-Greylist: Delayed for 00:01:09 by milter-greylist-4.5.12 (xxx); Sun, 29 Nov 2015 13:19:15 -0500 (EST)

# subsequent delivery
Nov 29 13:21:47 xxx sendmail[30760]: qid: Milter add: header: X-Greylist: IP, sender and recipient auto-whitelisted, not delayed by milter-greylist-4.5.12 (xxx); Sun, 29 Nov 2015 13:21:47 -0500 (EST)

Case #3 - no default racl (dacl is never consulted)

# cleared database 

#racl "DEF" greylist default delay 1m autowhite 5m                                                                                  
dacl "XSL" greylist header /^X-Spam-Level:[ ]*(.*)$/ delay 30m autowhite 90m

Nov 29 13:24:52 xxx milter-greylist[30814]: qid: addr xxx from <rm55@xxx> to <rm55@xxx> delayed for 00:05:00 (ACL )

# retry
Nov 29 13:29:56 xxx sendmail[30873]: qid: Milter add: header: X-Greylist: Delayed for 00:05:03 by milter-greylist-4.5.12 (xxx); Sun, 29 Nov 2015 13:29:56 -0500 (EST)

Case #4 - only racl action is continue (dacl is never consulted)

# cleared database 

#racl "DEF" greylist default delay 1m autowhite 5m                                                                                  
racl "CON" continue from /./
dacl "XSL" greylist header /^X-Spam-Level:[ ]*(.*)$/ delay 30m autowhite 90m

Nov 29 13:33:07 xxx milter-greylist[30934]: qid: addr xxx from <rm55@xxx> to <rm55@xxx> delayed for 00:05:00 (ACL CON)

# retry
(no point, this is just like the previous case)

Thanks,
Rudy

'Rudolph T. Maceyko' rm55@... [milter-greylist]
<milter-greylist@yahoogroups.com> wrote:

> Here are the results of some focused testing on this problem.  

I will have to read the code again to answer your question, so expect a
few days of delay, exept if someone else on the list beats me at it.

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

Is there any unexpected milter-greylist log entry in your syslog?

How is it looking your INPUT_MAIL_FILTER definitions in your  .mc file?
Not only for the milter-greylist, but for other milters.
Some milter may say "accept" instead of "continue"
before the dacl stage of milter-greylist got called.

On Nov 30, 2015, at 11:10 PM, manu@... [milter-greylist] <milter-greylist@yahoogroups.com> wrote:
> I will have to read the code again to answer your question, so expect a
> few days of delay, exept if someone else on the list beats me at it.

I have done a little diving through the code and just a tiny bit more playing around with this.  The problem remains.

Milter-greylist is only invoked using the -D option (via the systemd unit file provided by the EPEL milter-greylist RPM for CentOS 6.

The greylist.conf file in its entirety (minus blank lines and comments) is:

***

domainexact

list "known good servers" domain { \
…
}

list "ok countries" geoip { \
…
}

list "whitelist rcpts" rcpt {  \
…
}

list "blacklist rcpts" rcpt { \
...
}

list "blacklist from" from { \
…
}

list "blacklist empty sender" rcpt { \
…
}

report all

dumpfreq 1

timeout 5d

extendedregex

autowhite 0

quiet

geoipdb "/usr/share/GeoIP/GeoIP.dat"

socket "/run/milter-greylist/milter-greylist.sock"

dumpfile "/var/lib/milter-greylist/db/greylist.db" 600

user "grmilter"

list "my network" addr { \
…
}

list "broken mta" addr {   \
…
}

racl "RWMNET" whitelist list "my network"
racl "RWWRCP" whitelist list "whitelist rcpts"
racl "RWBMTA" whitelist list "broken mta"
racl "RWGSRV" whitelist list "known good servers"

racl "RBBFRM" blacklist list "blacklist from" flushaddr msg "invalid sender address"
racl "RBBNRP" blacklist from /^<>$/ list "blacklist empty sender" flushaddr msg "recipient address requires non-empty sender"
racl "RBBRCP" blacklist list "blacklist rcpts" flushaddr msg "invalid recipient address"

dacl "DC1" continue set $is_spam="no"
dacl "DC2" continue header /^X-Spam-Level:[ ]*(.*)$/ set $is_spam="yes"
dacl "DC3" continue $is_spam "yes" log "found X-Spam-Level header"
dacl continue header /^Subject:[ ]*(.*)$/ log "found subject header (%g{\1})"
dacl continue body /.*test.*/ log "found test string in body"
dacl continue msgsize > 0 log "message size is > 0"
dacl "DGXSPM" greylist $is_spam "yes" delay 31m autowhite 91m
dacl "DC2" continue not list "ok countries" log "%i geoip country = %C"
dacl "DGNOKC" greylist not list "ok countries" delay 16m autowhite 46m
dacl "DGDEFL" greylist default delay 6m auto white 15d

***

I’m getting only the following matches (this is just a sampling of recent logs):

  55027  RWMNET
    377  (empty ACL)
    123  RWWRCP
     42  RBBNRP
     42  312 (RBBNRP)
      9  RWGSRV
      5  RBBRCP
      5  313 (RBBRCP)
      3  RWDNSL (since removed from the configuration)

Nothing in dacl matches at all, and I’m getting logs for the header test that should trigger the DGXSPM dacl but instead I end up with the default 30 minute greylist (nowhere specified in the greylist.conf)

Thanks,
Rudy

'Rudolph T. Maceyko' rm55@... [milter-greylist]
<milter-greylist@yahoogroups.com> wrote:

> Nothing in dacl matches at all,

I found nothing obvious from what you posted.

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.

-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

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

'Rudolph T. Maceyko' rm55@... [milter-greylist]
<milter-greylist@yahoogroups.com> wrote:

> 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

That is content examination: data-stage logic is executed (as your "I was here"
confirms anyway)

>  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 )

That one is interesting the ACL line number/id string is missing. Hence we do
not really know if it happened at DATA or RCPT stage.

This is the code producing this is in
milter-greylist.c:log_and_report_greylisting()

        aclstr = fstring_expand(priv, NULL, " (ACL %a)", NULL);
        
        if (!(priv->priv_sr.sr_whitelist & EXF_NOLOG)) {
                mg_log(LOG_INFO,
                        "%s: addr %s[%s] from %s to %s delayed%s for %02d:%02d:%
02d%s",         
                        priv->priv_queueid, priv->priv_hostname, addrstr,
                        priv->priv_from, rcpt, delayed_rj, h, mn, s, aclstr);
        } 

Try replacing the " (ACL %a)" by " (ACL %A )", this will always display the line
number and never the ACL id string. That will let us have a definitive answer on
what ACL matches. 

Afterwards we will have to understand why %a returns an empty string.



-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

On Dec 5, 2015, at 11:28 PM, manu@... [milter-greylist] <milter-greylist@yahoogroups.com> wrote:
> Try replacing the " (ACL %a)" by " (ACL %A )", this will always display the line
> number and never the ACL id string. That will let us have a definitive answer on
> what ACL matches. 

Dec 06 10:25:46 xxx milter-greylist[19837]: tB6FPku6019844: addr xxx[xxx] from <xxx> to <xxx> delayed for 00:30:00 (ACL (none))

This matches my suspicion that some default racl is matching that is not in my config file.

In case there is any doubt:

$ ps faxuwww | grep [g]reylist
grmilter 19837  0.0  0.1 322136  4224 ?        Ssl  10:25   0:00 /usr/sbin/milter-greylist -D

The greylist.conf is exactly as I posted it on Friday.

So what’s happening?  I think real_envrcpt is signaling to TEMPFAIL in the default case (no previous greylisting, no autowhitelisting, no blacklisting), so real_eom does not have a chance to affect the message disposition.

RCPT phase:
 mlfi_envrcpt -> real_envrcpt -> acl_filter(AS_RCPT)
 /* SHOULD signal to continue unless DEFINITIVE action was taken */

DATA phase:
  mlfi_eom -> real_eom -> acl_filter(AS_DATA)
  /* SHOULD be given the chance to take action unless definitive action was taken in RCPT phase */

Some details from the code:

acl.c:acl_filter()
   2438         if (acl == NULL) {
   2439                 /*
   2440                  * No match: use the default action
   2441                  */
   2442                 if (testmode)
   2443                         retval = EXF_WHITELIST;
   2444                 else if (stage == AS_DATA)
   2445                         retval = EXF_WHITELIST | EXF_NOLOG;
   2446                 else
   2447                         retval = EXF_GREYLIST;
   2448                 retval |= EXF_DEFAULT;
   2449 
   2450                 priv->priv_sr.sr_delay = conf.c_delay;
   2451                 priv->priv_sr.sr_autowhite = conf.c_autowhite_validity;
   2452                 priv->priv_sr.sr_tarpit = conf.c_tarpit;
   2453                 priv->priv_sr.sr_tarpit_scope = conf.c_tarpit_scope;
   2454         }

   2557         error = 0;

   2561         priv->priv_sr.sr_whitelist = retval;
   2562 
   2563         return error;
   2564 }

When there is no racl match, we will greylist (and when there is no setting for the delay, we get the default of 30m (GLDELAY).

milter-greylist.c:real_envrcpt()
    725         if (acl_filter(AS_RCPT, ctx, priv) != 0) {
    726                 mg_log(LOG_ERR, "ACL evaluation failure");
    727                 return SMFIS_TEMPFAIL;
    728         }

acl_filter will have returned 0, so we continue…

priv->priv_sr.sr_wrhitelist will be EXF_GREYLIST | EXF_DEFAULT (for the the first time this tuple has been encountered)

    730         if (priv->priv_sr.sr_whitelist & EXF_WHITELIST &&
    731             priv->priv_sr.sr_tarpit <= 0) {
    732                 priv->priv_sr.sr_elapsed = 0;
    733                 goto exit_accept;
    734         }

not whitelisted or blacklisted so we continue…

    763          * Check if the tuple {sender IP, sender e-mail, recipient e-mail}
    764          * is in the greylist or autowhite list and if it can now be 
    765          * accepted. If in greylist, the greylist entry will change to 
    766          * autowhite entry. If it is not in the greylist, it will be added.
    767          */
    768 
    769         tuple.sa = SA(&priv->priv_addr);
    770         tuple.salen = priv->priv_addrlen;
    771         tuple.from = priv->priv_from;
    772         tuple.rcpt = rcpt;
    773         tuple.remaining = &remaining;
    774         tuple.elapsed = &priv->priv_sr.sr_elapsed;
    775         tuple.queueid = priv->priv_queueid;
    776         tuple.gldelay = priv->priv_sr.sr_delay;
    777         tuple.autowhite = priv->priv_sr.sr_autowhite;
    778 
    779         switch(mg_tuple_check(&tuple)) {

first time through, so we’ll take the default case:

    790         default:                        /* first encounter */
    791                 if (!(priv->priv_sr.sr_whitelist & EXF_TARPIT))
    792                         break;

not tarpitted so we break out of the case statement here

    818         /*
    819          * The message has been added to the greylist and will be delayed.
    820          * If the sender address is null, this will be done after the DATA
    821          * phase, otherwise immediately.
    822          * Delayed reject with per-recipient delays or messages 
    823          * will use the last match.
    824          */
    825         if ((conf.c_delayedreject == 1) && 
    826             (strcmp(priv->priv_from, "<>") == 0)) {
    827                 priv->priv_delayed_reject = 1;
    828                 goto exit_accept;
    829         }
    830 
    831         /*
    832          * Log temporary failure and report to the client.
    833          */
    834         priv->priv_sr.sr_whitelist |= save_nolog;
    835         log_and_report_greylisting(ctx, priv, *envrcpt);
    836         return mg_stat(priv, SMFIS_TEMPFAIL);

There you have it: we have reported back through the milter interface that the message should be TEMPFAILed, and we haven’t even consulted our dacls.

So, if we have been greylisted already and are retrying, how does that change things?

    779         switch(mg_tuple_check(&tuple)) {

    785         case T_PENDING:                 /* greylisted */
    786                 if (priv->priv_sr.sr_elapsed > priv->priv_max_elapsed)
    787                         priv->priv_max_elapsed = priv->priv_sr.sr_elapsed;
    788                 goto exit_accept;
    789                 break;

Let’s assume our delay period has elapsed:

    838 exit_accept:
    839         add_recipient(priv, rcpt);
    840         if (priv->priv_sr.sr_whitelist & EXF_WHITELIST)
    841                 priv->priv_last_whitelist = priv->priv_sr.sr_whitelist;
    842         return SMFIS_CONTINUE;
    843 }

So in this case we SHOULD be able to have actions in our dacls take effect, because the RCPT phase hasn’t TEMPFAILed…

milter-greylist.c:real_body()
   1142         if (priv->priv_sr.sr_whitelist & EXF_WHITELIST && 
   1143             priv->priv_sr.sr_whitelist & EXF_DEFAULT)
   1144                 envrcpt_continue = 1;

Remember, we are EXF_GREYLIST | EXF_DEFAULT, so this does not match.

  1152         /* 2015-12-05 debugging per manu@... */
   1153         mg_log(LOG_ERR, "I was here");
   1154         if (acl_filter(AS_DATA, ctx, priv) != 0) {
   1155                 mg_log(LOG_ERR, "ACL evaluation failure");
   1156                 return SMFIS_TEMPFAIL;
   1157         }

   1159         if (priv->priv_sr.sr_whitelist & EXF_BLACKLIST) {

Not us

   1190         if (priv->priv_sr.sr_whitelist & EXF_GREYLIST && envrcpt_continue) {

Not us either, because envrcpt_continue was NOT set on line 1144

   1237 passed:
   1238         /* Add custom header from DATA stage ACL */
   1239         /* XXX we do it twice??? */
   1240         if (priv->priv_sr.sr_addheader) {

skipping more code that doesn’t match our case

   1342         if (priv->priv_max_elapsed == 0) {
   1343                 /* All recipients are whitelisted */

Hmm?  This was set to 0 initially in real_connect(), and otherwise set to priv->priv_sr.sr_elapsed.  priv->priv_sr.sr_elapsed would be set to 0 for non-network connections and for authenticated connections (and SPF, DRAC, or access DB matches if we are using those but we aren’t); also for whitelisted entries but we’re not whitelisted (don’t have EXF_WHITELIST set still).  So otherwise we expect it to get set to priv->priv_max_elapsed in real_eom.  I’m out of time to trace how this work, but if we end up with priv_max_elapsed == 0 here, so maybe that’s the problem.  Anyway I will get some additional debugging set in milter-greylist since I see some logging that would be helpful here.

Thanks,
Rudy

'Rudolph T. Maceyko' rm55@... [milter-greylist]
<milter-greylist@yahoogroups.com> wrote:

> So what's happening?  I think real_envrcpt is signaling to TEMPFAIL in the
> default case (no previous greylisting, no autowhitelisting, no
> blacklisting), so real_eom does not have a chance to affect the message
> disposition.

This is something I overlooked: your ACL has no default clause for RCPT
stage. Does it help to add:something like this?

racl whitelist default


-- 
Emmanuel Dreyfus
http://hcpnet.free.fr/pubz
manu@...

On 2015-12-06 19:44, manu@... [milter-greylist] wrote: 

> 'Rudolph T. Maceyko' rm55@... [milter-greylist]
> <milter-greylist@yahoogroups.com> wrote:
> 
>> So what's happening? I think real_envrcpt is signaling to TEMPFAIL in the
>> default case (no previous greylisting, no autowhitelisting, no
>> blacklisting), so real_eom does not have a chance to affect the message
>> disposition.
> 
> This is something I overlooked: your ACL has no default clause for RCPT
> stage. Does it help to add:something like this?
> 
> racl whitelist default

Been there and done that. It does not help. I dont have "racl whitelist
default" now as a result of my attempting to prune out things from the
configuration file to see what's going on. 

See my message from 2015-11-29 where I showed the various cases (based
originally on the spamd dacls in the greylist.conf man page), and that
included "racl whitelist default." 

Thanks,
Rudy