Hi >hi, > >can you reproduce the problem easily ?
I believe so - seemed to happen every time for every message, on an admittedly limited sample as I stopped trying to use it quite quickly at that point... If you want some specific debug I'm happy to try again. Thanks JC >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=<j...@uphall.net>, to=<j...@cix.co.uk>, size=569, ndest=1, >> proto=ESMTP >> debug: scheduler: evp:62ceecb7d179e5ef scheduled (mta) >> debug: mta: received evp:62ceecb7d179e5ef for <j...@cix.co.uk> >> 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=<j...@uphall.net>, to=<j...@cix.co.uk>, 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 (-> j...@cix.co.uk) >> 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 misc@opensmtpd.org >> To unsubscribe, send a mail to: misc+unsubscr...@opensmtpd.org >> -- You received this mail because you are subscribed to misc@opensmtpd.org To unsubscribe, send a mail to: misc+unsubscr...@opensmtpd.org
