updated my instances and you're right, we have introduced a regression at some point
it'll be fixed in next snapshot Gilles On Sun, Jul 14, 2013 at 04:49:23AM -0300, Hugo Osvaldo Barrera wrote: > On 2013-07-13 23:57, Gilles Chehade wrote: > > On Fri, Jul 12, 2013 at 02:20:47PM -0300, Hugo Osvaldo Barrera wrote: > > > > > > Hmmm... It's odd, because it looks like smtpd isn't using TLS when > > > relaying my local email. > > > Let me explain a bit. > > > > > > [...] > > > > > > > Can you include the output of 'smtpd -dv' as the daemon starts and until > > it stabilizes ? > > > > It's hard to debug without that information, but it TLS should work fine > > as I used it daily on both OpenBSD and Linux Debian. > > > > > > > I understand that the first part (mutt->smtpd) doesn't run TLS; because > > > my local instance doesn't listen with TLS, but shouldn't the email be > > > relayed using TLS (local smtpd->remote smtpd)? > > > > > > > Yes, unless you explicitely require no encryption or smtps using one of > > the following: > > > > relay via smtp:// > > relay via smtps:// > > > > TLS is always attempted first. > > > > > > > Emails from EXTERNAL hosts seem to be using TLS, and, from the looks of > > > the logs, my local smtpd isn't trying to use STARTTLS at any given moment. > > > > > > Is this a bug? Shouldn't smtpd always try to use TLS on outgoing email? > > > > > > > Logs needed > > > > > > -- > > Gilles Chehade > > > > https://www.poolp.org @poolpOrg > > > > -- > > You received this email because you are subscribed to the > > "[email protected]" list > > To unsubscribe, send mail with subject: [[email protected]] unregister > > Full log of the receiving server (the MX server for the email's > recipient): > > # smtpd -dv > info: OpenSMTPD 201307121003 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: init server-ssl tree > info: No CA found in /etc/mail/certs/egress.ca > info: No DH parameters found in /etc/mail/certs/egress.dh: using built-in > parameters > debug: init client-ssl tree > debug: parent_send_config_ruleset: reloading > debug: parent_send_config_mfa: reloading > debug: parent_send_config: configuring smtp > queue: queue encryption enabled > debug: queue: done loading queue into scheduler > debug: mfa ready > debug: smtp: listen on IPv6:2607:f2f8:a520::2 port 587 flags 0x69 cert > "egress" > debug: smtp: listen on IPv6:fe80::5054:ff:fe27:2425%em0 port 587 flags 0x69 > cert "egress" > debug: smtp: listen on 174.136.104.18 port 587 flags 0x69 cert "egress" > debug: smtp: listen on IPv6:2607:f2f8:a520::2 port 465 flags 0x2 cert "egress" > debug: smtp: listen on IPv6:fe80::5054:ff:fe27:2425%em0 port 465 flags 0x2 > cert "egress" > debug: smtp: listen on 174.136.104.18 port 465 flags 0x2 cert "egress" > debug: smtp: listen on IPv6:2607:f2f8:a520::2 port 25 flags 0x1 cert "egress" > debug: smtp: listen on IPv6:fe80::5054:ff:fe27:2425%em0 port 25 flags 0x1 > cert "egress" > debug: smtp: listen on 174.136.104.18 port 25 flags 0x1 cert "egress" > debug: smtp: listen on 127.0.0.1 port 10028 flags 0x0 cert "" > debug: smtp: listen on IPv6:fe80::1%lo0 port 10028 flags 0x0 cert "" > debug: smtp: listen on IPv6:::1 port 10028 flags 0x0 cert "" > debug: smtp: listen on 127.0.0.1 port 25 flags 0x0 cert "" > debug: smtp: listen on IPv6:fe80::1%lo0 port 25 flags 0x0 cert "" > debug: smtp: listen on IPv6:::1 port 25 flags 0x0 cert "" > debug: smtp: will accept at most 495 clients > debug: smtpd: scanning offline queue... > debug: smtpd: offline scanning done > debug: smtp: new client on listener: 0xe24a6224120 > smtp-in: New session 000000009c3401ae from host hyperion.ubertech.com.ar > [190.210.108.249] > debug: aliases_virtual_get: '[email protected]' resolved to 1 nodes > debug: 0xe24aee5f000: end of message, msgflags=0x0000 > smtp-in: Accepted message 8e914422 on session 000000009c3401ae: > from=<[email protected]>, to=<[email protected]>, > size=1381, ndest=1, proto=ESMTP > debug: scheduler: evp:8e914422a6e35b71 scheduled (mda) > debug: lka: userinfo <getpwnam>:hugo > debug: mda: new session 00000000473a1560 for user "hugo" evpid > 8e914422a6e35b71 > debug: mda: no more envelope for "hugo" > debug: mda: got message fd 3 for session 00000000473a1560 evpid > 8e914422a6e35b71 > debug: mda: querying mda fd for session 00000000473a1560 evpid > 8e914422a6e35b71 > debug: smtpd: forking mda for session 00000000473a1560: > "/usr/local/libexec/dovecot/dovecot-lda -d [email protected]" as hugo > debug: mda: got mda fd 4 for session 00000000473a1560 evpid 8e914422a6e35b71 > debug: mda: end-of-file for session 00000000473a1560 evpid 8e914422a6e35b71 > debug: mda: all data sent for session 00000000473a1560 evpid 8e914422a6e35b71 > debug: smtpd: mda process done for session 00000000473a1560: exited okay > delivery: Ok for 8e914422a6e35b71: from=<[email protected]>, > to=<[email protected]>, user=hugo, method=mda, delay=1s, > stat=Delivered > debug: mda: session 00000000473a1560 done > debug: mda: user "hugo" becomes runnable > debug: mda: all done for user "hugo" > smtp-in: Closing session 000000009c3401ae > debug: smtp: 0xe24aee5f000: deleting session: done > > # cat /etc/mail/smtpd.conf: > # This is the smtpd server system-wide configuration file. > # See smtpd.conf(5) for more information. > > queue encryption key xxx > > table usrs db:/etc/mail/users.db > table aliases db:/etc/mail/aliases.db > table domains db:/etc/mail/domains.db > > listen on lo0 > listen on lo0 port 10028 tag DKIM > listen on egress port 25 tls hostname > "mx1.ubertech.com.ar" > listen on egress port 465 smtps hostname > "smtp.ubertech.com.ar" # Obsoleted by RFC3207 > listen on egress port 587 tls-require auth <usrs> hostname > "smtp.ubertech.com.ar" > > table catchall { "@" => hugo } > > accept from any for local alias <aliases> deliver to mda > "/usr/local/libexec/dovecot/dovecot-lda -d [email protected]" > accept from any for domain <domains> virtual <catchall> deliver to mda > "/usr/local/libexec/dovecot/dovecot-lda -d [email protected]" > > accept tagged DKIM for any relay > accept for any relay via smtp://127.0.0.1:10027 > > ### > Full log of the relaying instance of smtpd (the one running on my > desktop): > > # smtpd -dv > info: OpenSMTPD 201307121003p1 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: init server-ssl tree > debug: init client-ssl tree > libevent 2.0.21-stable (epoll) > debug: parent_send_config_ruleset: reloading > debug: parent_send_config_mfa: reloading > debug: parent_send_config: configuring smtp > debug: mfa ready > debug: smtp: listen on 127.0.0.1 port 25 flags 0x0 cert "" > debug: smtp: will accept at most 2022 clients > debug: queue: done loading queue into scheduler > debug: smtpd: scanning offline queue... > debug: smtpd: offline scanning done > debug: smtp: new client on listener: 0x23181f0 > [warn] event_del: event has no event_base set. > smtp-in: New session 00000000b7e69da4 from host localhost.localdomain > [127.0.0.1] > debug: 0x236a7e0: end of message, msgflags=0x0000 > smtp-in: Accepted message b7e69da4 on session 00000000b7e69da4: > from=<[email protected]>, to=<[email protected]>, > size=1165, ndest=1, proto=ESMTP > debug: scheduler: evp:b7e69da42d74027d scheduled (mta) > smtp-in: Closing session 00000000b7e69da4 > debug: smtp: 0x236a7e0: deleting session: done > debug: mta: received evp:b7e69da42d74027d for <[email protected]> > debug: mta: draining [relay:osvaldobarrera.com.ar] refcount=1, ntask=1, > nconnector=0, nconn=0 > debug: mta: querying MX for [relay:osvaldobarrera.com.ar]... > debug: mta: [relay:osvaldobarrera.com.ar] waiting for MX > debug: MXs for domain osvaldobarrera.com.ar: > IPv6:2607:f2f8:a520::2 preference 0 > 174.136.104.18 preference 0 > 190.210.108.249 preference 10 > debug: mta: ... got mx (0x23174e0, osvaldobarrera.com.ar, > [relay:osvaldobarrera.com.ar]) > debug: mta: draining [relay:osvaldobarrera.com.ar] refcount=1, ntask=1, > nconnector=0, nconn=0 > debug: mta: querying source for [relay:osvaldobarrera.com.ar]... > debug: mta: ... got source for [relay:osvaldobarrera.com.ar]: [] > debug: mta: new [connector:[]->[relay:osvaldobarrera.com.ar],0x1000] > debug: mta: connecting with [connector:[]->[relay:osvaldobarrera.com.ar],0x0] > debug: mta-routing: searching new route for > [connector:[]->[relay:osvaldobarrera.com.ar],0x0]... > debug: mta-routing: selecting candidate route [] <-> IPv6:2607:f2f8:a520::2 > debug: mta-routing: skipping route [] <-> 174.136.104.18: current one is > better > debug: mta: ma_route_unref(): really discarding route [] <-> 174.136.104.18 > debug: mta-routing: spawning new connection on [] <-> IPv6:2607:f2f8:a520::2 > debug: mta: 0x235a680: spawned for relay [relay:osvaldobarrera.com.ar] > debug: mta: connecting with [connector:[]->[relay:osvaldobarrera.com.ar],0x0] > debug: mta: cannot use [relay:osvaldobarrera.com.ar] before 2s > debug: mta-routing: no route available for > [connector:[]->[relay:osvaldobarrera.com.ar],0x0]: must wait a bit > debug: mta: retrying to connect on > [connector:[]->[relay:osvaldobarrera.com.ar],0x0] in 2s... > debug: mta: draining [relay:osvaldobarrera.com.ar] refcount=3, ntask=1, > nconnector=1, nconn=1 > debug: mta: scheduling relay [relay:osvaldobarrera.com.ar] in 1s... > [warn] event_del: event has no event_base set. > smtp-out: Connecting to smtp://IPv6:2607:f2f8:a520::2:25 (2607:f2f8:a520::2) > on session 0000000209c3fb3b... > debug: mta: io_connect failed: Network is unreachable > smtp-out: Error on session 0000000209c3fb3b: Connection failed: Network is > unreachable > debug: mta: 0x235a680: session done > [warn] event_del: event has no event_base set. > debug: mta_route_collect([] <-> IPv6:2607:f2f8:a520::2 (2607:f2f8:a520::2)) > smtp-out: Disabling route [] <-> IPv6:2607:f2f8:a520::2 (2607:f2f8:a520::2) > for 800s > debug: mta: connecting with > [connector:[]->[relay:osvaldobarrera.com.ar],0x2000] > debug: mta: canceling connector timeout > debug: mta: cannot use [relay:osvaldobarrera.com.ar] before 2s > debug: mta-routing: no route available for > [connector:[]->[relay:osvaldobarrera.com.ar],0x2000]: must wait a bit > debug: mta: retrying to connect on > [connector:[]->[relay:osvaldobarrera.com.ar],0x2000] in 2s... > debug: mta: ... timeout for [relay:osvaldobarrera.com.ar] > debug: mta: draining [relay:osvaldobarrera.com.ar] refcount=1, ntask=1, > nconnector=1, nconn=0 > debug: mta: querying source for [relay:osvaldobarrera.com.ar]... > debug: mta: ... got source for [relay:osvaldobarrera.com.ar]: [] > debug: mta: connecting with > [connector:[]->[relay:osvaldobarrera.com.ar],0x2000] > debug: mta: canceling connector timeout > debug: mta: cannot use [relay:osvaldobarrera.com.ar] before 1s > debug: mta-routing: no route available for > [connector:[]->[relay:osvaldobarrera.com.ar],0x2000]: must wait a bit > debug: mta: retrying to connect on > [connector:[]->[relay:osvaldobarrera.com.ar],0x2000] in 1s... > debug: mta: draining [relay:osvaldobarrera.com.ar] refcount=2, ntask=1, > nconnector=1, nconn=0 > debug: mta: scheduling relay [relay:osvaldobarrera.com.ar] in 10s... > debug: mta: ... timeout for > [connector:[]->[relay:osvaldobarrera.com.ar],0x2000] > debug: mta: connecting with [connector:[]->[relay:osvaldobarrera.com.ar],0x0] > debug: mta-routing: searching new route for > [connector:[]->[relay:osvaldobarrera.com.ar],0x0]... > debug: mta-routing: skipping route [] <-> IPv6:2607:f2f8:a520::2 > (2607:f2f8:a520::2): suspend > debug: mta-routing: selecting candidate route [] <-> 174.136.104.18 > debug: mta-routing: spawning new connection on [] <-> 174.136.104.18 > debug: mta: 0x235a680: spawned for relay [relay:osvaldobarrera.com.ar] > debug: mta: connecting with [connector:[]->[relay:osvaldobarrera.com.ar],0x0] > debug: mta: cannot use [relay:osvaldobarrera.com.ar] before 2s > debug: mta-routing: no route available for > [connector:[]->[relay:osvaldobarrera.com.ar],0x0]: must wait a bit > debug: mta: retrying to connect on > [connector:[]->[relay:osvaldobarrera.com.ar],0x0] in 2s... > [warn] event_del: event has no event_base set. > smtp-out: Connecting to smtp://174.136.104.18:25 (174.136.104.18) on session > 00000003ed5921eb... > [warn] event_del: event has no event_base set. > smtp-out: Connected on session 00000003ed5921eb > debug: mta-routing: route [] <-> 174.136.104.18 (174.136.104.18) is now valid. > debug: mta: connecting with > [connector:[]->[relay:osvaldobarrera.com.ar],0x2000] > debug: mta: canceling connector timeout > debug: mta: enough connections already > debug: mta: 0x235a680: handling next task for relay > [relay:osvaldobarrera.com.ar] > relay: Ok for b7e69da42d74027d: session=00000003ed5921eb, > from=<[email protected]>, to=<[email protected]>, rcpt=<->, > source=172.16.8.7, relay=174.136.104.18 (174.136.104.18), delay=5s, stat=250 > 8e914422 Message accepted for delivery > debug: mta: waiting for 1s before next transaction > mta: timeout for session hangon > debug: mta: 0x235a680: no task for relay [relay:osvaldobarrera.com.ar] > mta: debug: last connection: hanging on for 9s > mta: timeout for session hangon > debug: mta: 0x235a680: no task for relay [relay:osvaldobarrera.com.ar] > mta: debug: last connection: hanging on for 8s > mta: timeout for session hangon > debug: mta: 0x235a680: no task for relay [relay:osvaldobarrera.com.ar] > mta: debug: last connection: hanging on for 7s > mta: timeout for session hangon > debug: mta: 0x235a680: no task for relay [relay:osvaldobarrera.com.ar] > mta: debug: last connection: hanging on for 6s > mta: timeout for session hangon > debug: mta: 0x235a680: no task for relay [relay:osvaldobarrera.com.ar] > mta: debug: last connection: hanging on for 5s > mta: timeout for session hangon > debug: mta: 0x235a680: no task for relay [relay:osvaldobarrera.com.ar] > mta: debug: last connection: hanging on for 4s > debug: mta: ... timeout for [relay:osvaldobarrera.com.ar] > debug: mta: draining [relay:osvaldobarrera.com.ar] refcount=2, ntask=0, > nconnector=1, nconn=1 > debug: mta: all done for [relay:osvaldobarrera.com.ar] > mta: timeout for session hangon > debug: mta: 0x235a680: no task for relay [relay:osvaldobarrera.com.ar] > mta: debug: last connection: hanging on for 3s > mta: timeout for session hangon > debug: mta: 0x235a680: no task for relay [relay:osvaldobarrera.com.ar] > mta: debug: last connection: hanging on for 2s > mta: timeout for session hangon > debug: mta: 0x235a680: no task for relay [relay:osvaldobarrera.com.ar] > mta: debug: last connection: hanging on for 1s > mta: timeout for session hangon > debug: mta: 0x235a680: no task for relay [relay:osvaldobarrera.com.ar] > smtp-out: Closing session 00000003ed5921eb: 1 message sent. > debug: mta: 0x235a680: session done > debug: mta_route_collect([] <-> 174.136.104.18 (174.136.104.18)) > debug: mta: connecting with > [connector:[]->[relay:osvaldobarrera.com.ar],0x2000] > debug: mta: canceling connector timeout > debug: mta: no task for connector > debug: mta: ma_route_unref(): really discarding route [] <-> 174.136.104.18 > (174.136.104.18) > debug: mta: freeing [relay:osvaldobarrera.com.ar] > debug: mta: freeing [connector:[]->[relay:osvaldobarrera.com.ar],0x2000] > debug: mta: canceling timeout for > [connector:[]->[relay:osvaldobarrera.com.ar],0x2000] > > # cat /etc/mail/smtpd.conf > listen on lo > accept from local for any relay > > ### > > As far as I can see, no attempt is being made to use TLS at any point. > In case it's revelant; my desktop runs ArchLinux, the server is OpenBSD 5.3. > > Thanks, > > -- > Hugo Osvaldo Barrera -- Gilles Chehade https://www.poolp.org @poolpOrg -- You received this email because you are subscribed to the "[email protected]" list To unsubscribe, send mail with subject: [[email protected]] unregister
