[milters] Archive

Lists Index Date Thread Search

Article: 270
From: Anthony Howe
Date: 2004-12-07 05:31:22 -0500
Subject: [Fwd: Re: [milter-sender] Large messages and MilterSocketTimeout]

Removal...........: milters-request@milter.info?subject=remove
More information..: http://www.milter.info/#Support
--------------------------------------------------------

I'm forwarding this email as it appears to be a very well done 
experiment and analysis of milter timeout behaviour. The results are 
interesting and informative. I believe most of you might find it useful.
Comments welcome.

BTW I've just arrived in Canada (last night) for Xmas vacation, so my 
response times to moderated posts and questions might be a tad slower 
than usual.

-- 
Anthony C Howe                                 +33 6 11 89 73 78
http://www.snert.com/       ICQ:
7116561         AIM: Sir Wumpus

            "Once...we were here."  - Last of The Mohicans



-- Attached file included as plaintext by Ecartis --
-- File: Re: [milter-sender] Large messages and MilterSocketTimeout

Return-Path: <yar@comp.chem.msu.su>
Received: from comp.chem.msu.su (comp.chem.msu.su [158.250.32.97])
	by pop.snert.net (8.13.0/8.13.0) with ESMTP id iB70EXiL003779
	(version=TLSv1/SSLv3 cipher=EDH-RSA-DES-CBC3-SHA bits=168 verify=NO)
	for <achowe@snert.com>; Tue, 7 Dec 2004 01:14:54 +0100
Received: from comp.chem.msu.su (localhost [127.0.0.1])
	by comp.chem.msu.su (8.12.9p2/8.12.9) with ESMTP id iB70EW9d059901
	for <achowe@snert.com>; Tue, 7 Dec 2004 03:14:32 +0300 (MSK)
	(envelope-from yar@comp.chem.msu.su)
Received: (from yar@localhost)
	by comp.chem.msu.su (8.12.9p2/8.12.9/Submit) id iB70EVXw059896
	for achowe@snert.com; Tue, 7 Dec 2004 03:14:31 +0300 (MSK)
	(envelope-from yar)
Date: Tue, 7 Dec 2004 03:14:30 +0300
From: Yar Tikhiy <yar@comp.chem.msu.su>
To: Anthony Howe <achowe@snert.com>
Subject: Re: [milter-sender] Large messages and MilterSocketTimeout
Message-ID: <20041207001430.GA58690@comp.chem.msu.su>
References: <20041126181958.GA34346@comp.chem.msu.su>
<41A85032.60303@snert.com>
Mime-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <41A85032.60303@snert.com>
User-Agent: Mutt/1.5.6i

On Sat, Nov 27, 2004 at 11:00:18AM +0100, Anthony Howe wrote:
> Yar Tikhiy wrote:
> 
> >Recently, I noticed an issue regarding milter-sender and large
> >messages from hot countries far away over the great ocean :-)
> >Indeed, the issue was discovered due to a 6-megabyte mail from
> >Argentina to one of our users.
> >
> >Namely, milter-sender times out on waiting events from sendmail
> >if a message is transferred too slowly for the transfer to finish
> >in MilterSocketTimeout seconds or less.
> >
> >The maillog looks as follows:
> 
> > ...
> 
> >I'm not too familiar with milter API, but I suspect that milter-sender
> >doesn't register a callback for "body chunk" events and therefore gets
> >no milter events until message body has been received, which may take
> >quite a time if the connectivity is poor.
> 
> Actually it does register header and end-of-message events. The end of 
> message event is used to handle auto-whitelisting updates.
> 
> But I'm not sure what you are asking. The milter-to-sendmail timeout is 
> handled by the sendmail libmilter and is outside my control. You can 
> always change the default setting of MilterSocketTimeout. The libmilter 
> default is 7210 seconds, but I choose 1800 seconds for the majority of 
> servers that have high-speed access.
> 
> See also:
> 
> http://www.milter.org/milter_api/smfi_settimeout.html

Dear Anthony, I wasn't accusing milter-sender of bugs.  I just
wanted to let you know of a problem hiding somewhere withing the
entire sendmail-milter communication system.  You seem to be the
most active milter developer, so it might be of interest to you.

>From my side, I hope that a discussion with you will reveal the
real nature of the problem so that I can write down an actual problem
report to the responsible party.  Alas, I'm afraid I can hardly
find the root of the problem by myself because I have no milter
programming experience.

The problem is simple: a milter may time out on the communication
socket before the end of a very slow but otherwise normal SMTP
session.  When sendmail is receiving a email message, it imposes a
timeout on each read() from the network, not on the overall session
time, and it's a completely reasonable approach.  OTOH, a milter
(I mean both the library and the filter) seems to have no way to
know that the SMTP session is still alive unless it has registered
a handler for body chunks.  Perhaps a no-op keepalive command from
MTA to the milter would prevent the bogus timeout.  Does this seem
reasonable to you?
 
