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:<u...@vp44.net> SIZE=2178 Mar 5 14:43:12 out postfix/smtp[19842]: > mx1.hotmail.com[65.54.188.94]:25: RCPT TO:<u...@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 u...@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 u...@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 = u...@hotmail.com Mar 5 14:44:23 out postfix/smtp[19842]: send attr recipient = u...@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;u...@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=<u...@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
