On Jul 27, 2015, at 10:12 AM, Philip Prindeville <[email protected]> wrote:
> > On Jul 27, 2015, at 8:07 AM, Dianne Skoll <[email protected]> wrote: > >> On Mon, 27 Jul 2015 00:11:09 -0600 >> Philip Prindeville <[email protected]> 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=<[email protected]>, size=3652, class=-30, nrcpts=1, msgid=<CAAPGDw+kBMUqFBnaEBG+EWW85PiJr=cvgo4phoyolmo8cdy...@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,,,<[email protected]>,<[email protected]>,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=cvgo4phoyolmo8cdy...@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 _______________________________________________ NOTE: If there is a disclaimer or other legal boilerplate in the above message, it is NULL AND VOID. You may ignore it. Visit http://www.mimedefang.org and http://www.roaringpenguin.com MIMEDefang mailing list [email protected] http://lists.roaringpenguin.com/mailman/listinfo/mimedefang
