Re: Weird bounces with Postfix, LMTP and Cyrus

From: Christian Theune (no email)
Date: Fri Dec 02 2005 - 01:22:16 EST

Next message: Victor Duchovni: "Re: Weird bounces with Postfix, LMTP and Cyrus"

Previous message: Jahidul Hasan: "smtp process crash !"
Maybe in reply to: Christian Theune: "Re: Weird bounces with Postfix, LMTP and Cyrus"
Next in thread: Victor Duchovni: "Re: Weird bounces with Postfix, LMTP and Cyrus"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ] [ attachment ]

Hmm. Ok, I've taken a bit more log data that might help you:

This is a first mail that bounces:

Dec 1 15:02:41 uter postfix/lmtp[11210]: deliver_message: from

Dec 1 15:02:41 uter postfix/lmtp[11210]: >
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: RSET
Dec 1 15:02:41 uter postfix/lmtp[11210]: <
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.0.0 ok
Dec 1 15:02:41 uter postfix/lmtp[11210]: deliver_message: reusing
(count 5) session with: /var/imap/socket/lmtp
Dec 1 15:02:41 uter postfix/lmtp[11210]: >
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: MAIL
FROM:<> SIZE=6620
Dec 1 15:02:41 uter postfix/lmtp[11210]: >
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: RCPT
TO:<>
Dec 1 15:02:41 uter postfix/lmtp[11210]: >
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: RCPT
TO:<>
Dec 1 15:02:41 uter postfix/lmtp[11210]: >
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: DATA
Dec 1 15:02:41 uter postfix/lmtp[11210]: <
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.1.0 ok
Dec 1 15:02:41 uter postfix/lmtp[11210]: <
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.0.0 ok
Dec 1 15:02:41 uter postfix/lmtp[11210]: <
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.0.0 ok
Dec 1 15:02:41 uter postfix/lmtp[11210]: <
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.1.0 ok
Dec 1 15:02:41 uter postfix/lmtp[11210]: connect to subsystem private/bounce
Dec 1 15:02:41 uter postfix/bounce[11366]: connection established
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr nrequest = 0
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr flags = 0
Dec 1 15:02:41 uter postfix/bounce[11366]: master_notify: status 0
Dec 1 15:02:41 uter postfix/bounce[11366]: bounce socket: wanted
attribute: nrequest
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr queue_id = 2BAE72974
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr original_recipient
=
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr recipient =

Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr offset = 355
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr status = 5.0.0
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr action = failed
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr reason = host
/var/imap/socket/lmtp[/var/imap/socket/lmtp] said: 250 2.1.0 ok (in
reply to DATA command)
Dec 1 15:02:41 uter postfix/lmtp[11210]: private/bounce socket:
wanted attribute: status

The next mail is related to that, it looks like the bounce
notification and seems to get through to me (as I get those bounces):

Dec 1 15:02:41 uter postfix/bounce[11366]: bounce_append_proto:
flags=0x0 service=bounce id=2BAE72974 org_toto= off=355 stat=5.0.0 act=failed why=host
/var/imap/socket/lmtp[/var/imap/socket/lmtp] said: 250 2.1.0 ok (in
reply to DATA command)
Dec 1 15:02:41 uter postfix/bounce[11366]: send attr status = 0
Dec 1 15:02:41 uter postfix/bounce[11366]: master_notify: status 1
Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute name: status
Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute value: 0
Dec 1 15:02:41 uter postfix/bounce[11366]: connection closed
Dec 1 15:02:41 uter postfix/lmtp[11210]: private/bounce socket:
wanted attribute: (list terminator)
Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute name: (end)
Dec 1 15:02:41 uter postfix/lmtp[11210]: 2BAE72974:
to=<>, orig_to=<>,
relay=/var/imap/socket/lmtp[/var/imap/socket/lmtp], delay=0,
status=bounced (host /var/imap/socket/lmtp[/var/imap/socket/lmtp]
said: 250 2.1.0 ok (in reply to DATA command))
Dec 1 15:02:41 uter postfix/bounce[11366]: connection established
Dec 1 15:02:41 uter postfix/lmtp[11210]: connect to subsystem private/bounce
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr nrequest = 0
Dec 1 15:02:41 uter postfix/bounce[11366]: master_notify: status 0
Dec 1 15:02:41 uter postfix/bounce[11366]: bounce socket: wanted
attribute: nrequest
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr flags = 0
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr queue_id = 2BAE72974
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr original_recipient
=
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr recipient =

Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr offset = 399
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr status = 5.0.0
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr action = failed
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr reason = host
/var/imap/socket/lmtp[/var/imap/socket/lmtp] said: 250 2.1.0 ok (in
reply to DATA command)
Dec 1 15:02:41 uter postfix/lmtp[11210]: private/bounce socket:
wanted attribute: status

After that the same mail tries again on (rewritten to
) and fails again while talking to the lmtp:

Dec 1 15:02:41 uter postfix/bounce[11366]: bounce_append_proto:
flags=0x0 service=bounce id=2BAE72974 org_toto= off=399 stat=5.0.0 act=failed why=host
/var/imap/socket/lmtp[/var/imap/socket/lmtp] said: 250 2.1.0 ok (in
reply to DATA command)
Dec 1 15:02:41 uter postfix/bounce[11366]: send attr status = 0
Dec 1 15:02:41 uter postfix/bounce[11366]: master_notify: status 1
Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute name: status
Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute value: 0
Dec 1 15:02:41 uter postfix/bounce[11366]: connection closed
Dec 1 15:02:41 uter postfix/lmtp[11210]: private/bounce socket:
wanted attribute: (list terminator)
Dec 1 15:02:41 uter postfix/lmtp[11210]: input attribute name: (end)
Dec 1 15:02:41 uter postfix/lmtp[11210]: 2BAE72974:
to=<>, orig_to=<>,
relay=/var/imap/socket/lmtp[/var/imap/socket/lmtp], delay=0,
status=bounced (host /var/imap/socket/lmtp[/var/imap/socket/lmtp]
said: 250 2.1.0 ok (in reply to DATA command))
Dec 1 15:02:41 uter postfix/lmtp[11210]: >
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: RSET
Dec 1 15:02:41 uter postfix/lmtp[11210]: <
/var/imap/socket/lmtp[/var/imap/socket/lmtp]: 250 2.1.5 ok
Dec 1 15:02:41 uter postfix/lmtp[11210]: name_mask: resource
Dec 1 15:02:41 uter postfix/lmtp[11210]: name_mask: software
Dec 1 15:02:41 uter postfix/lmtp[11210]: deliver_request_final: send: "" 0
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr reason =
Dec 1 15:02:41 uter postfix/lmtp[11210]: send attr status = 0

On 12/1/05, Wietse Venema <> wrote:
> It would still be worthwhile to find out if the last
> delivery was OK by the process with the failed RSET.

I hope this is enough information. I'm not sure, but it looks like the
mail before the RSET was broken already.

After switching off connection reuse everything works fine. I haven't
found another bounce with those errors in the last 15 hours.

Thanks,
Christian

Next message: Victor Duchovni: "Re: Weird bounces with Postfix, LMTP and Cyrus"

Previous message: Jahidul Hasan: "smtp process crash !"
Maybe in reply to: Christian Theune: "Re: Weird bounces with Postfix, LMTP and Cyrus"
Next in thread: Victor Duchovni: "Re: Weird bounces with Postfix, LMTP and Cyrus"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ] [ attachment ]

Invaluement Anti-Spam DNSBLs