smptd - sslv3 alert handshake failure

[Bjorn Ketelaars]

I have a smtpd config, which has been running for >1 year without a
hitch until now. All outgoing mail is forwarded to a remote SMTP server
using a config similar to an example in smtpd.conf(5).

Forwarding is failing because of "handshake failed: error:1404B410:SSL
routines:ST_CONNECT:sslv3 alert handshake failure" (see below for more
information). I'm running current (amd64) with an update frequency of
~twice a week. This error started popping up this weekend - before the
libssl/libtls/libcrypto bump. Error remains after the bump.

$ cat /etc/mail/smtpd.conf
table aliases file:/etc/mail/aliases
table secrets file:/etc/mail/secrets

listen on lo0

action "local" mbox alias <aliases>
action "relay" relay host smtp+tls://***@smtp.ziggo.nl:587 auth <secrets>

match from local for local action "local"
match from local for any action "relay"


I bisected libssl/libtls/libcrypto (checked all changes of the last 2
months) without solving my issue. I also checked smtpd, and found that
eric@'s work on moving smtpd to libtls [0] is related to my issue.
Reverting smtpd to a version prior to March 5 fixes it for me. Best
guess - probably a stupid one - is that the remote host changed
something causing SNI related issues.

Hints on how to further investigate the above are appreciated!


[0] https://marc.info/?l=openbsd-cvs&m=161494786013059&w=2

debug: scheduler: scheduling evp:2b97a598686ca143
debug: scheduler: evp:2b97a598686ca143 scheduled (mta)
debug: mta: querying smarthost for relay:<dynamic:0>...
debug: mta: querying smarthost
debug: mta: ... got smarthost for 2b97a598686ca143: smtp+tls://***@smtp.ziggo.nl:587
debug: mta: received evp:2b97a598686ca143 for <***@hydroxide.nl>
debug: mta: draining [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] refcount=1, ntask=1, nconnector=0, nconn=0
debug: mta: querying secret for [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]...
debug: mta: querying MX for [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]...
debug: mta: [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] waiting for MX secret
debug: control -> client: pipe closed
debug: clearing p=client, fd=11, pid=0
debug: mta: ... got secret for [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]: AGJrZXRAemlnZ28ubmwAREgmd2pQVyZkS3V3enA2a2wqKjM=
debug: mta: draining [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] refcount=2, ntask=1, nconnector=0, nconn=0
debug: mta: [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] waiting for MX
debug: MXs for domain smtp.ziggo.nl:
212.54.42.9 preference -1
debug: mta: ... got mx (0x4c260099920, smtp.ziggo.nl, [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx])
debug: mta: draining [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] refcount=1, ntask=1, nconnector=0, nconn=0
debug: mta: querying source for [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]...
debug: mta: ... got source for [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]: []
debug: mta: new [connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x10000]
debug: mta: connecting with [connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x0]
debug: mta-routing: searching new route for [connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x0]...
debug: mta-routing: selecting candidate route [] <-> 212.54.42.9
debug: mta-routing: spawning new connection on [] <-> 212.54.42.9
debug: mta: 0x4c2600b96d0: spawned for relay [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]
debug: mta: connecting with [connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x0]
debug: mta: cannot use [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] before 2s
debug: mta-routing: no route available for [connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x0]: must wait a bit
debug: mta: retrying to connect on [connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x0] in 2s...
debug: mta: draining [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] refcount=3, ntask=1, nconnector=1, nconn=1
debug: mta: scheduling relay [relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] in 1s...
9483c6637b224554 mta connecting address=smtp+tls://212.54.42.9:587 host=smtp.mail.gtm.iss.as9143.net
9483c6637b224554 mta connected
debug: mta: 0x4c2600b96d0: IO error: handshake failed: error:1404B410:SSL routines:ST_CONNECT:sslv3 alert handshake failure
9483c6637b224554 mta error reason=IO Error: handshake failed: error:1404B410:SSL routines:ST_CONNECT:sslv3 alert handshake failure
debug: mta: 0x4c2600b96d0: session done
...

[Nick Ryan]

Bjorn, have a look at this from the opensmtpd mailling list.

https://www.mail-archive.com/***@opensmtpd.org/msg05278.html

The message from Eric has how to downgrade the smtpd listener to use all
TLS and compatible ciphers.

