SNI problem

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
12 messages Options
Reply | Threaded
Open this post in threaded view
|

SNI problem

Ján Máté
Hi Postfix users,

I have a problem with the new tls_server_sni_maps configuration option - it seems that Postfix (3.4.10 debian-buster) is unable to load the key+cert+chain combination using this option. The error is "SNI data for smtp.myserver.eu does not match next certificate" even if I am 100% sure that the key+cert+chain is OK, because I use the same key+cert+chain (loaded from same files) for the smtpd_tls_chain_files (and there it works).

Related config files:

/etc/postfix/main.cf:
tls_server_sni_maps = hash:/etc/postfix/table_hash-tls_server_sni_maps
smtpd_tls_chain_files =
    /etc/letsencrypt/live/eu.server.smtp/privkey.pem
    /etc/letsencrypt/live/eu.server.smtp/fullchain.pem

/etc/postfix/table_hash-tls_server_sni_maps (indexed using: postmap -F hash:/etc/postfix/table_hash-tls_server_sni_maps):
smtp.myserver.eu /etc/letsencrypt/live/eu.myserver.smtp/privkey.pem /etc/letsencrypt/live/eu.myserver.smtp/fullchain.pem
smtp.myserver2.eu /etc/letsencrypt/live/eu.myserver2.smtp/privkey.pem /etc/letsencrypt/live/eu.myserver2.smtp/fullchain.pem


Key+cert+chain hash info (the fullchain.pem file contains the cert.pem + chain.pem):
=== privkey.pem
ee key hash
(stdin)= b6dae1eecaa9a2b366b2acddf2ea2cfcec4fe8132ad2e8147be487b0ef241fc3
ee cert pubkey hash
(stdin)= -NONE-
ee chain names

=== cert.pem
ee key hash
(stdin)= -NONE-
ee cert pubkey hash
(stdin)= b6dae1eecaa9a2b366b2acddf2ea2cfcec4fe8132ad2e8147be487b0ef241fc3
ee chain names
subject=CN = smtp.myserver.eu
issuer=C = US, O = Let's Encrypt, CN = Let's Encrypt Authority X3

=== chain.pem
ee key hash
(stdin)= -NONE-
ee cert pubkey hash
(stdin)= 60b87575447dcba2a36b7d11ac09fb24a9db406fee12d2cc90180517616e8a18
ee chain names
subject=C = US, O = Let's Encrypt, CN = Let's Encrypt Authority X3
issuer=O = Digital Signature Trust Co., CN = DST Root CA X3



Info related to my testing:

Connection to Postfix from a remote server (client) using the correct "servername" in the SNI:

root@otherserver:~# openssl s_client -servername smtp.myserver.eu -starttls smtp -connect smtp.myserver.eu:25
CONNECTED(00000003)
140179153458304:error:14094438:SSL routines:ssl3_read_bytes:tlsv1 alert internal error:../ssl/record/rec_layer_s3.c:1544:SSL alert number 80
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 335 bytes and written 726 bytes
Verification: OK
---
New, (NONE), Cipher is (NONE)
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
Verify return code: 0 (ok)
---

Postfix server logs (server):

May 26 22:38:58 myserver postfix/smtpd[72379]: maps_file_find: tls_server_sni_maps: hash:/etc/postfix/table_hash-tls_server_sni_maps(0,lock|fold_fix|src_rhs_is_file): smtp.myserver.eu = LS0tLS1CRUdJTiBQUklWQVRFIEtFWS0tLS0tCk1JSUpRd0lCQURBTkJna3Foa2lHOXcwQkFRRUZBQVNDQ1Mwd2dna3BBZ0VBQW9J...
May 26 22:38:58 myserver postfix/smtpd[72379]: warning: key at index 1 in SNI data for smtp.myserver.eu does not match next certificate
May 26 22:38:58 myserver postfix/smtpd[72379]: warning: TLS library problem: error:1426D121:SSL routines:ssl_set_cert_and_key:not replacing certificate:../ssl/ssl_rsa.c:1107:
May 26 22:38:58 myserver postfix/smtpd[72379]: warning: error loading private keys and certificates from: SNI data for smtp.myserver.eu: aborting TLS handshake



Connection to Postfix from a remote server (client) without SNI servername (or SNI name not present in the tls_server_sni_maps):

root@otherserver:~# openssl s_client -noservername -starttls smtp -connect smtp.myserver.eu:25
CONNECTED(00000003)
depth=2 O = Digital Signature Trust Co., CN = DST Root CA X3
verify return:1
depth=1 C = US, O = Let's Encrypt, CN = Let's Encrypt Authority X3
verify return:1
depth=0 CN = smtp.myserver.eu
verify return:1
---
Certificate chain
 0 s:CN = smtp.myserver.eu
   i:C = US, O = Let's Encrypt, CN = Let's Encrypt Authority X3
 1 s:C = US, O = Let's Encrypt, CN = Let's Encrypt Authority X3
   i:O = Digital Signature Trust Co., CN = DST Root CA X3
---
Server certificate
-----BEGIN CERTIFICATE-----
...
...
...
-----END CERTIFICATE-----
subject=CN = smtp.myserver.eu

issuer=C = US, O = Let's Encrypt, CN = Let's Encrypt Authority X3

---
No client certificate CA names sent
Peer signing digest: SHA256
Peer signature type: RSA-PSS
Server Temp Key: ECDH, P-384, 384 bits
---
SSL handshake has read 4013 bytes and written 744 bytes
Verification: OK
---
New, TLSv1.3, Cipher is TLS_AES_256_GCM_SHA384
Server public key is 4096 bit
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
Verify return code: 0 (ok)
---
250 CHUNKING
---
Post-Handshake New Session Ticket arrived:
SSL-Session:
    Protocol  : TLSv1.3
    Cipher    : TLS_AES_256_GCM_SHA384
    Session-ID: 325F23D6EF2F8EF88571D5404773D64EDF2E5BAE1F126F9F17BF5C8DD7401EC0
    Session-ID-ctx: 
    Resumption PSK: 3E8690233C86E7A57A559DE1A0B60D4D0AA63524D3765ECACE0E03F48159E402D1CB457E7F87FB3C54EF2106B60B317A
    PSK identity: None
    PSK identity hint: None
    SRP username: None
    TLS session ticket lifetime hint: 7200 (seconds)
    TLS session ticket:
    ...
    ...
    ...

    Start Time: 1590529279
    Timeout   : 7200 (sec)
    Verify return code: 0 (ok)
    Extended master secret: no
    Max Early Data: 0
