From: Rob Mueller (robmfastmail.fm)
Date: Thu Apr 15 2004 - 14:24:50 CDT

• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

I think I've found a problem with the postfix lmtp delivery agent when a
command times out.

Basically, the problem started because occasionally (once a day) we'd see
this in our log:

Apr 15 02:51:08 frontend2 postfix/lmtp[8485]: 351BC2ABBB0:
to=<someuserourdomain>,
relay=/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox], delay=13,
status=bounced (host /var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]
said: 250 2.1.5 ok (someuserourdomain) (in reply to DATA command))

So it was getting a '250' response to the DATA command. This clearly seemed
to be an out of sync issue, so I checked the log for what had happened
previously with that process and found:

Apr 15 02:50:55 frontend2 postfix/lmtp[8485]: 910532ABACD:
to=<otheruserourdomain>,
relay=/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox], delay=65,
status=deferred (conversation with
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox] timed out while sending
end of data -- message may be sent more than once)

In every case there was one of these bounce problems, the previous log entry
for that lmtp process (with the same pid) had been a timeout while sending
end of data. I tried reproducing this at home, and did manage to by
inserting a long delay in the processing of the '.' end of data command in
our lmtp server. I used a lmtp -v to get a detailed log (included at the end
of this email)

Anyway, from what I see, the problem is that:

1. While delivering a message, the postfix lmtp process sends the
'<CR><LF>.<CR><LF>' end of data notifier
2. For some reason, the end lmtp server is slow, and the lmtp
"lmtp_data_done_timeout" is reached, and the mail is deferred
3. The lmtp process does not close the connection though (see below,
lmtp_cache_connect=yes)
4. It then tries to deliver another email using the existing open connection
5. Now if the original delivery has succeeded sometime between steps 2 and
4, it returns a '250' ok response, which now leaves the lmtp process one
step out of sync

I think a temporary fix is to disable 'lmtp_cache_connect', but I'd prefer
to keep it in the long term.

From what I can see, there is no reasonable way to re-use an existing lmtp
connection if we timed out while sending any part of a command. In the time
between the timeout and re-using the connection, the command may actually
complete, leaving a response code in the pipeline from the server and thus
out of sync. So I think if any part of an lmtp transaction times out, you
have to throw away the existing connection.

Rob

----

[root]# postconf | grep mail_version
mail_version = 2.0.18-20040122

[root]# postconf | grep lmtp_
lmtp_cache_connection = yes
lmtp_connect_timeout = 30s
lmtp_data_done_timeout = 60s
lmtp_data_init_timeout = 120s
lmtp_data_xfer_timeout = 60s
lmtp_lhlo_timeout = 30s
lmtp_mail_timeout = 30s
lmtp_quit_timeout = 60s
lmtp_rcpt_timeout = 30s
lmtp_rset_timeout = 120s
lmtp_sasl_auth_enable = no
lmtp_sasl_password_maps =
lmtp_sasl_security_options = noplaintext, noanonymous
lmtp_send_xforward_command = no
lmtp_skip_quit_response = no
lmtp_tcp_port = 24
lmtp_xforward_timeout = 300s

