Deferred email with remote protocol error in reply

[Libor Pechacek]

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 at fm.clnet.cz <mailto:lpechacek at suse.de>> SIZE=15311
 > RCPT TO:<test at fm.clnet.cz <mailto:flow at tormore.hwlab.suse.de>>
 > 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 at fm.clnet.cz <mailto:lpechacek at suse.de>> SIZE=15311
 > RCPT TO:<test at fm.clnet.cz <mailto:flow at tormore.hwlab.suse.de>>
 > 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 at fm.clnet.cz localhost"

Similar out-of-sync problem is described at
http://archives.neohapsis.com/archives/postfix/2005-11/1977.html

Hope, this helps.

Libor Pechacek