| Main Archive Page > Month Archives > postfix-users archives |
Re: Conversation timed out while sending end of data
From: Reindl Harald <h.reindl_at_nospam>Date: Sat Mar 05 2011 - 15:06:38 GMT
To: postfix-users@postfix.org
Why in the world do you start with a debug-log instead a normal
one with filtered where you see a problem?
> mx1.hotmail.com[65.54.188.94]:25: 220 BAY0-MC2-F32.Bay0.hotmail.com
> Sending unsolicited commercial or bulk e-mail to Microsoft's compu
sounds like hotmail is pissed off about to many mails from your server
Am 05.03.2011 16:02, schrieb Andy:
> Hi all.
> Since yesterday we are having major issues with our outbound relay,
> mostly with Hotmail/Live servers. Gmail & others seems to work fine.
> I updated postfix to the latest squeeze version and turned on debugging:
>
>
> Mar 5 14:43:11 out postfix/smtp[19842]: name_mask: resource
> Mar 5 14:43:11 out postfix/smtp[19842]: name_mask: software
> Mar 5 14:43:12 out postfix/smtp[19842]: vstream_buf_get_ready: fd 12 got 310
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 220 BAY0-MC2-F32.Bay0.hotmail.com
> Sending unsolicited commercial or bulk e-mail to Microsoft's compu
> Mar 5 14:43:12 out postfix/smtp[19842]: >
> mx1.hotmail.com[65.54.188.94]:25: EHLO out.vp44.net
> Mar 5 14:43:12 out postfix/smtp[19842]: vstream_fflush_some: fd 12 flush 19
> Mar 5 14:43:12 out postfix/smtp[19842]: vstream_buf_get_ready: fd 12 got 189
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250-BAY0-MC2-F32.Bay0.hotmail.com
> (3.12.0.56) Hello [178.238.138.56]
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250-SIZE 36909875
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250-PIPELINING
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250-8bitmime
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250-BINARYMIME
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250-CHUNKING
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250-AUTH LOGIN
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250-AUTH=LOGIN
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250 OK
> Mar 5 14:43:12 out postfix/smtp[19842]: server features: 0x100f size 36909875
> Mar 5 14:43:12 out postfix/smtp[19842]: Using ESMTP PIPELINING, TCP
> send buffer size is 4096
> Mar 5 14:43:12 out postfix/smtp[19842]: >
> mx1.hotmail.com[65.54.188.94]:25: MAIL FROM:<user@vp44.net> SIZE=2178
> Mar 5 14:43:12 out postfix/smtp[19842]: >
> mx1.hotmail.com[65.54.188.94]:25: RCPT TO:<user@hotmail.com>
> Mar 5 14:43:12 out postfix/smtp[19842]: >
> mx1.hotmail.com[65.54.188.94]:25: DATA
> Mar 5 14:43:12 out postfix/smtp[19842]: vstream_fflush_some: fd 12 flush 86
> Mar 5 14:43:12 out postfix/smtp[19842]: vstream_buf_get_ready: fd 12 got 33
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250 user@vp44.net....Sender OK
> Mar 5 14:43:12 out postfix/smtp[19842]: vstream_buf_get_ready: fd 12 got 37
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 250 user@hotmail.com
> Mar 5 14:43:12 out postfix/smtp[19842]: vstream_buf_get_ready: fd 12 got 46
> Mar 5 14:43:12 out postfix/smtp[19842]: <
> mx1.hotmail.com[65.54.188.94]:25: 354 Start mail input; end with
> <CRLF>.<CRLF>
> Mar 5 14:43:12 out postfix/smtp[19842]: vstream_buf_get_ready: fd 11 got 2182
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 55 data Received:
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 52 data ?by out.vp
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 76 data ?for <skor
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 69 data DKIM-Signa
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 55 data ?:reply-to
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 65 data ?:content-
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 65 data ?dQ=; b=GM
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 65 data ?uYGjZ12iw
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 52 data ?ajZOMbrqm
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 69 data DomainKey-
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 55 data ?:reply-to
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 65 data ?:content-
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 65 data ?jwPkuIjE4
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 65 data ?ikGtx65I5
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 26 data ?C29xfMA7F
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 61 data Received:
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 52 data ?by out.vp
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 76 data ?for <skor
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 48 data Received:
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 53 data ?by mail.v
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 76 data ?for <skor
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 48 data X-Virus-Sc
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 42 data Received:
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 67 data ?by localh
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 65 data ?with ESMT
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 38 data ?Sat, 5 M
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 101 data Received:
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 39 data ?(Authenti
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 54 data ?by mail.v
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 76 data ?for <skor
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 13 data Subject: t
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 28 data From: Art
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 24 data Reply-To:
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 34 data To: skorpi
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 24 data Content-Ty
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 37 data Date: Sat,
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 54 data Message-ID
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 17 data Mime-Versi
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 27 data X-Mailer:
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 31 data Content-Tr
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 0 data
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 4 data test
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 0 data
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 0 data
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type N len 0 data
> Mar 5 14:43:12 out postfix/smtp[19842]: rec_get: type X len 0 data
> Mar 5 14:43:12 out postfix/smtp[19842]: > mx1.hotmail.com[65.54.188.94]:25: .
> Mar 5 14:43:12 out postfix/smtp[19842]: >
> mx1.hotmail.com[65.54.188.94]:25: QUIT
> Mar 5 14:43:12 out postfix/smtp[19842]: vstream_fflush_some: fd 12 flush 2187
> Mar 5 14:44:23 out postfix/smtp[19842]: smtp_get: EOF
> Mar 5 14:44:23 out postfix/smtp[19842]: connect to subsystem private/defer
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr nrequest = 0
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr flags = 0
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr queue_id = BEB85788451
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr original_recipient
> = user@hotmail.com
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr recipient = user@hotmail.com
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr offset = 617
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr dsn_orig_rcpt =
> rfc822;user@hotmail.com
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr notify_flags = 0
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr status = 4.4.2
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr diag_type =
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr diag_text =
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr mta_type =
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr mta_mname =
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr action = delayed
> Mar 5 14:44:23 out postfix/smtp[19842]: send attr reason = lost
> connection with mx1.hotmail.com[65.54.188.94] while sending end of
> data -- message may be sent more than once
> Mar 5 14:44:23 out postfix/smtp[19842]: vstream_fflush_some: fd 13 flush 403
> Mar 5 14:44:23 out postfix/smtp[19842]: vstream_buf_get_ready: fd 13 got 10
> Mar 5 14:44:23 out postfix/smtp[19842]: private/defer socket: wanted
> attribute: status
> Mar 5 14:44:23 out postfix/smtp[19842]: input attribute name: status
> Mar 5 14:44:23 out postfix/smtp[19842]: input attribute value: 0
> Mar 5 14:44:23 out postfix/smtp[19842]: private/defer socket: wanted
> attribute: (list terminator)
> Mar 5 14:44:23 out postfix/smtp[19842]: input attribute name: (end)
> Mar 5 14:44:23 out postfix/smtp[19842]: BEB85788451:
> to=<user@hotmail.com>, relay=mx1.hotmail.com[65.54.188.94]:25,
> delay=132, delays=0.1/0/60/71, dsn=4.4.2, status=deferred (lost
> connection with mx1.hotmail.com[65.54.188.94] while sending end of
> data -- message may be sent more than once)
> Mar 5 14:44:23 out postfix/smtp[19842]: flush_add: site hotmail.com
> id BEB85788451
> Mar 5 14:44:23 out postfix/smtp[19842]: match_hostname: hotmail.com
> ~? out.vp44.net
> Mar 5 14:44:23 out postfix/smtp[19842]: match_hostname: hotmail.com
> ~? localhost.vp44.net
> Mar 5 14:44:23 out postfix/smtp[19842]: match_hostname: hotmail.com
> ~? localhost
> Mar 5 14:44:23 out postfix/smtp[19842]: match_list_match: hotmail.com: no match
> Mar 5 14:44:23 out postfix/smtp[19842]: flush_add: site hotmail.com
> id BEB85788451 status 4
>
>
> Where should I start looking for the cause of this problem?
>
> Andy
-- Mit besten Grüßen, Reindl Harald the lounge interactive design GmbH A-1060 Vienna, Hofmühlgasse 17 CTO / software-development / cms-solutions p: +43 (1) 595 3999 33, m: +43 (676) 40 221 40 icq: 154546673, http://www.thelounge.net/