Apr 15 11:34:01 robm postfix/lmtp[3915]: match_string: fast_flush_domains ~?
debug_peer_list
Apr 15 11:34:01 robm postfix/lmtp[3915]: match_string: fast_flush_domains ~?
fast_flush_domains
Apr 15 11:34:01 robm postfix/lmtp[3915]: dict_open: tcp:127.0.0.1:10027
Apr 15 11:34:01 robm postfix/lmtp[3915]: watchdog_create: 0x809a770 18000
Apr 15 11:34:01 robm postfix/lmtp[3915]: watchdog_stop: 0x809a770
Apr 15 11:34:01 robm postfix/lmtp[3915]: watchdog_start: 0x809a770
Apr 15 11:34:01 robm postfix/lmtp[3915]: connection established
Apr 15 11:34:01 robm postfix/lmtp[3915]: master_notify: status 0
Apr 15 11:34:01 robm postfix/lmtp[3915]: deliver_request_initial: send
initial status
Apr 15 11:34:01 robm postfix/lmtp[3915]: send attr status = 0
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
flags
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: flags
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: 3
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
queue_name
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: queue_name
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: active
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
queue_id
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: queue_id
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: 7A6C643A10
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
offset
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: offset
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: 249
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute: size
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: size
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: 299
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
nexthop
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: nexthop
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value:
unix:/var/imap/socket/lmtpprox
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
encoding
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: encoding
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: (end)
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
sender
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: sender
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value:
dummyhotmail.com
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
errors-to
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: errors-to
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value:
dummyhotmail.com
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
return-receipt
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name:
return-receipt
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: (end)
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute: time
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: time
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: 1082054025
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
client_name
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: client_name
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: robm.hp
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
client_address
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name:
client_address
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: 127.0.0.1
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
protocol_name
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: protocol_name
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: SMTP
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
helo_name
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: helo_name
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: (end)
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
offset
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: offset
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: 4294967295
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
original_recipient
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name:
original_recipient
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value:
robmhpvm1.com
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
recipient
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: recipient
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value:
robmhpvm1.com
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
offset
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute name: offset
Apr 15 11:34:01 robm postfix/lmtp[3915]: input attribute value: 0
Apr 15 11:34:01 robm postfix/lmtp[3915]: deliver_request_get: file
active/7/7A6C643A10
Apr 15 11:34:01 robm postfix/lmtp[3915]: deliver_message: from
dummyhotmail.com
Apr 15 11:34:01 robm postfix/lmtp[3915]: lmtp_connect_unix: trying:
/var/imap/socket/lmtpprox...
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 220 robm.hp LMTP Proxy
ready
Apr 15 11:34:01 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: LHLO hpvm1.com
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250-robm.hp
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250-8BITMIME
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]:
250-ENHANCEDSTATUSCODES
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250-PIPELINING
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250-SIZE
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250-IGNOREQUOTA
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250 ORCPT
Apr 15 11:34:01 robm postfix/lmtp[3915]: server features: 0x40e
Apr 15 11:34:01 robm postfix/lmtp[3915]: Using LMTP PIPELINING, send buffer
size is 4096
Apr 15 11:34:01 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: MAIL
FROM:<dummyhotmail.com> SIZE=299
Apr 15 11:34:01 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: RCPT
TO:<robmhpvm1.com> ORCPT=rfc822;<robmhpvm1.com>
Apr 15 11:34:01 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: DATA
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250 2.1.0 ok
(dummyhotmail.com SIZE=299)
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250 2.1.5 ok
(robmhpvm1.com)
Apr 15 11:34:01 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 354 go ahead
Apr 15 11:34:01 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: .
Apr 15 11:35:01 robm postfix/lmtp[3915]: connect to subsystem private/defer
Apr 15 11:35:01 robm postfix/lmtp[3915]: send attr nrequest = 0
Apr 15 11:35:01 robm postfix/lmtp[3915]: send attr flags = 0
Apr 15 11:35:01 robm postfix/lmtp[3915]: send attr queue_id = 7A6C643A10
Apr 15 11:35:01 robm postfix/lmtp[3915]: send attr original_recipient =
robmhpvm1.com
Apr 15 11:35:01 robm postfix/lmtp[3915]: send attr recipient =
robmhpvm1.com
Apr 15 11:35:01 robm postfix/lmtp[3915]: send attr offset = 4294967295
Apr 15 11:35:01 robm postfix/lmtp[3915]: send attr status = 4.0.0
Apr 15 11:35:01 robm postfix/lmtp[3915]: send attr action = delayed
Apr 15 11:35:01 robm postfix/lmtp[3915]: send attr reason = conversation
with /var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox] timed out while
sending end of data -- message may be sent more than once
Apr 15 11:35:01 robm postfix/lmtp[3915]: private/defer socket: wanted
attribute: status
Apr 15 11:35:02 robm postfix/lmtp[3915]: input attribute name: status
Apr 15 11:35:02 robm postfix/lmtp[3915]: input attribute value: 0
Apr 15 11:35:02 robm postfix/lmtp[3915]: private/defer socket: wanted
attribute: (list terminator)
Apr 15 11:35:02 robm postfix/lmtp[3915]: input attribute name: (end)
Apr 15 11:35:02 robm postfix/lmtp[3915]: 7A6C643A10: to=<robmhpvm1.com>,
relay=/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox], delay=77,
status=deferred (conversation with /var/imap/socket/lmtpprox[/v
ar/imap/socket/lmtpprox] timed out while sending end of data -- message may
be sent more than once)
Apr 15 11:35:02 robm postfix/lmtp[3915]: flush_add: site hpvm1.com id
7A6C643A10
Apr 15 11:35:02 robm postfix/lmtp[3915]: match_hostname: hpvm1.com ~?
localhost
Apr 15 11:35:02 robm postfix/lmtp[3915]: match_hostname: hpvm1.com ~?
tcp:127.0.0.1:10027(0,100)
Apr 15 11:35:02 robm postfix/lmtp[3915]: dict_tcp_lookup: key hpvm1.com
Apr 15 11:35:02 robm postfix/lmtp[3915]: dict_tcp_lookup: send: get
hpvm1.com
Apr 15 11:35:02 robm postfix/lmtp[3915]: dict_tcp_lookup: recv: 200
hpvm1.com
Apr 15 11:35:02 robm postfix/lmtp[3915]: dict_tcp_lookup: found: hpvm1.com
Apr 15 11:35:02 robm postfix/lmtp[3915]: connect to subsystem public/flush
Apr 15 11:35:02 robm postfix/lmtp[3915]: send attr request = add
Apr 15 11:35:02 robm postfix/lmtp[3915]: send attr site = hpvm1.com
Apr 15 11:35:02 robm postfix/lmtp[3915]: send attr queue_id = 7A6C643A10
Apr 15 11:35:02 robm postfix/lmtp[3915]: public/flush socket: wanted
attribute: status
Apr 15 11:35:02 robm postfix/lmtp[3915]: input attribute name: status
Apr 15 11:35:02 robm postfix/lmtp[3915]: input attribute value: 0
Apr 15 11:35:02 robm postfix/lmtp[3915]: public/flush socket: wanted
attribute: (list terminator)
Apr 15 11:35:02 robm postfix/lmtp[3915]: input attribute name: (end)
Apr 15 11:35:02 robm postfix/lmtp[3915]: flush_add: site hpvm1.com id
7A6C643A10 status 0
Apr 15 11:35:02 robm postfix/lmtp[3915]: name_mask: resource
Apr 15 11:35:02 robm postfix/lmtp[3915]: name_mask: software
Apr 15 11:35:02 robm postfix/lmtp[3915]: deliver_request_final: send: "" -1
Apr 15 11:35:02 robm postfix/lmtp[3915]: send attr reason =
Apr 15 11:35:02 robm postfix/lmtp[3915]: send attr status = 4294967295
Apr 15 11:35:02 robm postfix/lmtp[3915]: master_notify: status 1
Apr 15 11:35:02 robm postfix/lmtp[3915]: connection closed
Apr 15 11:35:02 robm postfix/lmtp[3915]: watchdog_stop: 0x809a770
Apr 15 11:35:02 robm postfix/lmtp[3915]: watchdog_start: 0x809a770
Apr 15 11:35:09 robm postfix/qmgr[3540]: 7A6C643A10:
from=<dummyhotmail.com>, size=299, nrcpt=1 (queue active)
Apr 15 11:35:09 robm postfix/lmtp[3915]: connection established
Apr 15 11:35:09 robm postfix/lmtp[3915]: master_notify: status 0
Apr 15 11:35:09 robm postfix/lmtp[3915]: deliver_request_initial: send
initial status
Apr 15 11:35:09 robm postfix/lmtp[3915]: send attr status = 0
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
flags
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: flags
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: 3
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
queue_name
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: queue_name
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: active
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
queue_id
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: queue_id
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: 7A6C643A10
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
offset
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: offset
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: 249
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute: size
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: size
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: 299
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
nexthop
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: nexthop
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value:
unix:/var/imap/socket/lmtpprox
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
encoding
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: encoding
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: (end)
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
sender
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: sender
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value:
dummyhotmail.com
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
errors-to
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: errors-to
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value:
dummyhotmail.com
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
return-receipt
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name:
return-receipt
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: (end)
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute: time
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: time
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: 1082054025
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
client_name
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: client_name
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: robm.hp
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
client_address
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name:
client_address
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: 127.0.0.1
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
protocol_name
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: protocol_name
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: SMTP
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
helo_name
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: helo_name
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: (end)
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
offset
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: offset
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: 4294967295
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
original_recipient
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name:
original_recipient
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value:
robmhpvm1.com
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
recipient
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: recipient
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value:
robmhpvm1.com
Apr 15 11:35:09 robm postfix/lmtp[3915]: lmtp socket: wanted attribute:
offset
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute name: offset
Apr 15 11:35:09 robm postfix/lmtp[3915]: input attribute value: 0
Apr 15 11:35:09 robm postfix/lmtp[3915]: deliver_request_get: file
active/7/7A6C643A10
Apr 15 11:35:09 robm postfix/lmtp[3915]: deliver_message: from
dummyhotmail.com
Apr 15 11:35:09 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: RSET
Apr 15 11:37:02 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250 2.1.5 Ok
Apr 15 11:37:02 robm postfix/lmtp[3915]: deliver_message: reusing (count 1)
session with: /var/imap/socket/lmtpprox
Apr 15 11:37:02 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: MAIL
FROM:<dummyhotmail.com> SIZE=299
Apr 15 11:37:02 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250 2.0.0 ok
Apr 15 11:37:02 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: RCPT
TO:<robmhpvm1.com> ORCPT=rfc822;<robmhpvm1.com>
Apr 15 11:37:02 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: DATA
Apr 15 11:37:02 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250 2.1.0 ok
(dummyhotmail.com SIZE=299)
Apr 15 11:37:02 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 250 2.1.5 ok
(robmhpvm1.com)
Apr 15 11:37:02 robm postfix/lmtp[3915]: connect to subsystem private/bounce
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr nrequest = 0
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr flags = 0
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr queue_id = 7A6C643A10
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr original_recipient =
robmhpvm1.com
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr recipient =
robmhpvm1.com
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr offset = 4294967295
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr status = 5.0.0
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr action = failed
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr reason = host
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox] said: 250 2.1.5 ok
(robmhpvm1.com) (in reply to DATA command)
Apr 15 11:37:02 robm postfix/lmtp[3915]: private/bounce socket: wanted
attribute: status
Apr 15 11:37:02 robm postfix/lmtp[3915]: input attribute name: status
Apr 15 11:37:02 robm postfix/lmtp[3915]: input attribute value: 0
Apr 15 11:37:02 robm postfix/lmtp[3915]: private/bounce socket: wanted
attribute: (list terminator)
Apr 15 11:37:02 robm postfix/lmtp[3915]: input attribute name: (end)
Apr 15 11:37:02 robm postfix/lmtp[3915]: 7A6C643A10: to=<robmhpvm1.com>,
relay=/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox], delay=197,
status=bounced (host /var/imap/socket/lmtpprox[/var/imap/socke
t/lmtpprox] said: 250 2.1.5 ok (robmhpvm1.com) (in reply to DATA command))
Apr 15 11:37:02 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: RSET
Apr 15 11:37:02 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 354 go ahead
Apr 15 11:37:02 robm postfix/lmtp[3915]: name_mask: resource
Apr 15 11:37:02 robm postfix/lmtp[3915]: name_mask: software
Apr 15 11:37:02 robm postfix/lmtp[3915]: deliver_request_final: send: "" 0
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr reason =
Apr 15 11:37:02 robm postfix/lmtp[3915]: send attr status = 0
Apr 15 11:37:02 robm postfix/lmtp[3915]: master_notify: status 1
Apr 15 11:37:02 robm postfix/lmtp[3915]: connection closed
Apr 15 11:37:02 robm postfix/lmtp[3915]: watchdog_stop: 0x809a770
Apr 15 11:37:02 robm postfix/lmtp[3915]: watchdog_start: 0x809a770
Apr 15 11:37:02 robm postfix/cleanup[3963]: 99A4243A4F:
message-id=<20040415183702.99A4243A4Fhpvm1.com>
Apr 15 11:37:02 robm postfix/qmgr[3540]: 99A4243A4F: from=<>, size=2041,
nrcpt=1 (queue active)
Apr 15 11:37:02 robm postfix/qmgr[3540]: 7A6C643A10: removed
Apr 15 11:37:10 robm postfix/smtp[3967]: 99A4243A4F: to=<dummyhotmail.com>,
relay=mx2.hotmail.com[65.54.166.230], delay=8, status=bounced (host
mx2.hotmail.com[65.54.166.230] said: 550 Requested action not
taken: mailbox unavailable (in reply to RCPT TO command))
Apr 15 11:37:10 robm postfix/qmgr[3540]: 99A4243A4F: removed
Apr 15 11:37:32 robm postfix/lmtp[3915]: idle timeout -- exiting
Apr 15 11:37:32 robm postfix/lmtp[3915]: >
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: QUIT
Apr 15 11:38:02 robm postfix/lmtp[3915]: <
/var/imap/socket/lmtpprox[/var/imap/socket/lmtpprox]: 421 4.4.1 bye idle for
too long
Apr 15 11:38:02 robm postfix/lmtp[3915]: cleanup: just closed down session

• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]