TLS handshake fails ("SSL_accept:error in error") for server->server connection (smtp submit dovecot->postfix) if /etc/pki/tls/openssl.cnf "Options=" includes 'ServerPreference' ?

Thu Sep 24 14:43:04 UTC 2020

> I'd be tempted to drop most if not all of those settings, they're not email-friendly.

PUBLIC email non-friendly, because of still-frequent old cipher/protocol implementations?

or,

inherently problematic with TLS in/onr SMTP?

in this case, there's nothing public ... both the dovecot and postfix instances are internal.  the internal postfix instance hands off to a public facing external postfix instance, which exposes/uses postfix-default cipherlists only.

the attempt is to clean- & tighten-up the comms internally; not that that's particularly relevant to the error(s) seen.

> That's rather more verbose than default Postfix TLS logging, I hope it is temporary.

yep. 'temporarily' monkeying with log levels all over the place, trying to find the cause of this^.
now dialed back.

> Are you sure the third line is copied correctly into your post?

not entirely; it's copied from my too-busy/very-messy 'WTF?' notes.

below, i've (re)included logs instead _directly_ copied from shell.

> That cipherlist, has an extra "T" in front of the TLS 1.3 ChaCha cipher, that should not be there...

fat thumbs in notes, I suspect.

> Also, Postfix has no knowledge of TLS 1.3 cipher suites, Postfix has only cipher configuration knobs only for the TLS <= 1.2 ciphers, so I don't know how that particular string ended up in your logs. 

a bit too postfix-y for this list, but ...

I'm then perhaps misreading

	http://www.postfix.org/TLS_README.html
	http://www.postfix.org/FORWARD_SECRECY_README.html

		"If you want to take maximal advantage of ciphers that offer forward secrecy see the Getting started section of FORWARD_SECRECY_README. The full document conveniently presents all information about Postfix forward secrecy support in one place: what forward secrecy is, how to tweak settings, and what you can expect to see when Postfix uses ciphers with forward secrecy.

		Postfix 2.8 and later, in combination with OpenSSL 0.9.7 and later allows TLS servers to preempt the TLS client's cipher-suite preference list. This is possible only with SSLv3 and later, as in SSLv2 the client chooses the cipher-suite from a list supplied by the server.

		By default, the OpenSSL server selects the client's most preferred cipher-suite that the server supports. With SSLv3 and later, the server may choose its own most preferred cipher-suite that is supported (offered) by the client. Setting "tls_preempt_cipherlist = yes" enables server cipher-suite preferences. The default OpenSSL behavior applies with "tls_preempt_cipherlist = no". "

RE-(re-,re-,etc-)reading, I'm now scratching my head a bit as to which is the server defining the preferences ... my _goal_ was to ensure that the server receiving submission -- 1st @ the MUA -> dovecot listener, then @ dovecot -> postfix -- dictates the ciphers/suites in use. or at least declares preference.

In any case, the following should be with defaults.

> Is there something in your Postfix configuration that resembles that
particular blob?  If so, it should not be there...

yep. now removed ...

with postfix's tls log level dialed back down

	-o smtpd_tls_loglevel=1

and its

	tls_high_cipherlist

back to default

simplifying

	/etc/pki/tls/openssl.cnf
		openssl_conf = default_conf

		[default_conf]
		ssl_conf = ssl_sect

		[ssl_sect]
		system_default = system_default_sect

		[system_default_sect]
		Options = PrioritizeChaCha

@ test submit to dovecot

	cat ~/test.eml | msmtp -a internal testrecipient at example.com

