Andreas Winkelmann wrote: > Am Friday 15 September 2006 04:52 schrieb Hardi Gunawan: > >> My email server experiencing a delivery problem. >> Here's the log: >> relay=/var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp], >> delay=0, status=deferred (remote protocol error in >> reply from >> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp] >> while sending end of data -- message may be sent more >> than once) >> > > Hmm, it seems, that Server (Cyrus lmtpd) and Client (Postfix lmtp) are out of > sync. I've never seen that on Unix-Sockets. > > Turn on verbose Logging in Postfix. master.cf: > > lmtp ..... lmtp -v > or > lmtp ..... lmtp -v -v > > And show the conservation. Here is abbreviated log of a failed LMTP transaction: > MAIL FROM:<lpechacek@xxxxxxxxxxx <mailto:lpechacek@xxxxxxx>> SIZE=15311 > RCPT TO:<test@xxxxxxxxxxx <mailto:flow@xxxxxxxxxxxxxxxxxxxxx>> > DATA < 250 2.1.0 ok < 250 2.1.5 ok < 354 go ahead > . < 7 lockers # Postfix reports non-LMTP response and resets the transaction > RSET < 250 2.1.5 Ok # this is final response to DATA command, now # are the client and server out of sync > MAIL FROM:<lpechacek@xxxxxxxxxxx <mailto:lpechacek@xxxxxxx>> SIZE=15311 > RCPT TO:<test@xxxxxxxxxxx <mailto:flow@xxxxxxxxxxxxxxxxxxxxx>> > DATA < 250 2.0.0 ok < 250 2.1.0 ok < 250 2.1.5 ok # responses to RSET (delayed), MAIL FROM and RCPT TO (both OK), the first # response is extra; Postfix interprets the last 250 response as response # to DATA command and bounces (!) the message > RSET < 354 go ahead # delayed 354 response to DATA :( > RSET In this case the obvious reason for the error is the "7 lockers" line that leaked from BDB. It makes only small harm itself but causes the next message to be bounced due to protocol error in case the LMTP connection is reused. Workaround to the bounces is simple - "lmtp_cache_connection = no" in Postfix's main.cf. I think Cyrus should keep from writing the 250 response when the reset is already sent by client. I thought the response was in the output buffer at the time RSET arrives and simply clearing the buffer would do the work but it seems to be a little bit more complicated. Reading the next command with prot_fgets at lmtpengine.c:1145 flushes the output buffer so that the unfortunate response gets to the client. I believe Cyrus should peek input stream for RSET before flushing the output buffer but I still haven't found the way how to implement it. Additional info: OS SUSE SLES10, Postfix 2.2.9, Cyrus 2.2.12, Berkeley DB 4.3.29, delivery through local Unix socket (mailbox_transport = lmtp:unix:/var/lib/imap/socket/lmtp), reproduce with "smtp-source -l 15000 -m 1000 -s 100 -t test -f lpechacek@xxxxxxxxxxx localhost" Similar out-of-sync problem is described at http://archives.neohapsis.com/archives/postfix/2005-11/1977.html Hope, this helps. Libor Pechacek ---- Cyrus Home Page: http://cyrusimap.web.cmu.edu/ Cyrus Wiki/FAQ: http://cyrusimap.web.cmu.edu/twiki List Archives/Info: http://asg.web.cmu.edu/cyrus/mailing-list.html
