Bounced email although LMTP returns an ok

[Andreas Winkelmann]

Am Wednesday 27 September 2006 14:40 schrieb Hardi Gunawan:

> It seems I've many problems with Cyrus on SuSE SLES10.
>
> My current problem is that there are many bounces on
> the server, but the LMTP returns an "ok".  Here's the
> log on the server:
>
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: >
> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp]:
> RSET
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: <
> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp]:
> 250 2.1.5 Ok
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]:
> deliver_message: reusing (count 4) session with:
> /var/lib/imap/socket/lmtp
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: >
> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp]:
> MAIL FROM:<xxxxxxxxxxxxxxxxxxxxxxxx> SIZE=130532
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: >
> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp]:
> RCPT TO:<xxxxxxxxxxxxxxxxxxxxxx>
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: >
> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp]:
> DATA
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: <
> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp]:

Pipelining is used. Cyrus Presents it and Postfix uses it. Pipelining is, 
sending Commands without waiting for a Response from the Server on each 
Command.

The Server gives the Responses after the DATA.

> 250 2.0.0 ok

This is the OK for MAIL FROM:

> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: <
> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp]:
> 250 2.1.0 ok

This is the OK for RCPT TO:

> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: <
> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp]:
> 250 2.1.5 ok

This is a "250 2.1.5..." after the DATA. This is wrong. The Server Response 
after DATA should be "354 ..."

Something seems to be out of sync.

For a fast Fix, you can disable PIPELINIG in the Postfix lmtp-Client.

Is there a Router between Postfix and Cyrus? Maybe capturing the 
Network-Traffic between Postfix and Cyrus would be a way to debug this. Best 
to do it on Both sides.

> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: connect to
> subsystem private/bounce
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: send attr
> nrequest = 0
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: send attr
> flags = 0
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: send attr
> queue_id = D3EC7A709
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: send attr
> original_recipient = xxxxxxxxxxxxxxxxxxxxxxxxx
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: send attr
> recipient = xxxxxxxxxxxxxxxxxxxxxxxx
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: send attr
> offset = 18446744073709551615
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: send attr
> status = 5.0.0
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: send attr
> action = failed
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: send attr
> reason = host
> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp]
> said:
> 250 2.1.5 ok (in reply to DATA command)
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]:
> private/bounce socket: wanted attribute: status
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: input
> attribute name: status
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: input
> attribute value: 0
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]:
> private/bounce socket: wanted attribute: (list
> terminator)
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: input
> attribute name: (end)
> Sep 26 20:12:29 mail2 postfix/lmtp[14840]: D3EC7A709:
> to=<xxxxxxxxxxxxxxxxxxxxxxxx>,
> relay=/var/lib/imap/socket/lmtp[/var/
> lib/imap/socket/lmtp], delay=0, status=bounced (host
> /var/lib/imap/socket/lmtp[/var/lib/imap/socket/lmtp]
> said: 250 2.1.5 ok (
> in reply to DATA command))
>
> I'm not sure the problem is on the postfix or cyrus
> side, though.



-- 
	Andreas