---
read R BLOCK



In short: if a connection from the client is performed without SNI (or SNI hostname not present in the tls_server_sni_maps) then everything works as expected (key+cert+chain from smtpd_tls_chain_files is used), but if I connect using a valid SNI hostname (the new tls_server_sni_maps is used) then the same key+cert+chain not works.

The /etc/postfix/table_hash-tls_server_sni_maps is correctly indexed using postmap -F, and also the:

postmap -Fq smtp.myserver.eu hash:/etc/postfix/table_hash-tls_server_sni_maps

returns the correct key+cert+chain:

-----BEGIN PRIVATE KEY-----
...
... here is the private key for smtp.myserver.eu
...
-----END PRIVATE KEY-----
-----BEGIN CERTIFICATE-----
...
... here is the certificate for smtp.myserver.eu
...
-----END CERTIFICATE-----
-----BEGIN CERTIFICATE-----
...
... here is the certificate for intermediate CA 
...
-----END CERTIFICATE-----


Any idea how to fix this problem?


Kind regards,


JM

Reply | Threaded
Open this post in threaded view
|

Re: SNI problem

Viktor Dukhovni
On Wed, May 27, 2020 at 12:40:25AM +0200, Ján Máté wrote:

> The error is "SNI data for smtp.myserver.eu does not match next
> certificate" even if I am 100% sure that the key+cert+chain is OK,
> because I use the same key+cert+chain (loaded from same files) for the
> smtpd_tls_chain_files (and there it works).

This is the symptom, the cause is indicated by the message one logged
next to it.

> /etc/postfix/main.cf:
> tls_server_sni_maps = hash:/etc/postfix/table_hash-tls_server_sni_maps
> smtpd_tls_chain_files =
>     /etc/letsencrypt/live/eu.server.smtp/privkey.pem
>     /etc/letsencrypt/live/eu.server.smtp/fullchain.pem
>
> /etc/postfix/table_hash-tls_server_sni_maps
> smtp.myserver.eu /etc/letsencrypt/live/eu.myserver.smtp/privkey.pem /etc/letsencrypt/live/eu.myserver.smtp/fullchain.pem
> smtp.myserver2.eu /etc/letsencrypt/live/eu.myserver2.smtp/privkey.pem /etc/letsencrypt/live/eu.myserver2.smtp/fullchain.pem

I just tested with:

    main.cf:
        smtpd_tls_loglevel = 1
        smtpd_tls_security_level = may
        smtpd_tls_chain_files =
                ${config_directory}/ee1pkey.pem
                ${config_directory}/ee1cert.pem
                ${config_directory}/cacert.pem
        tls_server_sni_maps = hash:${config_directory}/sni

    sni
        mx1.example.com
            .../ee1pkey.pem
            .../ee1cert.pem
            .../cacert.pem
        mx2.example.com
            .../ee2pkey.pem
            .../ee2cert.pem
            .../cacert.pem

My logs below...

> May 26 22:38:58 myserver postfix/smtpd[72379]: maps_file_find: tls_server_sni_maps: hash:/etc/postfix/table_hash-tls_server_sni_maps(0,lock|fold_fix|src_rhs_is_file): smtp.myserver.eu <http://smtp.myserver.eu/> = LS0tLS1CRUdJTiBQUklWQVRFIEtFWS0tLS0tCk1JSUpRd0lCQURBTkJna3Foa2lHOXcwQkFRRUZBQVNDQ1Mwd2dna3BBZ0VBQW9J...

You generally don't want to log this data (your log level is too high),
and should not publish it, it is liable to reveal part of your private
key, though luckily, in this case, only some of the fixed header bits
and none of the key material.

> May 26 22:38:58 myserver postfix/smtpd[72379]: warning: key at index 1 in SNI data for smtp.myserver.eu does not match next certificate
> May 26 22:38:58 myserver postfix/smtpd[72379]: warning: TLS library problem: error:1426D121:SSL routines:ssl_set_cert_and_key:not replacing certificate:../ssl/ssl_rsa.c:1107:

The second message is the real problem, OpenSSL believes it already has
a certificate loaded for that algorithm, which should not be the case.
The new key then does not match the already installed certificate.  But
there shouldn't be one already loaded.

> May 26 22:38:58 myserver postfix/smtpd[72379]: warning: error loading private keys and certificates from: SNI data for smtp.myserver.eu: aborting TLS handshake

And so things go wrong.  On the other hand, my logs show:

    postfix/postfix-script[95733]: starting the Postfix mail system
    postfix/master[95735]: daemon started -- version 3.6-20200511, configuration /var/tmp/postfix/etc

    -- No SNI servername used
    postfix/smtpd[95756]: connect from localhost[127.0.0.1]
    postfix/smtpd[95756]: Anonymous TLS connection established from localhost[127.0.0.1]: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
    postfix/smtpd[95756]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 quit=1 commands=3

    -- SNI servername: mx1.example.com
    postfix/smtpd[95756]: connect from localhost[127.0.0.1]
    postfix/smtpd[95756]: Anonymous TLS connection established from localhost[127.0.0.1] to mx1.example.com: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
    postfix/smtpd[95756]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 quit=1 commands=3

    -- SNI servername: mx2.example.com
    postfix/smtpd[95756]: connect from localhost[127.0.0.1]
    postfix/smtpd[95756]: Anonymous TLS connection established from localhost[127.0.0.1] to mx2.example.com: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
    postfix/smtpd[95756]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 quit=1 commands=3

> In short: if a connection from the client is performed without SNI (or
> SNI hostname not present in the tls_server_sni_maps) then everything
> works as expected (key+cert+chain from smtpd_tls_chain_files is used),
> but if I connect using a valid SNI hostname (the new
> tls_server_sni_maps is used) then the same key+cert+chain not works.

It seems that somehow, a certificate of the same type is already loaded
into the SSL handle under construction.  It is unclear how that
happened.