send/receive is successful.

	dovecot logs

		2020-09-24 04:59:01 submission-login: Info: Login: user=<testrecipient at example.com>, method=PLAIN, rip=10.0.1.17, lip=10.0.1.17, mpid=11209, TLS
		2020-09-24 04:59:01 submission(testrecipient at example.com)<q/Y1mg+wauOsHgsy>: Info: Successfully relayed message: from=<myexternaluser at fastmail.fm>, size=135, id=kROCNiWmbF/JKwAA+IOfAw, nrcpt=1, reply=`250 2.0.0 Ok: queued as 4BxxVF6VD2zWf49'
		2020-09-24 04:59:01 lmtp(11200): Info: Connect from local
		2020-09-24 04:59:01 submission(testrecipient at example.com)<q/Y1mg+wauOsHgsy>: Info: Disconnect from 10.0.1.17: Client has quit the connection in=223 out=114 (state=READY)
		2020-09-24 04:59:02 lmtp(testrecipient at example.com)<YCW8NiWmbF/AKwAA+IOfAw>: Info: sieve: msgid=<4BxxVF6VD2zWf49 at mx.example.com>: stored mail into mailbox 'INBOX'
		2020-09-24 04:59:02 lmtp(11200): Info: Disconnect from local: Client has quit the connection (state=READY)

	postfix logs

		Sep 24 04:59:01 mx postfix/submit-from-dovecot-proxy/smtpd[11186]: connect from internal.mx.example.com[10.0.1.17]
		Sep 24 04:59:01 mx postfix/submit-from-dovecot-proxy/smtpd[11186]: Trusted TLS connection established from internal.mx.example.com[10.0.1.17]: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature ECDSA (P-384) server-digest SHA384 client-signature ECDSA (P-384) client-digest SHA384
		Sep 24 04:59:01 mx postfix/submit-from-dovecot-proxy/smtpd[11186]: 4BxxVF6VD2zWf49: client=internal.mx.example.com[10.0.1.17]
		Sep 24 04:59:01 mx postfix/qmgr[11139]: 4BxxVF6VD2zWf49: from=<myexternaluser at fastmail.fm>, size=577, nrcpt=1 (queue active)
		Sep 24 04:59:01 mx postfix/submit-from-dovecot-proxy/smtpd[11186]: disconnect from internal.mx.example.com[10.0.1.17] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
		Sep 24 04:59:02 mx postfix/lmtp[11190]: 4BxxVF6VD2zWf49: to=<testrecipient at example.com>, relay=mx.example.com[private/dovecot-lmtp], delay=0.19, delays=0/0/0/0.19, dsn=2.0.0, status=sent (250 2.0.0 <testrecipient at example.com> YCW8NiWmbF/AKwAA+IOfAw Saved)
		Sep 24 04:59:02 mx postfix/qmgr[11139]: 4BxxVF6VD2zWf49: removed

changing only

	/etc/pki/tls/openssl.cnf
-		Options = PrioritizeChaCha
+		Options = ServerPreference,PrioritizeChaCha

@ re-test submit to dovecot FAILs,

	cat ~/test.eml | msmtp -a internal testrecipient at example.com
		msmtp: envelope from address myexternaluser at fastmail.fm not accepted by the server
		msmtp: server message: 421 4.4.0 internal.mx.example.com Failed to establish relay connection
		msmtp: could not send mail (account internal from /etc/msmtprc)

	dovecot log

		2020-09-24 05:01:44 submission-login: Info: Login: user=<testrecipient at example.com>, method=PLAIN, rip=10.0.1.17, lip=10.0.1.17, mpid=11260, TLS

		==> /var/log/dovecot/dovecot.log <==
		2020-09-24 05:01:44 submission(testrecipient at example.com)<GCHoow+wbuOsHgsy>: Error: smtp-client: conn internal.mx.example.com:465 (10.0.1.17:465) [1]: connect(internal.mx.example.com:465) failed: Failed to initialize SSL: Couldn't initialize SSL context: Can't load SSL certificate: error:14187180:SSL routines:ssl_do_config:bad value: section=system_default, cmd=Options, arg=ServerPreference,PrioritizeChaCha
		2020-09-24 05:01:44 submission(testrecipient at example.com)<GCHoow+wbuOsHgsy>: Error: Failed to establish relay connection: Failed to connect to remote server

		==> /var/log/dovecot/dovecot-info.log <==
		2020-09-24 05:01:44 submission(testrecipient at example.com)<GCHoow+wbuOsHgsy>: Info: Disconnect from 10.0.1.17: Failed to establish relay connection in=0 out=22 (state=GREETING)

	postfix log

		Sep 24 05:01:44 mx postfix/submit-from-dovecot-proxy/smtpd[11261]: connect from internal.mx.example.com[10.0.1.17]
		Sep 24 05:01:44 mx postfix/submit-from-dovecot-proxy/smtpd[11261]: SSL_accept error from internal.mx.example.com[10.0.1.17]: -1
		Sep 24 05:01:44 mx postfix/submit-from-dovecot-proxy/smtpd[11261]: warning: TLS library problem: error:1408F10B:SSL routines:ssl3_get_record:wrong version number:ssl/record/ssl3_record.c:331:
		Sep 24 05:01:44 mx postfix/submit-from-dovecot-proxy/smtpd[11261]: lost connection after CONNECT from internal.mx.example.com[10.0.1.17]
		Sep 24 05:01:44 mx postfix/submit-from-dovecot-proxy/smtpd[11261]: disconnect from internal.mx.example.com[10.0.1.17] commands=0/0

again, the _only_ change between the two submissions is the addition of the "ServerPreference" option to the openssl.cnf config.

still not clear to me which piece(s) of that^ are having an issue with it. or why.

for this list, my initial question is -- *IS* it openssl's "fault"?  or mine, or one of the other apps'?