Regards.

Post by Bjorn Ketelaars
I have a smtpd config, which has been running for >1 year without a
hitch until now. All outgoing mail is forwarded to a remote SMTP server
using a config similar to an example in smtpd.conf(5).
Forwarding is failing because of "handshake failed: error:1404B410:SSL
routines:ST_CONNECT:sslv3 alert handshake failure" (see below for more
information). I'm running current (amd64) with an update frequency of
~twice a week. This error started popping up this weekend - before the
libssl/libtls/libcrypto bump. Error remains after the bump.
$ cat /etc/mail/smtpd.conf
table aliases file:/etc/mail/aliases
table secrets file:/etc/mail/secrets
listen on lo0
action "local" mbox alias <aliases>
match from local for local action "local"
match from local for any action "relay"
I bisected libssl/libtls/libcrypto (checked all changes of the last 2
months) without solving my issue. I also checked smtpd, and found that
Reverting smtpd to a version prior to March 5 fixes it for me. Best
guess - probably a stupid one - is that the remote host changed
something causing SNI related issues.
Hints on how to further investigate the above are appreciated!
[0] https://marc.info/?l=openbsd-cvs&m=161494786013059&w=2
debug: scheduler: scheduling evp:2b97a598686ca143
debug: scheduler: evp:2b97a598686ca143 scheduled (mta)
debug: mta: querying smarthost for relay:<dynamic:0>...
debug: mta: querying smarthost
debug: mta: received evp:2b97a598686ca143 for
debug: mta: draining
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]
refcount=1, ntask=1, nconnector=0, nconn=0
debug: mta: querying secret for
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]...
debug: mta: querying MX for
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]...
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] waiting
for MX secret
debug: control -> client: pipe closed
debug: clearing p=client, fd=11, pid=0
debug: mta: ... got secret for
AGJrZXRAemlnZ28ubmwAREgmd2pQVyZkS3V3enA2a2wqKjM=
debug: mta: draining
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]
refcount=2, ntask=1, nconnector=0, nconn=0
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] waiting
for MX
212.54.42.9 preference -1
debug: mta: ... got mx (0x4c260099920, smtp.ziggo.nl,
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx])
debug: mta: draining
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]
refcount=1, ntask=1, nconnector=0, nconn=0
debug: mta: querying source for
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]...
debug: mta: ... got source for
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]: []
debug: mta: new
[connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x10000]
debug: mta: connecting with
[connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x0]
debug: mta-routing: searching new route for
[connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x0]...
debug: mta-routing: selecting candidate route [] <-> 212.54.42.9
debug: mta-routing: spawning new connection on [] <-> 212.54.42.9
debug: mta: 0x4c2600b96d0: spawned for relay
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]
debug: mta: connecting with
[connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x0]
debug: mta: cannot use
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] before 2s
debug: mta-routing: no route available for
must wait a bit
debug: mta: retrying to connect on
[connector:[]->[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx],0x0]
in 2s...
debug: mta: draining
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx]
refcount=3, ntask=1, nconnector=1, nconn=1
debug: mta: scheduling relay
[relay:smtp.ziggo.nlort=587,smtp+tls,auth=secrets:ziggo,mx] in 1s...
9483c6637b224554 mta connecting address=smtp+tls://212.54.42.9:587
host=smtp.mail.gtm.iss.as9143.net
9483c6637b224554 mta connected
error:1404B410:SSL routines:ST_CONNECT:sslv3 alert handshake failure
error:1404B410:SSL routines:ST_CONNECT:sslv3 alert handshake failure
debug: mta: 0x4c2600b96d0: session done
...

[Bjorn Ketelaars]

Post by Nick Ryan
Bjorn, have a look at this from the opensmtpd mailling list.
The message from Eric has how to downgrade the smtpd listener to use all TLS
and compatible ciphers.

This helped immensely, thank you! Adding 'ciphers "compat"' fixed my
problem.

I should have known:

$ openssl s_client -connect smtp.ziggo.nl:587 -starttls smtp
...
SSL-Session:
Protocol : TLSv1.2
Cipher : AES256-SHA256
...


According to my maillogs the above mentioned host would allow
TLSv1.3:AEAD-CHACHA20-POLY1305-SHA256 until the time that I started
experiencing problems. I can only guess why they switched.