> postmap -Fq smtp.myserver.eu hash:/etc/postfix/table_hash-tls_server_sni_maps
>
> returns the correct key+cert+chain:
>
> -----BEGIN PRIVATE KEY-----
> ...
> ... here is the private key for smtp.myserver.eu
> ...
> -----END PRIVATE KEY-----
> -----BEGIN CERTIFICATE-----
> ...
> ... here is the certificate for smtp.myserver.eu
> ...
> -----END CERTIFICATE-----
> -----BEGIN CERTIFICATE-----
> ...
> ... here is the certificate for intermediate CA
> ...
> -----END CERTIFICATE-----

That seems reasonable, is there anything in your system-wide openssl.cnf
file that looks like a default certificate chain that might be preloaded
into each new SSL_CTX?

--
    Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: SNI problem

Ján Máté
Hi Victor,

thanks for the explanation what's happening in the internals of Postfix, but the problem is still a mystery for me ...

I use the default Debian (Buster) /etc/ssl/openssl.cnf without any modifications, so I don't think that there is any default certificate chain that might be preloaded into each new SSL_CTX.

It looks like SNI works for you, but I cannot get it working - and tried really hard for more than a week (I read everything I found on Google and it looks like there are few people with working setup, and the remaining say that it does not work) :-/

Any idea how to debug it myself? ... or even better - I can allow you root access to the test server to check it yourself (just send me a private e-mail with your ssh public key).


Many thanks!


JM


> On 9 Jun 2020, at 19:07, Viktor Dukhovni <[hidden email]> wrote:
>
> On Wed, May 27, 2020 at 12:40:25AM +0200, Ján Máté wrote:
>
>> The error is "SNI data for smtp.myserver.eu does not match next
>> certificate" even if I am 100% sure that the key+cert+chain is OK,
>> because I use the same key+cert+chain (loaded from same files) for the
>> smtpd_tls_chain_files (and there it works).
>
> This is the symptom, the cause is indicated by the message one logged
> next to it.
>
>> /etc/postfix/main.cf:
>> tls_server_sni_maps = hash:/etc/postfix/table_hash-tls_server_sni_maps
>> smtpd_tls_chain_files =
>>    /etc/letsencrypt/live/eu.server.smtp/privkey.pem
>>    /etc/letsencrypt/live/eu.server.smtp/fullchain.pem
>>
>> /etc/postfix/table_hash-tls_server_sni_maps
>> smtp.myserver.eu /etc/letsencrypt/live/eu.myserver.smtp/privkey.pem /etc/letsencrypt/live/eu.myserver.smtp/fullchain.pem
>> smtp.myserver2.eu /etc/letsencrypt/live/eu.myserver2.smtp/privkey.pem /etc/letsencrypt/live/eu.myserver2.smtp/fullchain.pem
>
> I just tested with:
>
>    main.cf:
>        smtpd_tls_loglevel = 1
>        smtpd_tls_security_level = may
>        smtpd_tls_chain_files =
>                ${config_directory}/ee1pkey.pem
>                ${config_directory}/ee1cert.pem
>                ${config_directory}/cacert.pem
>        tls_server_sni_maps = hash:${config_directory}/sni
>
>    sni
>        mx1.example.com
>            .../ee1pkey.pem
>            .../ee1cert.pem
>            .../cacert.pem
>        mx2.example.com
>            .../ee2pkey.pem
>            .../ee2cert.pem
>            .../cacert.pem
>
> My logs below...
>
>> May 26 22:38:58 myserver postfix/smtpd[72379]: maps_file_find: tls_server_sni_maps: hash:/etc/postfix/table_hash-tls_server_sni_maps(0,lock|fold_fix|src_rhs_is_file): smtp.myserver.eu <http://smtp.myserver.eu/> = LS0tLS1CRUdJTiBQUklWQVRFIEtFWS0tLS0tCk1JSUpRd0lCQURBTkJna3Foa2lHOXcwQkFRRUZBQVNDQ1Mwd2dna3BBZ0VBQW9J...
>
> You generally don't want to log this data (your log level is too high),
> and should not publish it, it is liable to reveal part of your private
> key, though luckily, in this case, only some of the fixed header bits
> and none of the key material.
>
>> May 26 22:38:58 myserver postfix/smtpd[72379]: warning: key at index 1 in SNI data for smtp.myserver.eu does not match next certificate
>> May 26 22:38:58 myserver postfix/smtpd[72379]: warning: TLS library problem: error:1426D121:SSL routines:ssl_set_cert_and_key:not replacing certificate:../ssl/ssl_rsa.c:1107:
>
> The second message is the real problem, OpenSSL believes it already has
> a certificate loaded for that algorithm, which should not be the case.
> The new key then does not match the already installed certificate.  But
> there shouldn't be one already loaded.
>
>> May 26 22:38:58 myserver postfix/smtpd[72379]: warning: error loading private keys and certificates from: SNI data for smtp.myserver.eu: aborting TLS handshake
>
> And so things go wrong.  On the other hand, my logs show:
>
>    postfix/postfix-script[95733]: starting the Postfix mail system
>    postfix/master[95735]: daemon started -- version 3.6-20200511, configuration /var/tmp/postfix/etc
>
>    -- No SNI servername used
>    postfix/smtpd[95756]: connect from localhost[127.0.0.1]
>    postfix/smtpd[95756]: Anonymous TLS connection established from localhost[127.0.0.1]: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
>    postfix/smtpd[95756]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 quit=1 commands=3
>
>    -- SNI servername: mx1.example.com
>    postfix/smtpd[95756]: connect from localhost[127.0.0.1]
>    postfix/smtpd[95756]: Anonymous TLS connection established from localhost[127.0.0.1] to mx1.example.com: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
>    postfix/smtpd[95756]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 quit=1 commands=3
>
>    -- SNI servername: mx2.example.com
>    postfix/smtpd[95756]: connect from localhost[127.0.0.1]
>    postfix/smtpd[95756]: Anonymous TLS connection established from localhost[127.0.0.1] to mx2.example.com: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
>    postfix/smtpd[95756]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 quit=1 commands=3
>
>> In short: if a connection from the client is performed without SNI (or
>> SNI hostname not present in the tls_server_sni_maps) then everything
>> works as expected (key+cert+chain from smtpd_tls_chain_files is used),
>> but if I connect using a valid SNI hostname (the new
>> tls_server_sni_maps is used) then the same key+cert+chain not works.
>
> It seems that somehow, a certificate of the same type is already loaded
> into the SSL handle under construction.  It is unclear how that
> happened.
>
>> postmap -Fq smtp.myserver.eu hash:/etc/postfix/table_hash-tls_server_sni_maps
>>
>> returns the correct key+cert+chain:
>>
>> -----BEGIN PRIVATE KEY-----
>> ...
>> ... here is the private key for smtp.myserver.eu
>> ...
>> -----END PRIVATE KEY-----
>> -----BEGIN CERTIFICATE-----
>> ...
>> ... here is the certificate for smtp.myserver.eu
>> ...
>> -----END CERTIFICATE-----
>> -----BEGIN CERTIFICATE-----
>> ...
>> ... here is the certificate for intermediate CA
>> ...
>> -----END CERTIFICATE-----
>
> That seems reasonable, is there anything in your system-wide openssl.cnf
> file that looks like a default certificate chain that might be preloaded
> into each new SSL_CTX?
>
> --
>    Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: SNI problem

