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... ]