From: Sean Reifschneider on
FYI: Using protocol version 3 is also causing the same errors to be logged.
So we've tried 2, 3, 4, and 6.

Thanks,
Sean
--
Sean Reifschneider, Member of Technical Staff <jafo(a)tummy.com>
tummy.com, ltd. - Linux Consulting since 1995: Ask me about High Availability

From: Wietse Venema on
Wietse Venema:
> Sean Reifschneider:
> > On 03/18/2010 05:57 AM, Wietse Venema wrote:
> > > If the Postfix milter_protocol setting specifies a too high
> > > version, the libmilter library simply hangs up without logging
> >
> > We've tried protocol versions 2, 4, and 6 with the same error. We've also
> > tried two different versions of the libmilter: 8.13 and 8.14. We're trying
> > version 3 of the protocol right now, but it will take a while to know for
> > sure what the result of that is. It only happens for a few specific users
> > who only send mail a few times a day.
> >
> > My experience in the past has been that having the wrong protocol version
> > causes problems on all the milter interactions. In this case the milter is
> > working fine for almost all the requests, except for a couple of users (out
> > of thousands).
>
> Unfortunately, it seems that my crystal ball isn't working today.

FYI, The crystal ball is still blank.

In the mean time, it would help if you could provide verbose (smtpd
AND cleanup) logging for a failed session. Please include information
about Postfix version and configuration, as well as python filter
version and configuration, and libmilter version information. Then,
I'll see if the problem can be reproduced.

Wietse

From: Sean Reifschneider on
On 03/19/2010 04:38 AM, Wietse Venema wrote:
> In the mean time, it would help if you could provide verbose (smtpd
> AND cleanup) logging for a failed session. Please include information

We're trying to get the logging information. Versions we've seen this on
include:

postfix-2.5.9
postfix-2.5.1
pymilter-0.9.3 (with libmilter 8.14)
pymilter-0.8.6 (which I believe was against libmilter 8.13)
milter protocols: 2, 3, 4, and 6.

Postfix relevant configs:

milter_content_timeout = 3000 # tried 300, 600, and 3000
milter_default_action = accept # newly added to see if it helps
milter_protocol = 6
milter_connect_macros = b j _ {daemon_name} {if_name} {if_addr}
smtpd_milters = inet:127.0.0.1:2092

The milter is configured as:

socketname = 'inet:2092'
Milter.factory = OurMilter
Milter.set_flags(Milter.ADDHDRS)
Milter.runmilter('ourmilter', socketname, 240)

The problem with trying to reproduce it is, we can't really reproduce it at
will yet. As I've said before, this mail server has maybe 5 thousand users,
only something like 3 users are seeing this problem.

So, we're still trying to work on information to allow us to reproduce it,
so far only the customers involved can reproduce it.

So, I'd say don't spend too much time on trying to reproduce it -- that's
our job. :-) We were just hoping there was something obvious in the
configuration or similar.

Thanks,
Sean
--
Sean Reifschneider, Member of Technical Staff <jafo(a)tummy.com>
tummy.com, ltd. - Linux Consulting since 1995: Ask me about High Availability

From: Wietse Venema on
Sean Reifschneider:
> On 03/19/2010 04:38 AM, Wietse Venema wrote:
> > In the mean time, it would help if you could provide verbose (smtpd
> > AND cleanup) logging for a failed session. Please include information
>
> We're trying to get the logging information. Versions we've seen this on
> include:
>
> postfix-2.5.9
> postfix-2.5.1
> pymilter-0.9.3 (with libmilter 8.14)
> pymilter-0.8.6 (which I believe was against libmilter 8.13)
> milter protocols: 2, 3, 4, and 6.

I have only one milter change for Postfix 2.5, and that is below
(and that will also included with Postfix 2.5.10 later today).

This is for a problem that Stephen Warren reported half a year ago
that he ran into with pymilter-0.9.3, and that gave trouble with
SMFIC_HEADER.

Wietse

20090918

Bugfix (introduced Postfix 2.3): with Milter RCPT TO replies
turned off, there was no automatic flush-before-read on the
smtpd-to-milter stream, because the read was done on the
cleanup-to-milter stream. Problem reported by Stephen Warren.
File: milter/milter8.c.

diff -cr /var/tmp/postfix-2.5.9/src/milter/milter8.c postfix-2.5.10/src/milter/milter8.c
*** /var/tmp/postfix-2.5.9/src/milter/milter8.c Sat Jul 11 20:28:52 2009
--- postfix-2.5.10/src/milter/milter8.c Mon Oct 5 16:44:48 2009
***************
*** 2528,2533 ****
--- 2528,2540 ----
if (msg_verbose)
msg_info("%s: milter %s", myname, milter->m.name);

+ /*
+ * The next read on this Milter socket happens in a different process. It
+ * will not automatically flush the output buffer in this process.
+ */
+ if (milter->fp)
+ vstream_fflush(milter->fp);
+
if (attr_print(stream, ATTR_FLAG_MORE,
ATTR_TYPE_STR, MAIL_ATTR_MILT_NAME, milter->m.name,
ATTR_TYPE_INT, MAIL_ATTR_MILT_VERS, milter->version,

From: Sean Reifschneider on
On 03/22/2010 03:22 PM, Wietse Venema wrote:
> This is for a problem that Stephen Warren reported half a year ago
> that he ran into with pymilter-0.9.3, and that gave trouble with
> SMFIC_HEADER.

Ah, right. We can try that change, but I'm not optimistic that that will
help this problem. I'm fairly familiar with Stephen's problem, his milter
is based on the milter code that we're using, he's a good friend of mine
and I'm the one that suggested he use a milter to do what he wanted, and
helped him get started with it.

But, we'll give it a try.

Sean
--
Sean Reifschneider, Member of Technical Staff <jafo(a)tummy.com>
tummy.com, ltd. - Linux Consulting since 1995: Ask me about High Availability