Re: Postfix not sending SMFIC_RCPT to milter, libmilter rejecting state transition

2009-09-19 Thread Stephen Warren 
Wietse Venema wrote:
 Wietse Venema:
 Postfix VSTREAMs automatically flush output on the next read
 operation; a lot of things depend on this, including the SMTP client
 and SMTP server protocol implementations. This is how Postfix avoids
 sending silly little network packets.

 In the case of skipping Milter replies, the idea is that queued
 SMFIC_RCPT messages will be eventually be flushed when Postfix
 reads a response from the Milter application; normally that
 would be at or before the end-of-body reply.

 I am surprised that the VSTREAM doesn't flush SMFIC_RCPT as it
 should; normally one has to jump ugly hoops to lose output like
 that.
 
 My hypothesis is as follows: the automatic flush-before-read did
 not happen, because the write and the read operations were done 
 in different processes (and therefore, on different VSTREAMs).
 
 Specifically, the VSTREAM in the smtpd process did not automatically
 flush RCPT requests to the Milter socket, because the next read
 request on that Milter socket was done on a different VSTREAM in
 a cleanup process.
 
 Please see if the patch below solves the problem.

Yes, it does. Thanks.

 *** ./milter8.c-  Sat Jul 11 20:27:15 2009
 --- ./milter8.c   Fri Sep 18 16:38:11 2009
 ***
 *** 2584,2589 
 --- 2584,2596 
   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,

Re: Postfix not sending SMFIC_RCPT to milter, libmilter rejecting state transition

2009-09-18 Thread Wietse Venema 
Wietse Venema:
 Postfix VSTREAMs automatically flush output on the next read
 operation; a lot of things depend on this, including the SMTP client
 and SMTP server protocol implementations. This is how Postfix avoids
 sending silly little network packets.
 
 In the case of skipping Milter replies, the idea is that queued
 SMFIC_RCPT messages will be eventually be flushed when Postfix
 reads a response from the Milter application; normally that
 would be at or before the end-of-body reply.
 
 I am surprised that the VSTREAM doesn't flush SMFIC_RCPT as it
 should; normally one has to jump ugly hoops to lose output like
 that.

My hypothesis is as follows: the automatic flush-before-read did
not happen, because the write and the read operations were done 
in different processes (and therefore, on different VSTREAMs).

Specifically, the VSTREAM in the smtpd process did not automatically
flush RCPT requests to the Milter socket, because the next read
request on that Milter socket was done on a different VSTREAM in
a cleanup process.

Please see if the patch below solves the problem.

Wietse

*** ./milter8.c-Sat Jul 11 20:27:15 2009
--- ./milter8.c Fri Sep 18 16:38:11 2009
***
*** 2584,2589 
--- 2584,2596 
  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,

Postfix not sending SMFIC_RCPT to milter, libmilter rejecting state transition

2009-09-09 Thread Stephen Warren 
I'm writing a milter using pymilter-0.9.3, which interfaces to
libmilter1.0.1 (from sendmail 8.14.3) and running under postfix-2.6.5.
This is on Ubuntu jaunty (I have built the newer pymilter and postfix
versions in a PPA. The same postfix behaviour was observed with the
stock postfix 2.5.x package).

However, it seems that under some circumstances, postfix and libmilter
will fail to inter-operate in a couple of ways.

My milter doesn't care about RCPT TO, and hence doesn't define an
envrcpt() function in the pymilter class. This leads pymilter/libmilter
to negotiate an SMFIP value of 0x4a790. I can confirm this value from
both libmilter and postfix logs. This decodes to:

Set:

SMFIP_NOBODY, SMFIP_NR_HDR, SMFIP_NOUNKNOWN, SMFIP_NODATA, SMFIP_SKIP,
SMFIP_NR_HELO, SMFIP_NR_RCPT, SMFIP_NR_EOH

Not set:

SMFIP_NOCONNECT, SMFIP_NOHELO, SMFIP_NOMAIL, SMFIP_NORCPT, SMFIP_NOHDRS,
SMFIP_NOEOH, SMFIP_RCPT_REJ, SMFIP_NR_CONN, SMFIP_NR_MAIL,
SMFIP_NR_DATA, SMFIP_NR_UNKN, SMFIP_NR_BODY, SMFIP_HDR_LEADSPC

In particular, note that SMFIP_NORCPT is NOT set, although SMFIP_NR_RCPT is.

I dumped the communication between postfix and the milter using
wireshark. Ignoring D commands to define macros, I see C
(SMFIC_CONNECT), H (SMFIC_HELO), M (SMFIC_MAIL), L (SMFIC_HEADER), N
(SMFIC_EOH), E (SMFIC_BODYEOB). I see the same thing from libmilter's
debug output.

The problem here is that there's no R (SMFIC_RCPT) command at all,
despite the message have non-rejected recipients on the postfix side,
and despite SMFIP_NORCPT NOT being set in the negotiated flags.

This appears to be a bug in postfix. I can't see why this is happening
from the postfix source; src/milter/milter*.c doesn't seem to have
anything that would skip sending this command. The only thing I can
think of is that the output vstream/vbuf isn't being flushed out
correctly due to SMFIP_NR_RCPT being set. Note that I do see a few lines
in the postfix log that confirm postfix is attempting to send this command:

Sep  9 23:16:11 severn postfix/smtpd[18705]: event: SMFIC_RCPT; macros:
{rcpt_addr}=swar...@wwwdotorg.org {rcpt_host}=severn
.wwwdotorg.org {rcpt_mailer}=local
Sep  9 23:16:11 severn postfix/smtpd[18705]: skipping reply for event
SMFIC_RCPT from milter inet:2092

The second of these only happens after the command (request) in question
is queued into the vstream/vbuf by postfix. It should only skip waiting
for the reply, not sending the command/request.

I wouldn't care about this, except that libmilter has some state
validation code, which only allows a transition from a given command
type to specific other command types. The transition from SMFIC_MAIL to
SMFIC_HEADER without SMFIC_RCPT in-between is deemed illegal.
Consequently, libmilter calls the abort callback. However, this doesn't
seem to do anything useful, such as send an error back to postfix, drop
the socket, etc. Instead, libmilter simply never sends anything back,
leaving postfix to time out communicating with the milter. Specifically,
the postfix logs say:

Sep  9 23:16:21 severn postfix/cleanup[18710]: warning: milter
inet:2092: can't read SMFIC_BODYEOB reply packet header: Conn
ection timed out

Sep  9 23:16:21 severn postfix/cleanup[18710]: CBC29E45B7:
milter-reject: END-OF-MESSAGE from unknown[99.99.99.1]: 4.7.1 Ser
vice unavailable - try again later; from=swar...@wwwdotorg.org
to=swar...@wwwdotorg.org proto=ESMTP helo=esk.wwwdotorg.
org

This seems like a bug in libmilter; the milter protocol allows
SMFIP_NORCPT to be set, which should request skipping the SMFIC_RCPT
message). However, if that is done, libmilter will reject the transition.

Does anyone have any clues what's up? It seems a little unlikely that
nobody ever written a milter that doesn't care about RCPTs. I feel I've
got to be missing something!

To work around this, I simply defined a stub envrcpt() function in my
pymilter class. This causes an SMFIP value of 0x42790 to be negotiated,
which is the same as before except SMFIP_NR_RCPT is not set. In turn,
this causes postfix to send the SMFIC_RCPT command to the milter, and
everything works OK.

Any help greatly appreciated!