[Mimedefang] Seeing weird SMFI errors

[Philip Prindeville]

On Jul 27, 2015, at 10:12 AM, Philip Prindeville <philipp_subx at redfish-solutions.com> wrote:

> 
> On Jul 27, 2015, at 8:07 AM, Dianne Skoll <dfs at roaringpenguin.com> wrote:
> 
>> On Mon, 27 Jul 2015 00:11:09 -0600
>> Philip Prindeville <philipp_subx at redfish-solutions.com> wrote:
>> 
>>> Update: I changed the timeout argument to T=S:2m;R:2m;E:10m and
>>> rebuilt sendmail.cf, then restarted the service.
>> 
>>> The problem seems to have gone away, but I’m not sure why.
>> 
>> Obviously, your filter was taking more than 5 minutes but less than
>> 10 to process a message, so the timeout is no longer hit and sendmail
>> doesn't exit before MIMEDefang has had a chance to reply.
>> 
>> Regards,
>> 
>> Dianne.
> 
> 
> That’s a REALLY long time to take to process a message.
> 
> I’ll throw some profiling logging messages in there and see if I can figure out what steps are taking so long.
> 
> -Philip


Made the following changes… Added this:

use Time::HiRes qw(gettimeofday tv_interval);

…

my $ts1 = undef;
my $where = ‘';

sub __enter()
{
    ($where = (caller(1))[3]) =~ s/.*:://;

    $ts1 = [gettimeofday()];
}

sub __leave()
{
    my $elapsed = tv_interval($ts1);

    my $log = sprintf "%s used %f secs", $where, $elapsed;

    md_syslog('debug', $log);
}

and then pepper my functions like filter_helo() with:

__enter();

just after the opening brace, and:

__leave();

before any “return” or closing braces.  Seems to be working so far:

Jul 28 14:18:17 mail mimedefang.pl[20236]: relay: hr1.samba.org (144.76.82.147:52289 => 192.168.1.3:25) de
Jul 28 14:18:17 mail mimedefang.pl[20236]: filter_relay used 0.000451 secs
Jul 28 14:18:22 mail mimedefang.pl[20236]: helo: hr1.samba.org (144.76.82.147:52289) said "helo hr1.samba.org"
Jul 28 14:18:22 mail mimedefang.pl[20236]: filter_helo used 0.307565 secs
Jul 28 14:18:23 mail sendmail[20283]: STARTTLS=server, relay=hr1.samba.org [144.76.82.147], version=TLSv1/SSLv3, verify=FAIL, cipher=ECDHE-RSA-AES128-GCM-SHA256, bits=128/128
Jul 28 14:18:23 mail mimedefang.pl[20236]: helo: hr1.samba.org (144.76.82.147:52289) said "helo hr1.samba.org"
Jul 28 14:18:23 mail mimedefang.pl[20236]: filter_helo used 0.002247 secs
Jul 28 14:18:23 mail mimedefang.pl[20237]: t6SKIHgw020283: filter_sender used 0.000029 secs
Jul 28 14:18:23 mail mimedefang.pl[20236]: t6SKIHgw020283: filter_recipient used 0.000022 secs
Jul 28 14:18:24 mail sendmail[20283]: t6SKIHgw020283: from=<samba-technical-bounces at lists.samba.org>, size=3652, class=-30, nrcpts=1, msgid=<CAAPGDw+kBMUqFBnaEBG+EWW85PiJr=CvGo4PHOYOLMo8cdYe5A at mail.gmail.com>, proto=ESMTP, daemon=MTA-v4, relay=hr1.samba.org [144.76.82.147]
Jul 28 14:18:26 mail mimedefang.pl[20236]: t6SKIHgw020283: MDLOG,t6SKIHgw020283,mail_in,,,<samba-technical-bounces at lists.samba.org>,<philipp_subx at redfish-solutions.com>,Re: [PATCH] Add strsep function (missing on Solaris)
Jul 28 14:18:26 mail sendmail[20283]: t6SKIHgw020283: Milter add: header: X-Scanned-By: MIMEDefang 2.78 on 192.168.1.3
Jul 28 14:18:27 mail lmtpunix[20242]: Delivered: <CAAPGDw+kBMUqFBnaEBG+EWW85PiJr=CvGo4PHOYOLMo8cdYe5A at mail.gmail.com> to mailbox: user.philipp.Lists.Samba-technical
Jul 28 14:18:27 mail lmtpunix[20242]: USAGE philipp user: 0.006767 sys: 0.006767
Jul 28 14:18:27 mail sendmail[20286]: t6SKIHgw020283: to=philipp, delay=00:00:04, xdelay=00:00:01, mailer=cyrusv2, pri=87994, relay=localhost, dsn=2.0.0, stat=Sent


Am I correctly seeing that filter_helo() is being called twice for the same connection?  Looks that way.

-Philip