Alban Deniz:
> Hi Wietse,
>
> I ran a test case showing the unexpected filter response of SMFIR_ADDHEADER
> to
> the event SMFIC_MAIL. Here's a summary of my setup:
>
> postfix is configured with the SNFMilter milter. The master.cf file contains
> the
> line:
>
> smtp inet n - - - - smtpd -vvv
Unfortunately, this misses half of the protocol: namely, the
header/body/eom events including the "good" replies from your
milter.
To see the full converation, you also need verbose logging on the
cleanup server.
One -v is sufficient for milter logging; the rest is just noise.
Wietse
> The main.cf file contains the lines:
>
> smtpd_milters = unix:/snf-milter/socket
> milter_protocol = 2
> debug_peer_level = 9
> debug_peer_list = 192.168.1.4
>
> I'm running on Ubuntu 9.04, with postfix version 2.5.5.
>
> My test program mails a series of test messages addressed to ade...@skidmark
> from host neo to postfix running on host skidmark, using one SMTP connection.
>
> In this case, the first 18 messages were processed with no error. However,
> on
> message 19, postfix reported the unexpected filter response. The lines from
> mail.log file is attached (postfix_2009-07-10-1.log). I've also attached a
> file
> containing only the lines with SMFI[RC]_ (postfix_2009-07-10-1_SMFI.log).
>
> The first few lines seem to indicate the correct response to all SMFIC
> messages:
>
> postfix/smtpd[9470]: event: SMFIC_CONNECT; macros: j=skidmark.localdomain
> {daemon_name}=skidmark.localdomain v=Postfix 2.5.5
> postfix/smtpd[9470]: reply: SMFIR_CONTINUE data 0 bytes
> postfix/smtpd[9470]: event: SMFIC_HELO; macros: (none)
> postfix/smtpd[9470]: reply: SMFIR_CONTINUE data 0 bytes
> postfix/smtpd[9470]: event: SMFIC_MAIL; macros: {mail_addr}=ade...@neo
> postfix/smtpd[9470]: reply: SMFIR_CONTINUE data 0 bytes
> postfix/smtpd[9470]: event: SMFIC_RCPT; macros: {rcpt_addr}=ade...@skidmark
> postfix/smtpd[9470]: reply: SMFIR_CONTINUE data 0 bytes
> postfix/smtpd[9470]: skipping non-protocol event SMFIC_DATA for milter
> unix:/snf-milter/socket
> postfix/smtpd[9470]: event: SMFIC_MAIL; macros: {mail_addr}=ade...@neo
> postfix/smtpd[9470]: reply: SMFIR_CONTINUE data 0 bytes
> postfix/smtpd[9470]: event: SMFIC_RCPT; macros: {rcpt_addr}=ade...@skidmark
> postfix/smtpd[9470]: reply: SMFIR_CONTINUE data 0 bytes
> postfix/smtpd[9470]: skipping non-protocol event SMFIC_DATA for milter
> unix:/snf-milter/socket
>
> However, towards, the end, the unexpected response occurs:
>
> postfix/smtpd[9470]: event: SMFIC_MAIL; macros: {mail_addr}=ade...@neo
> postfix/smtpd[9470]: reply: SMFIR_CONTINUE data 0 bytes
> postfix/smtpd[9470]: event: SMFIC_RCPT; macros: {rcpt_addr}=ade...@skidmark
> postfix/smtpd[9470]: reply: SMFIR_CONTINUE data 0 bytes
> postfix/smtpd[9470]: skipping non-protocol event SMFIC_DATA for milter
> unix:/snf-milter/socket
> postfix/smtpd[9470]: event: SMFIC_MAIL; macros: {mail_addr}=ade...@neo
> postfix/smtpd[9470]: reply: SMFIR_ADDHEADER data 77 bytes
> postfix/smtpd[9470]: warning: milter unix:/snf-milter/socket: unexpected
> filter
> response SMFIR_ADDHEADER after event SMFIC_MAIL
>
> On earlier runs, the unexpected response occured after SMFIC_RCPT. The logs
> looked similar, so I didn't include them.
>
> My SNFMilter log indicates that smfi_addheader is invoked only in xxfi_eom().
>
> It seems to me that the logs confirm that postfix receiving an unexpected
> filter
> response, but not the reason why. However, I hope you can see something I've
> missed.
>
> I also attached the libmilter debug output for this run
> (SNFMilter_2009-07-10-1.libmilter.debug); it might give us more info on what
> libmilter is doing (called smfi_setdbg(6)). However, I am not able to
> understand the libmilter debug output. Can you recommend a reference that
> would help me understand the libmilter debug output?
>
> Also, please let me know if there are other diagnostics that might help. You
> mentioned looking at the socket communication between postfix and the milter.
>
> They communicate using a Unix domain socket. Can you recommend any software
> that might help look at the communication (e.g. a sniffer like tcpdump)?
>
> Thanks,
> Alban
>
> On Thursday 09 July 2009 07:39:40 pm Wietse Venema wrote:
> > 3) This is a good time to collect some concrete information. For
> > example, verbose Postfix logging, or some other recording, for a
> > session with the UNEXPECTED response of SMFIR_ADDHEADER.
> >
> > Wietse
>
[ Attachment, skipping... ]
[ Attachment, skipping... ]
[ Attachment, skipping... ]
