hi, can you reproduce the problem easily ?
Gilles On Thu, May 15, 2014 at 09:21:04AM +0100, John Cox wrote: > Hi > > It almost works for me on OpenBSD5.5-stable. > > Compiles, runs, delivers and then dies.... > > Many thanks > > John Cox > > # smtpd -d -v > debug: init ssl-tree > info: loading pki information for yidhra.outer.uphall.net > info: OpenSMTPD 201405142324 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 > filter: building simple chains... > debug: init ssl-tree > debug: parent_send_config: configuring pony process > filter: building complex chains... > info: loading pki keys for yidhra.outer.uphall.net > debug: parent_send_config: configuring ca process > filter: done building complex chains > filter: done building default chain > debug: init private ssl-tree > debug: ca_engine_init: using RSAX engine support > debug: smtp: listen on 127.0.0.1 port 25 flags 0x1 pki > "yidhra.outer.uphall.net" > debug: smtp: listen on IPv6:fe80::1%lo0 port 25 flags 0x1 pki > "yidhra.outer.uphall.net" > debug: smtp: listen on IPv6:::1 port 25 flags 0x1 pki > "yidhra.outer.uphall.net" > debug: smtp: listen on IPv6:fe80::6a05:caff:fe08:e7b1%em2 port 25 > flags 0x1 pki "yidhra.outer.uphall.net" > debug: smtp: listen on 10.44.0.3 port 25 flags 0x1 pki > "yidhra.outer.uphall.net" > debug: pony: rsae_init > debug: pony: rsae_init > debug: smtp: will accept at most 3503 clients > debug: queue: done loading queue into scheduler > debug: smtpd: scanning offline queue... > debug: smtpd: offline scanning done > debug: smtp: new client on listener: 0x114602434000 > smtp-in: New session 9485f27f7b43e5d1 from host 10.44.1.11 > [10.44.1.11] > debug: lka: looking up pki "yidhra.outer.uphall.net" > debug: session_start_ssl: switching to SSL > smtp-in: No PKI entry for requested SNI "smtp.outer.uphall.net"on > session 9485f27f7b43e5d1 > debug: pony: rsae_priv_dec > smtp-in: Started TLS on session 9485f27f7b43e5d1: version=TLSv1/SSLv3, > cipher=AES128-SHA, bits=128 > smtp: 0x1145f9b6f000: fd 5 from queue > smtp: 0x1145f9b6f000: fd 7 from filter > debug: filter: tx data (255) for req 9485f27f7b43e5d1 > debug: filter: tx data (314) for req 9485f27f7b43e5d1 > debug: smtp: 0x1145f9b6f000: data io done (569 bytes) > filter: deferring eom query... > debug: filter: tx done for req 9485f27f7b43e5d1 > filter: running eom query... > debug: 0x1145f9b6f000: end of message, msgflags=0x0000 > smtp-in: Accepted message 62ceecb7 on session 9485f27f7b43e5d1: > from=<[email protected]>, to=<[email protected]>, size=569, ndest=1, > proto=ESMTP > debug: scheduler: evp:62ceecb7d179e5ef scheduled (mta) > debug: mta: received evp:62ceecb7d179e5ef for <[email protected]> > debug: mta: draining > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > refcount=1, ntask=1, nconnector=0, nconn=0 > debug: mta: querying MX for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>]... > debug: mta: > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > waiting for MX > debug: MXs for domain azathoth.uphall.net: > 46.235.226.138 preference -1 > debug: mta: ... got mx (0x114600112a20, azathoth.uphall.net, > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>]) > debug: mta: draining > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > refcount=1, ntask=1, nconnector=0, nconn=0 > debug: mta: querying source for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>]... > debug: mta: ... got source for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>]: > 10.44.0.3 > debug: mta: new > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x10000] > debug: mta: connecting with > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0] > debug: mta-routing: searching new route for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0]... > debug: mta-routing: selecting candidate route 10.44.0.3 <-> > 46.235.226.138 > debug: mta-routing: spawning new connection on 10.44.0.3 <-> > 46.235.226.138 > debug: mta: 0x1145ff354000: spawned for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > debug: mta: connecting with > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0] > debug: mta: cannot use > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > before 2s > debug: mta-routing: no route available for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0]: > must wait a bit > debug: mta: retrying to connect on > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0] > in 2s... > debug: mta: draining > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > refcount=2, ntask=1, nconnector=1, nconn=1 > debug: mta: scheduling relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > in 1s... > smtp-out: Connecting to tls://46.235.226.138:25 (azathoth.uphall.net) > on session 9485f28b95a78a2e... > smtp-out: Connected on session 9485f28b95a78a2e > debug: lka: looking up pki "yidhra.outer.uphall.net" > debug: pony: rsae_init > debug: pony: rsae_init > debug: pony: rsae_init > debug: pony: rsae_pub_dec > debug: pony: rsae_bn_mod_exp > debug: pony: rsae_priv_enc > debug: mta: ... timeout for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > debug: mta: draining > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > refcount=2, ntask=1, nconnector=1, nconn=1 > debug: mta: querying source for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>]... > debug: mta: ... got source for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>]: > 10.44.0.3 > debug: mta: connecting with > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000] > debug: mta: canceling connector timeout > debug: mta: cannot use > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > before 1s > debug: mta-routing: no route available for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000]: > must wait a bit > debug: mta: retrying to connect on > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000] > in 1s... > debug: mta: draining > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > refcount=2, ntask=1, nconnector=1, nconn=1 > debug: mta: scheduling relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > in 10s... > debug: mta: ... timeout for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000] > debug: mta: connecting with > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0] > debug: mta-routing: searching new route for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0]... > debug: mta-routing: skipping route 10.44.0.3 <-> 46.235.226.138 > (azathoth.uphall.net): not validated yet > debug: mta: hit route limit > debug: mta-routing: no route available for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0]: > limits reached > debug: mta: retrying to connect on > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0] > in 5s... > smtp-in: Closing session 9485f27f7b43e5d1 > debug: smtp: 0x1145f9b6f000: deleting session: done > debug: mta: ... timeout for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000] > debug: mta: connecting with > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0] > debug: mta-routing: searching new route for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0]... > debug: mta-routing: skipping route 10.44.0.3 <-> 46.235.226.138 > (azathoth.uphall.net): not validated yet > debug: mta: hit route limit > debug: mta-routing: no route available for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0]: > limits reached > debug: mta: retrying to connect on > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x0] > in 5s... > debug: mta: ... timeout for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > debug: mta: draining > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > refcount=2, ntask=1, nconnector=1, nconn=1 > debug: mta: querying source for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>]... > debug: mta: ... got source for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>]: > 10.44.0.3 > debug: mta: connecting with > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000] > debug: mta: canceling connector timeout > debug: mta-routing: searching new route for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000]... > debug: mta-routing: skipping route 10.44.0.3 <-> 46.235.226.138 > (azathoth.uphall.net): not validated yet > debug: mta: hit route limit > debug: mta-routing: no route available for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000]: > limits reached > debug: mta: retrying to connect on > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000] > in 5s... > debug: mta: draining > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > refcount=2, ntask=1, nconnector=1, nconn=1 > debug: mta: scheduling relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > in 10s... > smtp-out: Started TLS on session 9485f28b95a78a2e: > version=TLSv1/SSLv3, cipher=DHE-RSA-AES256-GCM-SHA384, bits=256 > smtp-out: Server certificate verification succeeded on session > 9485f28b95a78a2e > debug: mta-routing: route 10.44.0.3 <-> 46.235.226.138 > (azathoth.uphall.net) is now valid. > debug: mta: connecting with > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000] > debug: mta: canceling connector timeout > debug: mta: enough connections already > debug: mta: 0x1145ff354000: handling next task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > relay: Ok for 62ceecb7d179e5ef: session=9485f28b95a78a2e, > from=<[email protected]>, to=<[email protected]>, rcpt=<->, source=10.44.0.3, > relay=46.235.226.138 (azathoth.uphall.net), delay=12s, stat=250 2.0.0 > s4F8E9kN023032 Message accepted for delivery > debug: mta: waiting for 1s before next transaction > debug: mta: flush for 62ceecb7d179e5ef (-> [email protected]) > mta: timeout for session hangon > debug: mta: 0x1145ff354000: no task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > mta: debug: last connection: hanging on for 9s > mta: timeout for session hangon > debug: mta: 0x1145ff354000: no task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > mta: debug: last connection: hanging on for 8s > mta: timeout for session hangon > debug: mta: 0x1145ff354000: no task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > mta: debug: last connection: hanging on for 7s > mta: timeout for session hangon > debug: mta: 0x1145ff354000: no task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > mta: debug: last connection: hanging on for 6s > mta: timeout for session hangon > debug: mta: 0x1145ff354000: no task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > mta: debug: last connection: hanging on for 5s > mta: timeout for session hangon > debug: mta: 0x1145ff354000: no task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > mta: debug: last connection: hanging on for 4s > mta: timeout for session hangon > debug: mta: 0x1145ff354000: no task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > mta: debug: last connection: hanging on for 3s > mta: timeout for session hangon > debug: mta: 0x1145ff354000: no task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > mta: debug: last connection: hanging on for 2s > mta: timeout for session hangon > debug: mta: 0x1145ff354000: no task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > mta: debug: last connection: hanging on for 1s > debug: mta: ... timeout for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > debug: mta: draining > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > refcount=2, ntask=0, nconnector=1, nconn=1 > debug: mta: all done for > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > mta: timeout for session hangon > debug: mta: 0x1145ff354000: no task for relay > [relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>] > smtp-out: Closing session 9485f28b95a78a2e: 1 message sent. > debug: mta: 0x1145ff354000: session done > debug: pony: rsae_finish > debug: pony: rsae_finish > debug: pony: rsae_finish > debug: mta_route_collect(10.44.0.3 <-> 46.235.226.138 > (azathoth.uphall.net)) > debug: mta: connecting with > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=yidhra.outer.uphall.net,mx,sourcetable=<dynamic:0>],0x20000] > debug: mta: canceling connector timeout > debug: mta: no task for connector > debug: mta: ma_route_unref(): really discarding route 10.44.0.3 <-> > 46.235.226.138 (azathoth.uphall.net) > debug: mta: freeing > [relay:azathoth.uphall.net,starttls,pki_name=debug: mta: connecting > with %s > ,mx,sourcetable=<dynamic:0>] > debug: mta: freeing > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=debug: > mta: connecting with %s > ,mx,sourcetable=<dynamic:0>],0x20000] > debug: mta: canceling timeout for > [connector:10.44.0.3->[relay:azathoth.uphall.net,starttls,pki_name=debug: > mta: connecting with %s > ,mx,sourcetable=<dynamic:0>],0x20000] > smtpd in free(): error: chunk is already free 0x114600114100 > warn: parent -> pony: pipe closed > warn: lka -> pony: pipe closed > warn: queue -> pony: pipe closed > warn: control -> pony: pipe closed > warn: ca -> pony: pipe closed > warn: scheduler -> queue: pipe closed > # > > -- > You received this mail because you are subscribed to [email protected] > To unsubscribe, send a mail to: [email protected] > -- Gilles Chehade https://www.poolp.org @poolpOrg -- You received this mail because you are subscribed to [email protected] To unsubscribe, send a mail to: [email protected]