Viktor Dukhovni
On Tue, Jun 09, 2020 at 08:31:27PM +0200, Ján Máté wrote:

> Thanks for the explanation what's happening in the internals of
> Postfix, but the problem is still a mystery for me ...
>
> I use the default Debian (Buster) /etc/ssl/openssl.cnf without any
> modifications, so I don't think that there is any default certificate
> chain that might be preloaded into each new SSL_CTX.

Have you looked at that file?  Any mention of any default certificate
chain files there?

> It looks like SNI works for you, but I cannot get it working - and
> tried really hard for more than a week (I read everything I found on
> Google and it looks like there are few people with working setup, and
> the remaining say that it does not work) :-/
>
> Any idea how to debug it myself? ... or even better - I can allow you
> root access to the test server to check it yourself (just send me a
> private e-mail with your ssh public key).

Can you strace the SMTP server process?  Add a "-D" flag to the
smtpd(8) entry in master.cf after setting:

    debugger_command =
        PATH=/usr/bin:/bin:/usr/sbin:/sbin
        strace -o /tmp/tr.$process_name.$process_id -p $process_id & sleep 1

Then 'grep open' in the trace file, looking for unexpected reads of
certificate chain files.

To get closer to your config, I just built Postfix 3.4.12, against
OpenSSL 1.1.1, which also works:

    # postfix start
    postfix/postfix-script: starting the Postfix mail system

    # openssl s_client -CAfile rootcert.pem -servername mx1.example.com -starttls smtp -connect localhost:25 -brief
    CONNECTION ESTABLISHED
    Protocol version: TLSv1.3
    Ciphersuite: TLS_AES_256_GCM_SHA384
    Peer certificate: CN = mx1.example.com
    Hash used: SHA256
    Signature type: RSA-PSS
    Verification: OK
    Server Temp Key: X25519, 253 bits
    250 CHUNKING
    quit
    221 2.0.0 Bye

    # openssl s_client -CAfile rootcert.pem -servername mx2.example.com -starttls smtp -connect localhost:25 -brief
    CONNECTION ESTABLISHED
    Protocol version: TLSv1.3
    Ciphersuite: TLS_AES_256_GCM_SHA384
    Peer certificate: CN = mx2.example.com
    Hash used: SHA256
    Signature type: RSA-PSS
    Verification: OK
    Server Temp Key: X25519, 253 bits
    250 CHUNKING
    quit
    221 2.0.0 Bye

    # openssl s_client -CAfile rootcert.pem -servername mx1.example.com -starttls smtp -connect localhost:25 -brief
    CONNECTION ESTABLISHED
    Protocol version: TLSv1.3
    Ciphersuite: TLS_AES_256_GCM_SHA384
    Peer certificate: CN = mx1.example.com
    Hash used: SHA256
    Signature type: RSA-PSS
    Verification: OK
    Server Temp Key: X25519, 253 bits
    250 CHUNKING
    quit
    221 2.0.0 Bye

    # openssl s_client -CAfile rootcert.pem -servername mx2.example.com -starttls smtp -connect localhost:25 -brief
    CONNECTION ESTABLISHED
    Protocol version: TLSv1.3
    Ciphersuite: TLS_AES_256_GCM_SHA384
    Peer certificate: CN = mx2.example.com
    Hash used: SHA256
    Signature type: RSA-PSS
    Verification: OK
    Server Temp Key: X25519, 253 bits
    250 CHUNKING
    quit
    221 2.0.0 Bye

    # cat ../log/maillog
    Jun 09 15:35:23 vpro postfix/postfix-script[2294]: starting the Postfix mail system
    Jun 09 15:35:23 vpro postfix/master[2296]: daemon started -- version 3.4.12, configuration /var/tmp/postfix/etc
    Jun 09 15:35:28 vpro postfix/smtpd[2301]: connect from localhost[127.0.0.1]
    Jun 09 15:35:28 vpro postfix/smtpd[2301]: Anonymous TLS connection established from localhost[127.0.0.1] to mx1.example.com: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
    Jun 09 15:35:30 vpro postfix/smtpd[2301]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 quit=1 commands=3
    Jun 09 15:35:31 vpro postfix/smtpd[2301]: connect from localhost[127.0.0.1]
    Jun 09 15:35:31 vpro postfix/smtpd[2301]: Anonymous TLS connection established from localhost[127.0.0.1] to mx2.example.com: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
    Jun 09 15:35:33 vpro postfix/smtpd[2301]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 quit=1 commands=3
    Jun 09 15:35:34 vpro postfix/smtpd[2301]: connect from localhost[127.0.0.1]
    Jun 09 15:35:34 vpro postfix/smtpd[2301]: Anonymous TLS connection established from localhost[127.0.0.1] to mx1.example.com: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
    Jun 09 15:35:35 vpro postfix/smtpd[2301]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 quit=1 commands=3
    Jun 09 15:35:37 vpro postfix/smtpd[2301]: connect from localhost[127.0.0.1]
    Jun 09 15:35:37 vpro postfix/smtpd[2301]: Anonymous TLS connection established from localhost[127.0.0.1] to mx2.example.com: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange X25519 server-signature RSA-PSS (2048 bits) server-digest SHA256
    Jun 09 15:35:38 vpro postfix/smtpd[2301]: disconnect from localhost[127.0.0.1] ehlo=1 starttls=1 quit=1 commands=3

