On 08/21/14 15:59, Fabio Riga wrote: > Hi list, > > I run an OpenBSD 5.5 server on a VPS with OpenSMTPd. I get the message > "Connection closed unexpectedly" and a TempFail for every message sent to > every domain of a very big Italian ISP. The TempFail last 4 days, then the > message expires. I don't know if the laconic message is an OpenSMTPd issue or > a ISP one, but maybe somebody has a clue of the possible causes. > > I tryed as well to ask to the ISP, maybe I'll get an answer... > > Here it is a part of maillog: > I think it could a network problem on their side, from Italy (OpenBSD 5.6) I cannot deliver (see log file), from outside Italy there are no problems. Cheers Giovanni
Script started on Thu Aug 21 17:28:16 2014 $ sm sudo smtpd -dv debug: init ssl-tree info: OpenSMTPD 5.4.3 starting debug: bounce warning after 4h debug: using "fs" queue backend debug: using "ramqueue" scheduler backend debug: using "ram" stat backend info: startup [debug mode] debug: parent_send_config_ruleset: reloading debug: parent_send_config: configuring pony process debug: parent_send_config: configuring ca process debug: init ssl-tree debug: ca_engine_init: using RSAX engine support debug: smtp: listen on 127.0.0.1 port 25 flags 0x400 pki "" debug: smtp: listen on IPv6:fe80::1%lo0 port 25 flags 0x400 pki "" debug: smtp: listen on IPv6:::1 port 25 flags 0x400 pki "" debug: smtp: will accept at most 2037 clients debug: init private ssl-tree debug: queue: done loading queue into scheduler debug: smtpd: scanning offline queue... debug: smtpd: offline scanning done debug: smtp: new client on listener: 0x4536b769300 smtp: 0x4565257e000: STATE_NEW -> STATE_CONNECTED smtp-in: New session aa25a6d9509a520a from host 1000@localhost [local] smtp: 0x4565257e000: >>> 220 localhost ESMTP OpenSMTPD smtp: 0x4565257e000: <<< EHLO localhost smtp: 0x4565257e000: STATE_CONNECTED -> STATE_HELO smtp: 0x4565257e000: >>> 250-localhost Hello localhost [local], pleased to meet you smtp: 0x4565257e000: >>> 250-8BITMIME smtp: 0x4565257e000: >>> 250-ENHANCEDSTATUSCODES smtp: 0x4565257e000: >>> 250-SIZE 36700160 smtp: 0x4565257e000: >>> 250 HELP smtp: 0x4565257e000: <<< MAIL FROM:<[email protected]> smtp: 0x4565257e000: >>> 250 2.0.0: Ok smtp: 0x4565257e000: <<< RCPT TO:<[email protected]> smtp: 0x4565257e000: >>> 250 2.1.5 Destination address valid: Recipient ok smtp: 0x4565257e000: <<< DATA smtp: 0x4565257e000: STATE_HELO -> STATE_BODY smtp: 0x4565257e000: >>> 354 Enter mail, end with "." on a line by itself <<< [MSG] From: Giovanni Bechis <[email protected]> <<< [MSG] Date: Thu, 21 Aug 2014 17:28:35 +0200 (CEST) <<< [MSG] Message-Id: <[email protected]> <<< [MSG] To: [email protected] <<< [MSG] Subject: test <<< [MSG] <<< [MSG] test debug: 0x4565257e000: end of message, msgflags=0x0000 smtp: 0x4565257e000: >>> 250 2.0.0: e8eb560f Message accepted for delivery smtp-in: Accepted message e8eb560f on session aa25a6d9509a520a: from=<[email protected]>, to=<[email protected]>, size=196, ndest=1, proto=ESMTP debug: scheduler: evp:e8eb560f60257862 scheduled (mta) smtp: 0x4565257e000: STATE_BODY -> STATE_HELO smtp: 0x4565257e000: <<< QUIT smtp: 0x4565257e000: >>> 221 2.0.0: Bye smtp: 0x4565257e000: STATE_HELO -> STATE_QUIT smtp-in: Closing session aa25a6d9509a520a debug: smtp: 0x4565257e000: deleting session: done debug: mta: received evp:e8eb560f60257862 for <[email protected]> debug: mta: draining [relay:staff.aruba.it] refcount=1, ntask=1, nconnector=0, nconn=0 debug: mta: querying MX for [relay:staff.aruba.it]... debug: mta: [relay:staff.aruba.it] waiting for MX debug: MXs for domain staff.aruba.it: 62.149.157.49 preference 10 debug: mta: ... got mx (0x45611e38220, staff.aruba.it, [relay:staff.aruba.it]) debug: mta: draining [relay:staff.aruba.it] refcount=1, ntask=1, nconnector=0, nconn=0 debug: mta: querying source for [relay:staff.aruba.it]... debug: mta: ... got source for [relay:staff.aruba.it]: [] debug: mta: new [connector:[]->[relay:staff.aruba.it],0x10000] debug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x0] debug: mta-routing: searching new route for [connector:[]->[relay:staff.aruba.it],0x0]... debug: mta-routing: selecting candidate route [] <-> 62.149.157.49 debug: mta-routing: spawning new connection on [] <-> 62.149.157.49 debug: mta: 0x45666484000: spawned for relay [relay:staff.aruba.it] debug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x0] debug: mta: cannot use [relay:staff.aruba.it] before 2s debug: mta-routing: no route available for [connector:[]->[relay:staff.aruba.it],0x0]: must wait a bit debug: mta: retrying to connect on [connector:[]->[relay:staff.aruba.it],0x0] in 2s... debug: mta: draining [relay:staff.aruba.it] refcount=3, ntask=1, nconnector=1, nconn=1 debug: mta: scheduling relay [relay:staff.aruba.it] in 1s... smtp-out: Connecting to smtp+tls://62.149.157.49:25 (staff.aruba.it) on session aa25a6dc79081475... smtp-out: Connected on session aa25a6dc79081475 debug: mta: ... timeout for [relay:staff.aruba.it] debug: mta: draining [relay:staff.aruba.it] refcount=2, ntask=1, nconnector=1, nconn=1 debug: mta: querying source for [relay:staff.aruba.it]... debug: mta: ... got source for [relay:staff.aruba.it]: [] debug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x20000] debug: mta: cancelling connector timeout debug: mta: cannot use [relay:staff.aruba.it] before 1s debug: mta-routing: no route available for [connector:[]->[relay:staff.aruba.it],0x0]: must wait a bit debug: mta: retrying to connect on [connector:[]->[relay:staff.aruba.it],0x0] in 1s... debug: mta: draining [relay:staff.aruba.it] refcount=3, ntask=1, nconnector=1, nconn=1 debug: mta: scheduling relay [relay:staff.aruba.it] in 10s... smtp-out: Error on session aa25a6dc79081475: BANNER rejected: 554 mxcm01.ad.aruba.it bizsmtp hTUb1o01o0Qbrrr01 Connection refused from 151.76.0.19. See http://www.spamhaus.org/query/bl?ip=151.76.0.19 for more information. debug: mta: 0x45666484000: session done debug: mta_route_collect([] <-> 62.149.157.49 (staff.aruba.it)) smtp-out: Disabling route [] <-> 62.149.157.49 (staff.aruba.it) for 800s debug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x20000] debug: mta: cancelling connector timeout debug: mta: cannot use [relay:staff.aruba.it] before 1s debug: mta-routing: no route available for [connector:[]->[relay:staff.aruba.it],0x0]: must wait a bit debug: mta: retrying to connect on [connector:[]->[relay:staff.aruba.it],0x0] in 1s... debug: mta: ... timeout for [connector:[]->[relay:staff.aruba.it],0x20000] debug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x0] debug: mta-routing: searching new route for [connector:[]->[relay:staff.aruba.it],0x0]... debug: mta-routing: skipping route [] <-> 62.149.157.49 (staff.aruba.it): suspend smtp-out: No valid route for [connector:[]->[relay:staff.aruba.it],0x0] debug: mta-routing: no route available for [connector:[]->[relay:staff.aruba.it],0x8]: errors on connector debug: mta: ... timeout for [relay:staff.aruba.it] debug: mta: draining [relay:staff.aruba.it] refcount=1, ntask=1, nconnector=1, nconn=0 debug: mta: querying source for [relay:staff.aruba.it]... debug: mta: ... got source for [relay:staff.aruba.it]: [] debug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x8] debug: mta: connector error debug: mta: draining [relay:staff.aruba.it] refcount=2, ntask=1, nconnector=1, nconn=0 debug: mta: querying source for [relay:staff.aruba.it]... debug: mta: ... got source for [relay:staff.aruba.it]: [] debug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x8] debug: mta: connector error debug: mta: draining [relay:staff.aruba.it] refcount=3, ntask=1, nconnector=1, nconn=0 debug: mta_flush([relay:staff.aruba.it], 73, "Network error on destination MXs") relay: TempFail for e8eb560f60257862: session=0000000000000000, from=<[email protected]>, to=<[email protected]>, rcpt=<->, source=-, relay=staff.aruba.it, delay=12s, stat=Network error on destination MXs debug: mta: freeing [relay:staff.aruba.it] debug: mta: freeing [connector:[]->[relay:staff.aruba.it],0x8] debug: mta: flush for e8eb560f60257862 (-> [email protected]) ^Cinfo: pony agent exiting info: scheduler handler exiting info: lookup agent exiting info: ca agent exiting info: queue handler exiting info: control process exiting warn: parent terminating $ less sm $ less smtpd.log $ less smtpd.log [?1049h[?1h= [H[2J[H[H[2J[HScript started on Thu Aug 21 17:28:16 2014 $ [7m^G^G[27msudo smtpd -dv[7m^M[27m debug: init ssl-tree info: OpenSMTPD 5.4.3 starting debug: bounce warning after 4h debug: using "fs" queue backend debug: using "ramqueue" scheduler backend debug: using "ram" stat backend info: startup [debug mode] debug: parent_send_config_ruleset: reloading debug: parent_send_config: configuring pony process debug: parent_send_config: configuring ca process debug: init ssl-tree debug: ca_engine_init: using RSAX engine support debug: smtp: listen on 127.0.0.1 port 25 flags 0x400 pki "" debug: smtp: listen on IPv6:fe80::1%lo0 port 25 flags 0x400 pki "" debug: smtp: listen on IPv6:::1 port 25 flags 0x400 pki "" debug: smtp: will accept at most 2037 clients debug: init private ssl-tree debug: queue: done loading queue into scheduler debug: smtpd: scanning offline queue... debug: smtpd: offline scanning done debug: smtp: new client on listener: 0x4536b769300 [7msmtpd.log[27m[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: STATE_NEW -> STATE_CONNECTED :[K [K [KESCESC[KOO[KBB [Ksmtp-in: New session aa25a6d9509a520a from host 1000@localhost [local] :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 220 localhost ESMTP OpenSMTPD :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: <<< EHLO localhost :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: STATE_CONNECTED -> STATE_HELO :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 250-localhost Hello localhost [local], pleased to meet :[K [K [KESCESC[KOO[KBB [Kyou :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 250-8BITMIME :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 250-ENHANCEDSTATUSCODES :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 250-SIZE 36700160 :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 250 HELP :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: <<< MAIL FROM:<[email protected]> :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 250 2.0.0: Ok :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: <<< RCPT TO:<[email protected]> :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 250 2.1.5 Destination address valid: Recipient ok :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: <<< DATA :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: STATE_HELO -> STATE_BODY :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 354 Enter mail, end with "." on a line by itself :[K [K [KESCESC[KOO[KBB [K<<< [MSG] From: Giovanni Bechis <[email protected]> :[K [K [KESCESC[KOO[KBB [K<<< [MSG] Date: Thu, 21 Aug 2014 17:28:35 +0200 (CEST) :[K [K [KESCESC[KOO[KBB [K<<< [MSG] Message-Id: <[email protected]> :[K [K [KESCESC[KOO[KBB [K<<< [MSG] To: [email protected] :[K [K [KESCESC[KOO[KBB [K<<< [MSG] Subject: test :[K [K [KESCESC[KOO[KBB [K<<< [MSG] :[K [K [KESCESC[KOO[KBB [K<<< [MSG] test :[K [K [KESCESC[KOO[KBB [Kdebug: 0x4565257e000: end of message, msgflags=0x0000 :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 250 2.0.0: e8eb560f Message accepted for delivery :[K [K [KESCESC[KOO[KBB [Ksmtp-in: Accepted message e8eb560f on session aa25a6d9509a520a: from=<giovanni@b :[K [K [KESCESC[KOO[KBB [Kigio.paclan.it>, to=<[email protected]>, size=196, ndest=1, proto=ESMTP :[K [K [KESCESC[KOO[KBB [Kdebug: scheduler: evp:e8eb560f60257862 scheduled (mta) :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: STATE_BODY -> STATE_HELO :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: <<< QUIT :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: >>> 221 2.0.0: Bye :[K [K [KESCESC[KOO[KBB [Ksmtp: 0x4565257e000: STATE_HELO -> STATE_QUIT :[K [K [KESCESC[KOO[KBB [Ksmtp-in: Closing session aa25a6d9509a520a :[K [K [KESCESC[KOO[KBB [Kdebug: smtp: 0x4565257e000: deleting session: done :[K [K [KESCESC[KOO[KBB [Kdebug: mta: received evp:e8eb560f60257862 for <[email protected]> :[K [K [KESCESC[KOO[KBB [Kdebug: mta: draining [relay:staff.aruba.it] refcount=1, ntask=1, nconnector=0, n :[K [K [KESCESC[KOO[KBB [Kconn=0 :[K [K [KESCESC[KOO[KBB [Kdebug: mta: querying MX for [relay:staff.aruba.it]... :[K [K [KESCESC[KOO[KBB [Kdebug: mta: [relay:staff.aruba.it] waiting for MX :[K [K [KESCESC[KOO[KBB [Kdebug: MXs for domain staff.aruba.it: :[K [K [KESCESC[KOO[KBB [K 62.149.157.49 preference 10 :[K [K [KESCESC[KOO[KBB [Kdebug: mta: ... got mx (0x45611e38220, staff.aruba.it, [relay:staff.aruba.it]) :[K [K [KESCESC[KOO[KBB [Kdebug: mta: draining [relay:staff.aruba.it] refcount=1, ntask=1, nconnector=0, n :[K [K [KESCESC[KOO[KBB [Kconn=0 :[K [K [KESCESC[KOO[KBB [Kdebug: mta: querying source for [relay:staff.aruba.it]... :[K [K [KESCESC[KOO[KBB [Kdebug: mta: ... got source for [relay:staff.aruba.it]: [] :[K [K [KESCESC[KOO[KBB [Kdebug: mta: new [connector:[]->[relay:staff.aruba.it],0x10000] :[K [K [KESCESC[KOO[KBB [Kdebug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x0] :[K [K [KESCESC[KOO[KBB [Kdebug: mta-routing: searching new route for [connector:[]->[relay:staff.aruba.it :[K [K [KESCESC[KOO[KBB [K],0x0]... :[K [K [KESCESC[KOO[KBB [Kdebug: mta-routing: selecting candidate route [] <-> 62.149.157.49 :[K [K [KESCESC[KOO[KBB [Kdebug: mta-routing: spawning new connection on [] <-> 62.149.157.49 :[K [K [KESCESC[KOO[KBB [Kdebug: mta: 0x45666484000: spawned for relay [relay:staff.aruba.it] :[K [K [KESCESC[KOO[KBB [Kdebug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x0] :[K [K [KESCESC[KOO[KBB [Kdebug: mta: cannot use [relay:staff.aruba.it] before 2s :[K [K [KESCESC[KOO[KBB [Kdebug: mta-routing: no route available for [connector:[]->[relay:staff.aruba.it] :[K [K [KESCESC[KOO[KBB [K,0x0]: must wait a bit :[K [K [KESCESC[KOO[KBB [Kdebug: mta: retrying to connect on [connector:[]->[relay:staff.aruba.it],0x0] in :[K [K [KESCESC[KOO[KBB [K 2s... :[K [K [KESCESC[KOO[KBB [Kdebug: mta: draining [relay:staff.aruba.it] refcount=3, ntask=1, nconnector=1, n :[K [K [KESCESC[KOO[KBB [Kconn=1 :[K [K [KESCESC[KOO[KBB [Kdebug: mta: scheduling relay [relay:staff.aruba.it] in 1s... :[K [K [KESCESC[KOO[KBB [Ksmtp-out: Connecting to smtp+tls://62.149.157.49:25 (staff.aruba.it) on session :[K [K [KESCESC[KOO[KBB [Kaa25a6dc79081475... :[K [K [KESCESC[KOO[KBB [Ksmtp-out: Connected on session aa25a6dc79081475 :[K [K [KESCESC[KOO[KBB [Kdebug: mta: ... timeout for [relay:staff.aruba.it] :[K [K [KESCESC[KOO[KBB [Kdebug: mta: draining [relay:staff.aruba.it] refcount=2, ntask=1, nconnector=1, n :[K [K [KESCESC[KOO[KBB [Kconn=1 :[K [K [KESCESC[KOO[KBB [Kdebug: mta: querying source for [relay:staff.aruba.it]... :[K [K [KESCESC[KOO[KBB [Kdebug: mta: ... got source for [relay:staff.aruba.it]: [] :[K [K [KESCESC[KOO[KBB [Kdebug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x20000] :[K [K [KESCESC[KOO[KBB [Kdebug: mta: cancelling connector timeout :[K [K [KESCESC[KOO[KBB [Kdebug: mta: cannot use [relay:staff.aruba.it] before 1s :[K [K [KESCESC[KOO[KBB [Kdebug: mta-routing: no route available for [connector:[]->[relay:staff.aruba.it] :[K [K [KESCESC[KOO[KBB [K,0x0]: must wait a bit :[K [K [KESCESC[KOO[KBB [Kdebug: mta: retrying to connect on [connector:[]->[relay:staff.aruba.it],0x0] in :[K [K [KESCESC[KOO[KBB [K 1s... :[K [K [KESCESC[KOO[KBB [Kdebug: mta: draining [relay:staff.aruba.it] refcount=3, ntask=1, nconnector=1, n :[K [K [KESCESC[KOO[KBB [Kconn=1 :[K [K [KESCESC[KOO[KBB [Kdebug: mta: scheduling relay [relay:staff.aruba.it] in 10s... :[K [K [KESCESC[KOO[KBB [Ksmtp-out: Error on session aa25a6dc79081475: BANNER rejected: 554 mxcm01.ad.arub :[K [K [KESCESC[KOO[KBB [Ka.it bizsmtp hTUb1o01o0Qbrrr01 Connection refused from 151.76.0.19. See http://w :[K [K [KESCESC[KOO[KBB [Kww.spamhaus.org/query/bl?ip=151.76.0.19 for more information. :[K [K [KESCESC[KOO[KBB [Kdebug: mta: 0x45666484000: session done :[K [K [KESCESC[KOO[KBB [Kdebug: mta_route_collect([] <-> 62.149.157.49 (staff.aruba.it)) :[K [K [KESCESC[KOO[KBB [Ksmtp-out: Disabling route [] <-> 62.149.157.49 (staff.aruba.it) for 800s :[K [K [KESCESC[KOO[KBB [Kdebug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x20000] :[K [K [KESCESC[KOO[KBB [Kdebug: mta: cancelling connector timeout :[K [K [KESCESC[KOO[KBB [Kdebug: mta: cannot use [relay:staff.aruba.it] before 1s :[K [K [KESCESC[KOO[KBB [Kdebug: mta-routing: no route available for [connector:[]->[relay:staff.aruba.it] :[K [K [KESCESC[KOO[KBB [K,0x0]: must wait a bit :[K [K [KESCESC[KOO[KBB [Kdebug: mta: retrying to connect on [connector:[]->[relay:staff.aruba.it],0x0] in :[K [K [KESCESC[KOO[KBB [K 1s... :[K [K [KESCESC[KOO[KBB [Kdebug: mta: ... timeout for [connector:[]->[relay:staff.aruba.it],0x20000] :[K [K [KESCESC[KOO[KBB [Kdebug: mta: connecting with [connector:[]->[relay:staff.aruba.it],0x0] :[K [K [KESCESC[KOO[KBB [Kdebug: mta-routing: searching new route for [connector:[]->[relay:staff.aruba.it :[K [K [KESCESC[KOO[KBB [K],0x0]... :[K [K [KESCESC[KOO[KBB [Kdebug: mta-routing: skipping route [] <-> 62.149.157.49 (staff.aruba.it): suspen :[K [K [KESCESC[KOO[KBB [Kd :[K [K [KESCESC[KOO[KBB [Ksmtp-out: No valid route for [connector:[]->[relay:staff.aruba.it],0x0] :[K [K [KESCESC[KOO[KBB [Kdebug: mta-routing: no route available for [connector:[]->[relay:staff.aruba.it] :[K [K [KESCESC[KOO[KBB [K,0x8]: errors on connector [7m(END)[27m[K [K [KESCESC[KOO[KBB [K [K[7m(END)[27m[K [K [KESCESC[KOO[KBB [K [K[7m(END)[27m[K [K [KESCESC[KOO[KBB [K [K[7m(END)[27m[K [K [KESCESC[KOO[KBB [K [K[7m(END)[27m[K [K [KESCESC[KOO[KBB [K [K[7m(END)[27m[K [K [KESCESC[KOO[KBB [K [K[7m(END)[27m[K [K [KESCESC[KOO[KBB [K [K[7m(END)[27m[K [K [KESCESC[KOO[KBB [K [K[7m(END)[27m[K [K [KESCESC[KOO[KBB [K [K[7m(END)[27m[K [K[?1l>[?1049l$