> As for the other broken pipe cases, I would be interested in a 
> description of what triggers then, especially if its within my ability 
> to fix them. I don't particularly need log output. I think your final 
> analysis will be sufficient.

Of course, I wasn't going to send you tons of logs, but there were
certain characterisitic patterns reproducing each time.  Those
patterns disappeared from the maillog file after I had increased
MilterSocketTimeout to 86400 seconds, so I guessed that they were
related to the milter socket timeout, too. The patterns were as
follows:


	Nov 23 00:07:54 rt1 sm-mta[31941]: iAMK7sug031941: timeout waiting for input from
[69.224.212.149] during server cmd read
	Nov 23 00:07:54 rt1 sm-mta[31941]: iAMK7sug031941: Milter (milter-sender): write(Q)
returned -1, expected 5: Broken pipe
	Nov 23 00:07:54 rt1 sm-mta[31941]: iAMK7sug031941: Milter (milter-sender): to error state

Sendmail was going to say QUIT to milter-sender since the client
had been gone before issuing an SMTP command, but milter-sender had
timed out either.


	Nov 15 08:33:08 rt1 sm-mta[81521]: iAF4WDPr081521: Milter (milter-sender): write(D)
returned -1, expected 5: Broken pipe
	Nov 15 08:33:08 rt1 sm-mta[81521]: iAF4WDPr081521: Milter (milter-sender): to error state
	Nov 15 08:41:09 rt1 sm-mta[81521]: iAF4WDPr081521: lost input channel from
aggd.static.otenet.gr [62.103.214.242] to MTA after mail
	Nov 15 08:41:09 rt1 sm-mta[81521]: iAF4WDPr081521: from=<xiz2g6f649ou@iii.com>,
size=0, class=0, nrcpts=0, proto=SMTP, daemon=MTA, relay=aggd.static.otenet.gr
[62.103.214.242]

Client was gone after issuing a MAIL FROM command.  Milter-sender
had timed out before sendmail could notice the client had gone.


	Nov 22 22:27:17 rt1 sm-mta[19947]: iAMHR0TX019947: timeout waiting for input from
[213.208.178.98] during message collect
	Nov 22 22:27:17 rt1 sm-mta[19947]: iAMHR0TX019947: from=<mailer@careerforum.ru>,
size=154399, class=0, nrcpts=1,
msgid=<003401c4d0b4$f8c187e0$6c01a8c0@careerforum.ru>, proto=ESMTP, daemon=MTA,
relay=[213.208.178.98]
	Nov 22 22:27:17 rt1 sm-mta[19947]: iAMHR0TX019947: Milter (milter-sender): write(A)
returned -1, expected 5: Broken pipe
	Nov 22 22:27:17 rt1 sm-mta[19947]: iAMHR0TX019947: Milter (milter-sender): to error state

Sendmail was going to say ABORT to milter-sender since the client
had been gone in the middle of message transmission, but milter-sender
had timed out earlier.

				* * *

It's no surprise that I haven't seen the messages in my maillog
file since I increased the milter socket timeout.  Sendmail waits
for another SMTP command for 1h by default (Timeout.command) and
it waits for a body chunk for 1h, too (Timeout.datablock).  The 1h
value was greater than the default 30m socket timeout set by
milter-sender.

I think that the value of MilterSocketTimeout should be adjusted
with the sendmail timeouts and vice versa.  At least the users could
be advised to do so.

The latter three error cases are different from the first one both
in theory and practice.  That is, I've just finished a little
experiment, in which host A was sending a large mail to host B
through a very thin pipe (9600 bits per second.)  The sendmail
timeouts were at their default value, 1h; MilterSocketTimeout was
set to 5400 sec in milter-sender.cf.  The mail tranfer took approx.
3 hours.  As soon as it had finished, the familiar error appeared
in the maillog file:

	Dec  7 00:26:20 bsd sm-mta[16574]: iB6HpGSR016574: from=<tyv@jubjub.rinet.ru>,
size=14735079, class=0, nrcpts=1, msgid=<20041206173556.GA43325@jubjub.rinet.ru>,
proto=ESMTP, daemon=IPv4, relay=jubjub.rinet.ru [195.54.192.86]
	Dec  7 00:26:20 bsd sm-mta[16574]: iB6HpGSR016574: Milter (milter-sender): write(E)
returned -1, expected 5: Broken pipe
	Dec  7 00:26:20 bsd sm-mta[16574]: iB6HpGSR016574: Milter (milter-sender): to error state

The conclusion is that just increasing MilterSocketTimeout over 1h
won't help against this kind of a "Broken pipe" error, unlike against
the other ones.  This supports the model of what's happening I
proposed above.

Thanks!

-- 
Yar



Lists Index Date Thread Search