The main.cf file is the stock one I get from an install from source
plus:

    inet_interfaces = loopback-only

    local_recipient_maps =
    mydestination =
    alias_database =
    alias_maps = $alias_database
    local_transport = error:5.1.2:Mailbox unavailable

    smtpd_tls_loglevel = 1
    smtpd_tls_security_level = may
    smtpd_tls_chain_files =
            ${config_directory}/ee1pkey.pem
            ${config_directory}/ee1cert.pem
            ${config_directory}/cacert.pem

    tls_server_sni_maps = hash:${config_directory}/sni
    maillog_file = /var/tmp/postfix/log/maillog

My laptop OpenSSL dev library is a slightly dated 1.1.1c snapshot:

    # postconf -T compile-version
    OpenSSL 1.1.1c-dev  xx XXX xxxx
    # postconf -T run-version
    OpenSSL 1.1.1c-dev  xx XXX xxxx

but that won't differ materially from 1.1.1g, also a stock upstream
(from OpenSSL.org) openssl.cnf file, no Debian special-sauce.

--
    Viktor.
Reply | Threaded
Open this post in threaded view
|

Re: SNI problem

Ján Máté
Hi Victor,

yes, I looked at /etc/ssl/openssl.cnf and found nothing related to default or preloaded chain.

See the result of the debug from strace - only 3 cert related files are opened = the private key, full chain and DH param:

