Re: Test of opendkim-2.3.1 on a busy e-mail server

On Mon, Apr 11, 2011 at 04:23:03PM -0700, Murray S. Kucherawy wrote:
> > From: opendkim-dev-bounce_at_lists.opendkim.org [mailto:opendkim-dev-bounce_at_lists.opendkim.org] On Behalf Of SM
> > Sent: Monday, April 11, 2011 4:04 PM
>
> Thanks, Gary, for the detailed testing and report. This is looking pretty good.
>
> SM covered some of the cases reported. Here are some comments on the others:
>
> > > Apr 9 17:08:12 electra opendkim[16259]: [ID 184845 mail.error]
> > > p39M1OTW016852: Authentication-Results header add failed
> >
> > This one is odd.

> This typically means that, during the end-of-message phase of
> milter, the MTA gave up waiting for the filter to say something and
> closed the connection; eventually the filter did have something to
> say, but the socket joining them had been closed by then. It
> certainly should be unusual. It should also be the case that
> progress messages from the filter should keep the read timeout from
> hitting, but there's a second EOM timeout that can't be avoided,
> though that's pretty long by default (a full minute?).

Maybe if I include the rest of the log for that message it will help:

    Apr 9 17:01:24 electra sm-mta[16852]: [ID 801593 mail.info] p39M1OTW016852: from=<users-return-99607-Roderick_Francey=umanitoba.ca_at_httpd.apache.org>, size=3780, class=-60, nrcpts=1, msgid=<BANLkTiknTw9YOkeeca28FYz36kN3cSBSCA_at_mail.gmail.com>, proto=SMTP, daemon=MTA, relay=hermes.apache.org [140.211.11.3]
    Apr 9 17:03:19 electra sm-mta[16852]: [ID 801593 mail.error] p39M1OTW016852: Milter (dkim): timeout before data read, where=eom
    Apr 9 17:03:19 electra sm-mta[16852]: [ID 801593 mail.info] p39M1OTW016852: Milter (dkim): to error state
    Apr 9 17:03:19 electra sm-mta[16852]: [ID 801593 mail.info] p39M1OTW016852: Milter: data, reject=452 4.2.1 id p39M1OTW016852 from 140.211.11.3 temporary embargo. See http://mail.cc.umanitoba.ca/grey/
    Apr 9 17:03:19 electra sm-mta[16852]: [ID 801593 mail.info] p39M1OTW016852: to=<Roderick_Francey@umanitoba.ca>, delay=00:01:55, pri=141780, stat=id p39M1OTW016852 from 140.211.11.3 temporary embargo. See http://mail.cc.umanitoba.ca/grey/
    Apr 9 17:08:12 electra opendkim[16259]: [ID 184845 mail.error] p39M1OTW016852: Authentication-Results header add failed
    Apr 9 17:08:12 electra opendkim[16259]: [ID 632817 mail.info] p39M1OTW016852: s=gamma d=gmail.com SSL error:04077068:rsa routines:RSA_verify:bad signature
    Apr 9 17:08:12 electra opendkim[16259]: [ID 614597 mail.notice] p39M1OTW016852: bad signature data

It looks as if the DCC filter rejected the message, but five minutes
later the opendkim filter continued processing it. These are the
filters that we use:

    INPUT_MAIL_FILTER(`j-chkmail', `S=local:/var/run/jchkmail/j-chkmail.sock, T=C:2m;S:20s;R:40s;E:5m')dnl
    INPUT_MAIL_FILTER(`dkim', `S=inet:8891_at_localhost, T=S:60s;R:60s')dnl
    INPUT_MAIL_FILTER(`dcc', `S=inet:3331_at_electra.cc.umanitoba.ca, F=T, T=S:60s;R:60s')dnl

-- 
-Gary Mills-        -Unix Group-        -Computer and Network Services-