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
pgpjwK67QVoCr.pgp
Description: PGP signature