openat(AT_FDCWD, "pid/inet.smtp", O_RDWR) = 9
openat(AT_FDCWD, "/etc/aliases.db", O_RDONLY) = 12
openat(AT_FDCWD, "/sys/devices/system/cpu/online", O_RDONLY|O_CLOEXEC) = 13
openat(AT_FDCWD, "/etc/DB_CONFIG", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/aliases.db", O_RDONLY) = 13
openat(AT_FDCWD, "/etc/aliases.db", O_RDONLY) = 14
openat(AT_FDCWD, "/usr/lib/postfix/postfix-ldap.so", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/usr/lib/postfix/libldap_r-2.4.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libldap_r-2.4.so.2", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/usr/lib/postfix/liblber-2.4.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/liblber-2.4.so.2", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libgnutls.so.30", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libp11-kit.so.0", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libidn2.so.0", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libunistring.so.2", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libtasn1.so.6", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libnettle.so.6", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libhogweed.so.4", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libgmp.so.10", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libffi.so.6", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/etc/host.conf", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 12
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libcrammd5.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libgssapiv2.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libgssapi_krb5.so.2", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libkrb5.so.3", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libk5crypto.so.3", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libcom_err.so.2", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libkrb5support.so.0", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libkeyutils.so.1", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libntlm.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libscram.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libsasldb.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libgs2.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/etc/gss/mech.d", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libdigestmd5.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libanonymous.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/liblogin.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libcrypt.so.1", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libplain.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/etc/ldap/ldap.conf", O_RDONLY) = 12
openat(AT_FDCWD, "ldaprc", O_RDONLY)    = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/postfix/tables/ldap-virtual_alias_maps", O_RDONLY) = 12
openat(AT_FDCWD, "/etc/postfix/tables/ldap-virtual_alias_maps-alternate", O_RDONLY) = 12
openat(AT_FDCWD, "/etc/postfix/tables/ldap-virtual_mailbox_maps", O_RDONLY) = 12
openat(AT_FDCWD, "/usr/lib/postfix/postfix-pcre.so", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/usr/lib/postfix/libpcre.so.3", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpcre.so.3", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/etc/postfix/tables/pcre-check_helo_access", O_RDONLY) = 12
openat(AT_FDCWD, "/etc/postfix/sasl/smtpd.conf", O_RDONLY) = 12
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 12
openat(AT_FDCWD, "/dev/urandom", O_RDONLY) = 15
openat(AT_FDCWD, "/etc/postfix/tables/hash-tls_server_sni_maps.db", O_RDONLY) = 12
openat(AT_FDCWD, "/etc/postfix/tables/DB_CONFIG", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/postfix/tables/hash-tls_server_sni_maps.db", O_RDONLY) = 15
openat(AT_FDCWD, "/etc/postfix/tables/hash-tls_server_sni_maps.db", O_RDONLY) = 16
openat(AT_FDCWD, "/usr/lib/ssl/openssl.cnf", O_RDONLY) = 17
openat(AT_FDCWD, "/etc/letsencrypt/live/smtp.example.com/privkey.pem", O_RDONLY) = 17
openat(AT_FDCWD, "/etc/letsencrypt/live/smtp.example.com/fullchain.pem", O_RDONLY) = 17
openat(AT_FDCWD, "/etc/ssl/local/dh_ffdhe4096.pem", O_RDONLY) = 17
openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/proc/sys/kernel/ngroups_max", O_RDONLY) = 17
openat(AT_FDCWD, "/etc/group", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libnss_systemd.so.2", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/librt.so.1", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/run/systemd/userdb/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 17
openat(AT_FDCWD, "/proc/sys/kernel/random/boot_id", O_RDONLY|O_NOCTTY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/var/lib/sss/mc/initgroups", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 22
openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 22
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/tls/haswell/x86_64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/tls/haswell/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/tls/x86_64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/tls/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/haswell/x86_64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/haswell/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/x86_64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = 22
openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 22

openssl s_client -servername smtp.example.com -starttls smtp -connect smtp.example.com:25
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: key at index 1 in SNI data for smtp.example.com does not match next certificate
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: TLS library problem: error:1426D121:SSL routines:ssl_set_cert_and_key:not replacing certificate:../ssl/ssl_rsa.c:1107:
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: error loading private keys and certificates from: SNI data for smtp.example.com: aborting TLS handshake
Jun  9 22:17:55 example postfix/smtpd[246494]: SSL_accept error from ***[93.***.***.***]: -1
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: TLS library problem: error:1422E0EA:SSL routines:final_server_name:callback failed:../ssl/statem/extensions.c:1007:
Jun  9 22:17:55 example postfix/smtpd[246494]: lost connection after STARTTLS from ***[93.***.***.***]
Jun  9 22:17:55 example postfix/smtpd[246494]: disconnect from ***[93.184.***.***] ehlo=1 starttls=0/1 commands=1/2

server log:
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: key at index 1 in SNI data for smtp.example.com does not match next certificate
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: TLS library problem: error:1426D121:SSL routines:ssl_set_cert_and_key:not replacing certificate:../ssl/ssl_rsa.c:1107:
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: error loading private keys and certificates from: SNI data for smtp.example.com: aborting TLS handshake
Jun  9 22:17:55 example postfix/smtpd[246494]: SSL_accept error from ***[93.***.***.***]: -1
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: TLS library problem: error:1422E0EA:SSL routines:final_server_name:callback failed:../ssl/statem/extensions.c:1007:


Any further ideas?


Thanks,


JM
Reply | Threaded
Open this post in threaded view
|

Re: SNI problem

Ján Máté
Ups,

the correct

openssl s_client -servername smtp.example.com -starttls smtp -connect smtp.example.com:25

output:


CONNECTED(00000003)
140192932344960:error:14094438:SSL routines:ssl3_read_bytes:tlsv1 alert internal error:../ssl/record/rec_layer_s3.c:1544:SSL alert number 80
---
no peer certificate available
---
No client certificate CA names sent
---
SSL handshake has read 326 bytes and written 726 bytes
Verification: OK
---
New, (NONE), Cipher is (NONE)
Secure Renegotiation IS NOT supported
Compression: NONE
Expansion: NONE
No ALPN negotiated
Early data was not sent
Verify return code: 0 (ok)
---


JM


On 9 Jun 2020, at 22:36, Ján Máté <[hidden email]> wrote:

Hi Victor,

yes, I looked at /etc/ssl/openssl.cnf and found nothing related to default or preloaded chain.

See the result of the debug from strace - only 3 cert related files are opened = the private key, full chain and DH param:

openat(AT_FDCWD, "pid/inet.smtp", O_RDWR) = 9
openat(AT_FDCWD, "/etc/aliases.db", O_RDONLY) = 12
openat(AT_FDCWD, "/sys/devices/system/cpu/online", O_RDONLY|O_CLOEXEC) = 13
openat(AT_FDCWD, "/etc/DB_CONFIG", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/aliases.db", O_RDONLY) = 13
openat(AT_FDCWD, "/etc/aliases.db", O_RDONLY) = 14
openat(AT_FDCWD, "/usr/lib/postfix/postfix-ldap.so", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/usr/lib/postfix/libldap_r-2.4.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libldap_r-2.4.so.2", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/usr/lib/postfix/liblber-2.4.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/liblber-2.4.so.2", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libgnutls.so.30", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libp11-kit.so.0", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libidn2.so.0", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libunistring.so.2", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libtasn1.so.6", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libnettle.so.6", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libhogweed.so.4", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libgmp.so.10", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libffi.so.6", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/etc/host.conf", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 12
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libcrammd5.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libgssapiv2.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libgssapi_krb5.so.2", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libkrb5.so.3", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libk5crypto.so.3", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libcom_err.so.2", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libkrb5support.so.0", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libkeyutils.so.1", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libntlm.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libscram.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libsasldb.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libgs2.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/etc/gss/mech.d", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libdigestmd5.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libanonymous.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/liblogin.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libcrypt.so.1", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2/libplain.so", O_RDONLY|O_CLOEXEC) = 15
openat(AT_FDCWD, "/etc/ldap/ldap.conf", O_RDONLY) = 12
openat(AT_FDCWD, "ldaprc", O_RDONLY)    = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/postfix/tables/ldap-virtual_alias_maps", O_RDONLY) = 12
openat(AT_FDCWD, "/etc/postfix/tables/ldap-virtual_alias_maps-alternate", O_RDONLY) = 12
openat(AT_FDCWD, "/etc/postfix/tables/ldap-virtual_mailbox_maps", O_RDONLY) = 12
openat(AT_FDCWD, "/usr/lib/postfix/postfix-pcre.so", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/usr/lib/postfix/libpcre.so.3", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpcre.so.3", O_RDONLY|O_CLOEXEC) = 12
openat(AT_FDCWD, "/etc/postfix/tables/pcre-check_helo_access", O_RDONLY) = 12
openat(AT_FDCWD, "/etc/postfix/sasl/smtpd.conf", O_RDONLY) = 12
openat(AT_FDCWD, "/usr/lib/x86_64-linux-gnu/sasl2", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 12
openat(AT_FDCWD, "/dev/urandom", O_RDONLY) = 15
openat(AT_FDCWD, "/etc/postfix/tables/hash-tls_server_sni_maps.db", O_RDONLY) = 12
openat(AT_FDCWD, "/etc/postfix/tables/DB_CONFIG", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/postfix/tables/hash-tls_server_sni_maps.db", O_RDONLY) = 15
openat(AT_FDCWD, "/etc/postfix/tables/hash-tls_server_sni_maps.db", O_RDONLY) = 16
openat(AT_FDCWD, "/usr/lib/ssl/openssl.cnf", O_RDONLY) = 17
openat(AT_FDCWD, "/etc/letsencrypt/live/smtp.example.com/privkey.pem", O_RDONLY) = 17
openat(AT_FDCWD, "/etc/letsencrypt/live/smtp.example.com/fullchain.pem", O_RDONLY) = 17
openat(AT_FDCWD, "/etc/ssl/local/dh_ffdhe4096.pem", O_RDONLY) = 17
openat(AT_FDCWD, "/etc/passwd", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/proc/sys/kernel/ngroups_max", O_RDONLY) = 17
openat(AT_FDCWD, "/etc/group", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libnss_systemd.so.2", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/librt.so.1", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/run/systemd/userdb/", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 17
openat(AT_FDCWD, "/proc/sys/kernel/random/boot_id", O_RDONLY|O_NOCTTY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libnss_sss.so.2", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/var/lib/sss/mc/initgroups", O_RDONLY|O_CLOEXEC) = 17
openat(AT_FDCWD, "/etc/resolv.conf", O_RDONLY|O_CLOEXEC) = 22
openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 22
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/tls/haswell/x86_64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/tls/haswell/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/tls/x86_64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/tls/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/haswell/x86_64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/haswell/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/x86_64/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libnss_dns.so.2", O_RDONLY|O_CLOEXEC) = 22
openat(AT_FDCWD, "/etc/hosts", O_RDONLY|O_CLOEXEC) = 22

openssl s_client -servername smtp.example.com -starttls smtp -connect smtp.example.com:25
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: key at index 1 in SNI data for smtp.example.com does not match next certificate
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: TLS library problem: error:1426D121:SSL routines:ssl_set_cert_and_key:not replacing certificate:../ssl/ssl_rsa.c:1107:
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: error loading private keys and certificates from: SNI data for smtp.example.com: aborting TLS handshake
Jun  9 22:17:55 example postfix/smtpd[246494]: SSL_accept error from ***[93.***.***.***]: -1
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: TLS library problem: error:1422E0EA:SSL routines:final_server_name:callback failed:../ssl/statem/extensions.c:1007:
Jun  9 22:17:55 example postfix/smtpd[246494]: lost connection after STARTTLS from ***[93.***.***.***]
Jun  9 22:17:55 example postfix/smtpd[246494]: disconnect from ***[93.184.***.***] ehlo=1 starttls=0/1 commands=1/2

server log:
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: key at index 1 in SNI data for smtp.example.com does not match next certificate
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: TLS library problem: error:1426D121:SSL routines:ssl_set_cert_and_key:not replacing certificate:../ssl/ssl_rsa.c:1107:
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: error loading private keys and certificates from: SNI data for smtp.example.com: aborting TLS handshake
Jun  9 22:17:55 example postfix/smtpd[246494]: SSL_accept error from ***[93.***.***.***]: -1
Jun  9 22:17:55 example postfix/smtpd[246494]: warning: TLS library problem: error:1422E0EA:SSL routines:final_server_name:callback failed:../ssl/statem/extensions.c:1007:


Any further ideas?


Thanks,


JM

Reply | Threaded
Open this post in threaded view
|

Re: SNI problem

Viktor Dukhovni
In reply to this post by Viktor Dukhovni


> On Jun 9, 2020, at 1:07 PM, Viktor Dukhovni <[hidden email]> wrote:
>
>> May 26 22:38:58 myserver postfix/smtpd[72379]: warning: key at index 1 in SNI data for smtp.myserver.eu does not match next certificate
>> May 26 22:38:58 myserver postfix/smtpd[72379]: warning: TLS library problem: error:1426D121:SSL routines:ssl_set_cert_and_key:not replacing certificate:../ssl/ssl_rsa.c:1107:
>
> The second message is the real problem, OpenSSL believes it already has
> a certificate loaded for that algorithm, which should not be the case.
> The new key then does not match the already installed certificate.  But
> there shouldn't be one already loaded.

Amazingly enough the issue seems to be caused by an obsolete, and
seemingly unrelated setting in the OP's main.cf file:

        smtpd_tls_eecdh_grade = ultra

This predates support for automatic negotiated EC curve selection
in OpenSSL, and is now just a bad idea.  The default "auto" setting
is the only correct one to use.  That said, how this breaks loading
of RSA certificate chains is rather a deep mystery I shall pursue
with the OpenSSL team.

The OP also has other excessive fine-tuning of the TLS stack that
is somewhat counter-productive.

  * 4096 bit RSA cert
  * TLS 1.0 disabled
  * Overly specific cipherlist
  * ...

For SMTP, try to have modest, but broadly interoperable expectations
of security that raise the ceiling rather than the floor.

        https://tools.ietf.org/rfc7435

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: SNI problem

Ján Máté
Hi Victor,

many thanks for finding out the cause of the problem - I hope the information about smtpd_tls_eecdh_grade will be useful for other Postfix users!


JM


> On 10 Jun 2020, at 01:22, Viktor Dukhovni <[hidden email]> wrote:
>
>
>
>> On Jun 9, 2020, at 1:07 PM, Viktor Dukhovni <[hidden email]> wrote:
>>
>>> May 26 22:38:58 myserver postfix/smtpd[72379]: warning: key at index 1 in SNI data for smtp.myserver.eu does not match next certificate
>>> May 26 22:38:58 myserver postfix/smtpd[72379]: warning: TLS library problem: error:1426D121:SSL routines:ssl_set_cert_and_key:not replacing certificate:../ssl/ssl_rsa.c:1107:
>>
>> The second message is the real problem, OpenSSL believes it already has
>> a certificate loaded for that algorithm, which should not be the case.
>> The new key then does not match the already installed certificate.  But
>> there shouldn't be one already loaded.
>
> Amazingly enough the issue seems to be caused by an obsolete, and
> seemingly unrelated setting in the OP's main.cf file:
>
> smtpd_tls_eecdh_grade = ultra
>
> This predates support for automatic negotiated EC curve selection
> in OpenSSL, and is now just a bad idea.  The default "auto" setting
> is the only correct one to use.  That said, how this breaks loading
> of RSA certificate chains is rather a deep mystery I shall pursue
> with the OpenSSL team.
>
> The OP also has other excessive fine-tuning of the TLS stack that
> is somewhat counter-productive.
>
>  * 4096 bit RSA cert
>  * TLS 1.0 disabled
>  * Overly specific cipherlist
>  * ...
>
> For SMTP, try to have modest, but broadly interoperable expectations
> of security that raise the ceiling rather than the floor.
>
> https://tools.ietf.org/rfc7435
>
> --
> Viktor.
>

Reply | Threaded
Open this post in threaded view
|

PATCH: Handle TLS 1.3 Hello retry requests (was: SNI problem)

Viktor Dukhovni
In reply to this post by Viktor Dukhovni
> On Jun 9, 2020, at 7:22 PM, Viktor Dukhovni <[hidden email]> wrote:
>
> This predates support for automatic negotiated EC curve selection
> in OpenSSL, and is now just a bad idea.  The default "auto" setting
> is the only correct one to use.  That said, how this breaks loading
> of RSA certificate chains is rather a deep mystery I shall pursue
> with the OpenSSL team.

Turns out the problem is that my SNI code in Postfix did not expect
to be called twice for the same connection as happens with TLS 1.3
HRR (hello retry requests) when the client's key share guess does
not match the server's supported signature algorithms (e.g. only P384
with "smtpd_tls_eecdh_grade = ultra").

Git commit at:

  https://github.com/vdukhovni/postfix/commit/851b525c5c09405c48b8cd697d14cb0d2edbb68b

Raw patch:

  https://github.com/vdukhovni/postfix/commit/851b525c5c09405c48b8cd697d14cb0d2edbb68b.patch

This applies to Postfix 3.4, 3.5 and 3.6 snapshots.

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: PATCH: Handle TLS 1.3 Hello retry requests (was: SNI problem)

Wietse Venema
Viktor Dukhovni:

> > On Jun 9, 2020, at 7:22 PM, Viktor Dukhovni <[hidden email]> wrote:
> >
> > This predates support for automatic negotiated EC curve selection
> > in OpenSSL, and is now just a bad idea.  The default "auto" setting
> > is the only correct one to use.  That said, how this breaks loading
> > of RSA certificate chains is rather a deep mystery I shall pursue
> > with the OpenSSL team.
>
> Turns out the problem is that my SNI code in Postfix did not expect
> to be called twice for the same connection as happens with TLS 1.3
> HRR (hello retry requests) when the client's key share guess does
> not match the server's supported signature algorithms (e.g. only P384
> with "smtpd_tls_eecdh_grade = ultra").
>
> Git commit at:
>
>   https://github.com/vdukhovni/postfix/commit/851b525c5c09405c48b8cd697d14cb0d2edbb68b
>
> Raw patch:
>
>   https://github.com/vdukhovni/postfix/commit/851b525c5c09405c48b8cd697d14cb0d2edbb68b.patch
>
> This applies to Postfix 3.4, 3.5 and 3.6 snapshots.

Released in postfix-3.6-20200610. Stable releases will be updated
after the code has been running for a few days.

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: SNI problem

Nikolai Lusan
In reply to this post by Viktor Dukhovni
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

Thank you very much for finding that.

I have been having the same issue for months now, and was beginning to
think I might have to resort to writing a patch to the SNI code which was
seemingly not inspecting deep enough into the certificates (i.e. if you had
more than one hostname in the TLS cert - as in the case of a letsencrypt
wildcard cert - only first name was being matched). Turns out I was wrong,
but I hadn't had the time to sit down and properly debug the issue.

I had the "smtpd_tls_eecdh_grade" set to "strong", after removing it from
the main.cf file and letting it default I can verify that the starttls sni
all works on my servers.


On Tue, 2020-06-09 at 19:22 -0400, Viktor Dukhovni wrote:

> > On Jun 9, 2020, at 1:07 PM, Viktor Dukhovni <[hidden email]
> > > wrote:
> >
> > > May 26 22:38:58 myserver postfix/smtpd[72379]: warning: key at index
> > > 1 in SNI data for smtp.myserver.eu does not match next certificate
> > > May 26 22:38:58 myserver postfix/smtpd[72379]: warning: TLS library
> > > problem: error:1426D121:SSL routines:ssl_set_cert_and_key:not
> > > replacing certificate:../ssl/ssl_rsa.c:1107:
> >
> > The second message is the real problem, OpenSSL believes it already has
> > a certificate loaded for that algorithm, which should not be the case.
> > The new key then does not match the already installed certificate.  But
> > there shouldn't be one already loaded.
>
> Amazingly enough the issue seems to be caused by an obsolete, and
> seemingly unrelated setting in the OP's main.cf file:
>
> smtpd_tls_eecdh_grade = ultra
>
> This predates support for automatic negotiated EC curve selection
> in OpenSSL, and is now just a bad idea.  The default "auto" setting
> is the only correct one to use.  That said, how this breaks loading
> of RSA certificate chains is rather a deep mystery I shall pursue
> with the OpenSSL team.
>
> The OP also has other excessive fine-tuning of the TLS stack that
> is somewhat counter-productive.
>
>   * 4096 bit RSA cert
>   * TLS 1.0 disabled
>   * Overly specific cipherlist
>   * ...
>
> For SMTP, try to have modest, but broadly interoperable expectations
> of security that raise the ceiling rather than the floor.
>
> https://tools.ietf.org/rfc7435
>
- --
Nikolai Lusan <[hidden email]>
-----BEGIN PGP SIGNATURE-----

iQIzBAEBCgAdFiEEVfd4GW6z4nsBxdLo4ZaDRV2VL6QFAl7jnRAACgkQ4ZaDRV2V
L6QovQ/9GhBj69ncJVApi6vKtGUvY5lxe/Epff5knj49LTh1c+s1gN3VWMowvYwz
hmXkZQeeA5s/5m1Lp3W+3ZAeyIjoGqP4MQNfrNjQB+HtK6sdq/eVD55saRBAn8Lx
mIRCmfvEK0HeojL2PEVpW3SI/39Hzs9DqyNkFBu4l1d8x1GFf2abSgewBBGye9Zo
J+nORi6Hf1jBHCj/euuFGrr5N1nSNKq/lpP4bGXJxTKH0nwEEazIAhp+C8xdbgry
UOZyLJvmuwMIQk/MUb7q4NU/XdjLW95GAugkg+8pFdcdkF08c+TO2ARwNuJPzQRm
XNgd+VyV8uhrP4+DoVc0aL+76tmSu3lchap8HYLSxq+H+WhgOdKTCrBsQl1rw9od
vUJ62BqI9a/7lskYu6yT1tjhgGjle4S8stDXln1efKQfTLuX/q17xqjLR0RRCHod
gaoDERDsYJAOriMlG3KzTO96kTDNtqJT41LPIG188XUb6zQ9r+0vpoyU65HKugNx
Lv0HApEsvEo25BIWSsMbTALX2mr62IJQ7K3AqyafZYDGdg+H06aOhBj5dQRlr6QF
0Pys7yp4KMJoy/kqwanQI9Rd1EtDW5+L97qyARmqtQ2TdOmxOL8ayte5spF/c9Ks
4SWCcMMFifSJ34xfZ48nwtZCampOAM/3aHlb3LweN+FB6bQaaIA=
=o4N+
-----END PGP SIGNATURE-----

Reply | Threaded
Open this post in threaded view
|

Re: SNI problem

Viktor Dukhovni
On Sat, Jun 13, 2020 at 01:19:44AM +1000, Nikolai Lusan wrote:

> Thank you very much for finding that.

The OP provided a system on which I could compare:

    - Vendor Postfix vs. Postfix built from source
    - stock configs vs. OP's actual config.

It turned out that the configuration was what mattered, and then it was
just a matter of adding one setting at a time, until the SNI chain
failed to load.  After that a bunch of head- scratching as to why the
EECDH grade would matter, but no longer requiring a remote system to
find how to reproduce.

> I had the "smtpd_tls_eecdh_grade" set to "strong", after removing it from
> the main.cf file and letting it default I can verify that the starttls sni
> all works on my servers.

That's of course a good idea, with or without the bug, for which the
real fix is one of the upcoming releases, even with the EECDH grade
set to "auto", HRR might happen anyway, just far less likely.  So
upgrade when a patch release is available for your system.

--
    Viktor.