How to debug a TLSv1.3 protocol problem?

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

How to debug a TLSv1.3 protocol problem?

Claus Assmann
I'm stuck and looking for some hints/help.  I have two MTAs (let's
call them M1 and S8), both built with OpenSSL 1.1.1g. The problem
is M1 cannot establish a TLSv1.3 connection with S8. Using other
MTAs/sites/protocols/tools works just fine, e.g., M1 can send mail
to google using TLSv1.3, and S8 can send mail to M1. Replacing the
server or client with openssl s_client/s_server also works.

I've added some TLS callbacks to S8 which I found in s_cb.c, but
all I get at the end is "SSL_accept:error in TLSv1.3 early data"
(see "full" trace below for the steps leading to this).
Unfortunately I cannot find a way to figure out more details or
what kind of error that is.  Any hints how to determine (and fix?)
the problem?

S8 server side:
info_callback where=0x10, ret=1
info_callback where=0x2001, ret=1
SSL_accept:before SSL initialization
ssl_msg_cb, writep=0, version=0, len=5, ct=256
ssl_msg_cb, before SSL initialization
info_callback where=0x2001, ret=1
SSL_accept:before SSL initialization
ssl_msg_cb, writep=0, version=772, len=512, ct=22
ssl_msg_cb, SSLv3/TLS read client hello
info_callback where=0x2001, ret=1
SSL_accept:SSLv3/TLS read client hello
ssl_msg_cb, writep=1, version=0, len=5, ct=256
ssl_msg_cb, SSLv3/TLS write server hello
ssl_msg_cb, writep=1, version=772, len=88, ct=22
ssl_msg_cb, SSLv3/TLS write server hello
info_callback where=0x2001, ret=1
SSL_accept:SSLv3/TLS write server hello
ssl_msg_cb, writep=1, version=0, len=5, ct=256
ssl_msg_cb, SSLv3/TLS write change cipher spec
ssl_msg_cb, writep=1, version=772, len=1, ct=20
ssl_msg_cb, SSLv3/TLS write change cipher spec
info_callback where=0x2001, ret=1
SSL_accept:SSLv3/TLS write change cipher spec
info_callback where=0x2001, ret=1
SSL_accept:TLSv1.3 early data
info_callback where=0x2002, ret=-1
SSL_accept:error in TLSv1.3 early data

M1 client side:
apps_ssl_info_cb, where=10, ret=1
apps_ssl_info_cb, SSL_connect=before SSL initialization
ssl_msg_cb, writep=1, version=0, len=5, ct=100
ssl_msg_cb, SSLv3/TLS write client hello
ssl_msg_cb, writep=1, version=772, len=512, ct=16
ssl_msg_cb, SSLv3/TLS write client hello
apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
ssl_msg_cb, writep=0, version=0, len=5, ct=100
ssl_msg_cb, SSLv3/TLS write client hello
apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
ssl_msg_cb, writep=0, version=772, len=88, ct=16
ssl_msg_cb, SSLv3/TLS read server hello
apps_ssl_info_cb, SSL_connect=SSLv3/TLS read server hello
ssl_msg_cb, writep=1, version=0, len=5, ct=100
ssl_msg_cb, SSLv3/TLS write change cipher spec
ssl_msg_cb, writep=1, version=772, len=1, ct=14
ssl_msg_cb, SSLv3/TLS write change cipher spec
apps_ssl_info_cb, SSL_connect=SSLv3/TLS write change cipher spec
ssl_msg_cb, writep=1, version=0, len=5, ct=100
ssl_msg_cb, SSLv3/TLS write client hello
ssl_msg_cb, writep=1, version=772, len=512, ct=16
ssl_msg_cb, SSLv3/TLS write client hello
apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
ssl_msg_cb, writep=0, version=0, len=5, ct=100
ssl_msg_cb, SSLv3/TLS write client hello

and here it hangs until timeout.

Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Matt Caswell-2
Are you able to capture a wireshark trace of the handshake?

Matt

On 18/05/2020 17:59, Claus Assmann wrote:

> I'm stuck and looking for some hints/help.  I have two MTAs (let's
> call them M1 and S8), both built with OpenSSL 1.1.1g. The problem
> is M1 cannot establish a TLSv1.3 connection with S8. Using other
> MTAs/sites/protocols/tools works just fine, e.g., M1 can send mail
> to google using TLSv1.3, and S8 can send mail to M1. Replacing the
> server or client with openssl s_client/s_server also works.
>
> I've added some TLS callbacks to S8 which I found in s_cb.c, but
> all I get at the end is "SSL_accept:error in TLSv1.3 early data"
> (see "full" trace below for the steps leading to this).
> Unfortunately I cannot find a way to figure out more details or
> what kind of error that is.  Any hints how to determine (and fix?)
> the problem?
>
> S8 server side:
> info_callback where=0x10, ret=1
> info_callback where=0x2001, ret=1
> SSL_accept:before SSL initialization
> ssl_msg_cb, writep=0, version=0, len=5, ct=256
> ssl_msg_cb, before SSL initialization
> info_callback where=0x2001, ret=1
> SSL_accept:before SSL initialization
> ssl_msg_cb, writep=0, version=772, len=512, ct=22
> ssl_msg_cb, SSLv3/TLS read client hello
> info_callback where=0x2001, ret=1
> SSL_accept:SSLv3/TLS read client hello
> ssl_msg_cb, writep=1, version=0, len=5, ct=256
> ssl_msg_cb, SSLv3/TLS write server hello
> ssl_msg_cb, writep=1, version=772, len=88, ct=22
> ssl_msg_cb, SSLv3/TLS write server hello
> info_callback where=0x2001, ret=1
> SSL_accept:SSLv3/TLS write server hello
> ssl_msg_cb, writep=1, version=0, len=5, ct=256
> ssl_msg_cb, SSLv3/TLS write change cipher spec
> ssl_msg_cb, writep=1, version=772, len=1, ct=20
> ssl_msg_cb, SSLv3/TLS write change cipher spec
> info_callback where=0x2001, ret=1
> SSL_accept:SSLv3/TLS write change cipher spec
> info_callback where=0x2001, ret=1
> SSL_accept:TLSv1.3 early data
> info_callback where=0x2002, ret=-1
> SSL_accept:error in TLSv1.3 early data
>
> M1 client side:
> apps_ssl_info_cb, where=10, ret=1
> apps_ssl_info_cb, SSL_connect=before SSL initialization
> ssl_msg_cb, writep=1, version=0, len=5, ct=100
> ssl_msg_cb, SSLv3/TLS write client hello
> ssl_msg_cb, writep=1, version=772, len=512, ct=16
> ssl_msg_cb, SSLv3/TLS write client hello
> apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
> ssl_msg_cb, writep=0, version=0, len=5, ct=100
> ssl_msg_cb, SSLv3/TLS write client hello
> apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
> ssl_msg_cb, writep=0, version=772, len=88, ct=16
> ssl_msg_cb, SSLv3/TLS read server hello
> apps_ssl_info_cb, SSL_connect=SSLv3/TLS read server hello
> ssl_msg_cb, writep=1, version=0, len=5, ct=100
> ssl_msg_cb, SSLv3/TLS write change cipher spec
> ssl_msg_cb, writep=1, version=772, len=1, ct=14
> ssl_msg_cb, SSLv3/TLS write change cipher spec
> apps_ssl_info_cb, SSL_connect=SSLv3/TLS write change cipher spec
> ssl_msg_cb, writep=1, version=0, len=5, ct=100
> ssl_msg_cb, SSLv3/TLS write client hello
> ssl_msg_cb, writep=1, version=772, len=512, ct=16
> ssl_msg_cb, SSLv3/TLS write client hello
> apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
> ssl_msg_cb, writep=0, version=0, len=5, ct=100
> ssl_msg_cb, SSLv3/TLS write client hello
>
> and here it hangs until timeout.
>
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Alexander Gryanko
In reply to this post by Claus Assmann
Hi,

You can try to add SSL_CTX_set_keylog_callback to your MTA. With keylog callback, your MTA will start writing log in NSS format for decryption of TLS frames. https://wiki.wireshark.org/TLS#Using_the_.28Pre.29-Master-Secret

Or you can enable SSL_trace with disabling OPENSSL_NO_SSL_TRACE build option and  SSL_set_msg_callback(client_ssl, SSL_trace) callback.

But first of all, check your cert type. Looks like you are using non-RSA cert which is not supported by S8.

On Mon, 18 May 2020 at 20:00, Claus Assmann <[hidden email]> wrote:
I'm stuck and looking for some hints/help.  I have two MTAs (let's
call them M1 and S8), both built with OpenSSL 1.1.1g. The problem
is M1 cannot establish a TLSv1.3 connection with S8. Using other
MTAs/sites/protocols/tools works just fine, e.g., M1 can send mail
to google using TLSv1.3, and S8 can send mail to M1. Replacing the
server or client with openssl s_client/s_server also works.

I've added some TLS callbacks to S8 which I found in s_cb.c, but
all I get at the end is "SSL_accept:error in TLSv1.3 early data"
(see "full" trace below for the steps leading to this).
Unfortunately I cannot find a way to figure out more details or
what kind of error that is.  Any hints how to determine (and fix?)
the problem?

S8 server side:
info_callback where=0x10, ret=1
info_callback where=0x2001, ret=1
SSL_accept:before SSL initialization
ssl_msg_cb, writep=0, version=0, len=5, ct=256
ssl_msg_cb, before SSL initialization
info_callback where=0x2001, ret=1
SSL_accept:before SSL initialization
ssl_msg_cb, writep=0, version=772, len=512, ct=22
ssl_msg_cb, SSLv3/TLS read client hello
info_callback where=0x2001, ret=1
SSL_accept:SSLv3/TLS read client hello
ssl_msg_cb, writep=1, version=0, len=5, ct=256
ssl_msg_cb, SSLv3/TLS write server hello
ssl_msg_cb, writep=1, version=772, len=88, ct=22
ssl_msg_cb, SSLv3/TLS write server hello
info_callback where=0x2001, ret=1
SSL_accept:SSLv3/TLS write server hello
ssl_msg_cb, writep=1, version=0, len=5, ct=256
ssl_msg_cb, SSLv3/TLS write change cipher spec
ssl_msg_cb, writep=1, version=772, len=1, ct=20
ssl_msg_cb, SSLv3/TLS write change cipher spec
info_callback where=0x2001, ret=1
SSL_accept:SSLv3/TLS write change cipher spec
info_callback where=0x2001, ret=1
SSL_accept:TLSv1.3 early data
info_callback where=0x2002, ret=-1
SSL_accept:error in TLSv1.3 early data

M1 client side:
apps_ssl_info_cb, where=10, ret=1
apps_ssl_info_cb, SSL_connect=before SSL initialization
ssl_msg_cb, writep=1, version=0, len=5, ct=100
ssl_msg_cb, SSLv3/TLS write client hello
ssl_msg_cb, writep=1, version=772, len=512, ct=16
ssl_msg_cb, SSLv3/TLS write client hello
apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
ssl_msg_cb, writep=0, version=0, len=5, ct=100
ssl_msg_cb, SSLv3/TLS write client hello
apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
ssl_msg_cb, writep=0, version=772, len=88, ct=16
ssl_msg_cb, SSLv3/TLS read server hello
apps_ssl_info_cb, SSL_connect=SSLv3/TLS read server hello
ssl_msg_cb, writep=1, version=0, len=5, ct=100
ssl_msg_cb, SSLv3/TLS write change cipher spec
ssl_msg_cb, writep=1, version=772, len=1, ct=14
ssl_msg_cb, SSLv3/TLS write change cipher spec
apps_ssl_info_cb, SSL_connect=SSLv3/TLS write change cipher spec
ssl_msg_cb, writep=1, version=0, len=5, ct=100
ssl_msg_cb, SSLv3/TLS write client hello
ssl_msg_cb, writep=1, version=772, len=512, ct=16
ssl_msg_cb, SSLv3/TLS write client hello
apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
ssl_msg_cb, writep=0, version=0, len=5, ct=100
ssl_msg_cb, SSLv3/TLS write client hello

and here it hangs until timeout.



--
С уважением,
Александр Грянко
Phone: +7(962)9558222
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Claus Assmann
In reply to this post by Claus Assmann
On Mon, May 18, 2020, Alexander Gryanko wrote:

[thanks for the hints, I will try that ASAP]

> But first of all, check your cert type. Looks like you are using non-RSA
> cert which is not supported by S8.

As I wrote: it works fine if I don't use TLSv1.3 or if I use openssl
s_client with TLSv1.3 (it is an RSA cert and I also tested against
another S8 server which uses a Let's Encrypt cert).
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Viktor Dukhovni
In reply to this post by Claus Assmann
On Mon, May 18, 2020 at 06:59:59PM +0200, Claus Assmann wrote:

> I'm stuck and looking for some hints/help.  I have two MTAs (let's
> call them M1 and S8), both built with OpenSSL 1.1.1g. The problem
> is M1 cannot establish a TLSv1.3 connection with S8. Using other
> MTAs/sites/protocols/tools works just fine, e.g., M1 can send mail
> to google using TLSv1.3, and S8 can send mail to M1. Replacing the
> server or client with openssl s_client/s_server also works.

I'll strongly second Matt's request for a PCAP file.

> M1 client side:
> apps_ssl_info_cb, where=10, ret=1
> apps_ssl_info_cb, SSL_connect=before SSL initialization
> ssl_msg_cb, writep=1, version=0, len=5, ct=100
> ssl_msg_cb, SSLv3/TLS write client hello
> ssl_msg_cb, writep=1, version=772, len=512, ct=16
> ssl_msg_cb, SSLv3/TLS write client hello
> apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
> ssl_msg_cb, writep=0, version=0, len=5, ct=100
> ssl_msg_cb, SSLv3/TLS write client hello
> apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
> ssl_msg_cb, writep=0, version=772, len=88, ct=16
> ssl_msg_cb, SSLv3/TLS read server hello
> apps_ssl_info_cb, SSL_connect=SSLv3/TLS read server hello
> ssl_msg_cb, writep=1, version=0, len=5, ct=100
> ssl_msg_cb, SSLv3/TLS write change cipher spec
> ssl_msg_cb, writep=1, version=772, len=1, ct=14
> ssl_msg_cb, SSLv3/TLS write change cipher spec
> apps_ssl_info_cb, SSL_connect=SSLv3/TLS write change cipher spec
> ssl_msg_cb, writep=1, version=0, len=5, ct=100
> ssl_msg_cb, SSLv3/TLS write client hello
> ssl_msg_cb, writep=1, version=772, len=512, ct=16
> ssl_msg_cb, SSLv3/TLS write client hello
> apps_ssl_info_cb, SSL_connect=SSLv3/TLS write client hello
> ssl_msg_cb, writep=0, version=0, len=5, ct=100
> ssl_msg_cb, SSLv3/TLS write client hello

The client trace looks rather odd, why is writing the hello
again after CCS?  I don't recall what happens with HRR
(Hello retry request) when client's initial keyshare is
not usable on the server...  Any unusual signature algorithm
preferences in this particular client?

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

Re: How to debug a TLSv1.3 protocol problem?

Jan Just Keijser-2
In reply to this post by Claus Assmann
Hi Claus,

On 18/05/20 20:59, Claus Assmann wrote:
> On Mon, May 18, 2020, Alexander Gryanko wrote:
>
> [thanks for the hints, I will try that ASAP]
>
>> But first of all, check your cert type. Looks like you are using non-RSA
>> cert which is not supported by S8.
> As I wrote: it works fine if I don't use TLSv1.3 or if I use openssl
> s_client with TLSv1.3 (it is an RSA cert and I also tested against
> another S8 server which uses a Let's Encrypt cert).
FWIW:  adding TLS 1.3 support to my EAP-TLS code got me stumped for a
while as well. I eventually added up the following snippet:

     /* Set up a SSL Session cache with a callback. This is needed for
TLSv1.3+.
      * During the initial handshake the server signals to the client
early on
      * that the handshake is finished, even before the client has sent its
      * credentials to the server. The actual connection (and moment
that the
      * client sends its credentials) only starts after the arrival of
the first
      * session ticket. The 'ssl_new_session_cb' catches this ticket.
      */
     SSL_CTX_set_session_cache_mode(ctx, SSL_SESS_CACHE_CLIENT |
SSL_SESS_CACHE_NO_INTERNAL_STORE);
     SSL_CTX_sess_set_new_cb(ctx, ssl_new_session_cb);



with

int ssl_new_session_cb(SSL *s, SSL_SESSION *sess)
{
     dbglog("EAP-TLS: Post-Handshake New Session Ticket arrived:");

     /* always return success */
     return 1;
}


This callback is necessary as otherwise the client thinks the session
handshake is done too soon (and in my case, it does not bother to send
any client-side certificate info to the server).

Perhaps you are seeing something similar? If not, then sorry for the noise.

HTH,

JJK / Jan Just Keijser

Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Claus Assmann
On Tue, May 19, 2020, Jan Just Keijser wrote:

> FWIW:  adding TLS 1.3 support to my EAP-TLS code got me stumped for a while as
> well. I eventually added up the following snippet:

>     SSL_CTX_set_session_cache_mode(ctx, SSL_SESS_CACHE_CLIENT |
> SSL_SESS_CACHE_NO_INTERNAL_STORE);
>     SSL_CTX_sess_set_new_cb(ctx, ssl_new_session_cb);

Thanks, I actally added the callback yesterday based on reading
s_client.c.  It didn't change anything :-(
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Claus Assmann
In reply to this post by Viktor Dukhovni
On Mon, May 18, 2020, Viktor Dukhovni wrote:

> I'll strongly second Matt's request for a PCAP file.

If tcpdump is "good enough" then that should be attached.
If wireshark and some TLS decoding is needed, then I need
some time to figure that out.

> The client trace looks rather odd, why is writing the hello
> again after CCS?  I don't recall what happens with HRR

Maybe M1 doesn't get an answer?

> (Hello retry request) when client's initial keyshare is
> not usable on the server...  Any unusual signature algorithm
> preferences in this particular client?

AFIACT none at all.

I've added SSL_trace as suggested and the output is below.
When I compare M1 with openssl s_client the main difference
is that s_client has
extension_type=padding
but I don't see where/how M1 would turn that off (or where
s_client turns it on?)

------------------------------------------------------------
M8 client side:
Sent Record
Header:
  Version = TLS 1.0 (0x301)
  Content Type = Handshake (22)
  Length = 512
    ClientHello, Length=508
      client_version=0x303 (TLS 1.2)
      Random:
        gmt_unix_time=0x2CE5293F
        random_bytes (len=28): 60F8FD89D6BFFC32D30870CF534B271108BD7E00452949D9E2CECD7D
      session_id (len=32): E028F6D32F2F0FB8CC112794C7AA4E97AD76EDF6B955F49B51CA837F6115ABE2
      cipher_suites (len=62)
        {0x13, 0x02} TLS_AES_256_GCM_SHA384
        {0x13, 0x03} TLS_CHACHA20_POLY1305_SHA256
        {0x13, 0x01} TLS_AES_128_GCM_SHA256
        {0xC0, 0x2C} TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
        {0xC0, 0x30} TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
        {0x00, 0x9F} TLS_DHE_RSA_WITH_AES_256_GCM_SHA384
        {0xCC, 0xA9} TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
        {0xCC, 0xA8} TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256
        {0xCC, 0xAA} TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256
        {0xC0, 0x2B} TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
        {0xC0, 0x2F} TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
        {0x00, 0x9E} TLS_DHE_RSA_WITH_AES_128_GCM_SHA256
        {0xC0, 0x24} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384
        {0xC0, 0x28} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
        {0x00, 0x6B} TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
        {0xC0, 0x23} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256
        {0xC0, 0x27} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
        {0x00, 0x67} TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
        {0xC0, 0x0A} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
        {0xC0, 0x14} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
        {0x00, 0x39} TLS_DHE_RSA_WITH_AES_256_CBC_SHA
        {0xC0, 0x09} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA
        {0xC0, 0x13} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0x33} TLS_DHE_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0x9D} TLS_RSA_WITH_AES_256_GCM_SHA384
        {0x00, 0x9C} TLS_RSA_WITH_AES_128_GCM_SHA256
        {0x00, 0x3D} TLS_RSA_WITH_AES_256_CBC_SHA256
        {0x00, 0x3C} TLS_RSA_WITH_AES_128_CBC_SHA256
        {0x00, 0x35} TLS_RSA_WITH_AES_256_CBC_SHA
        {0x00, 0x2F} TLS_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0xFF} TLS_EMPTY_RENEGOTIATION_INFO_SCSV
      compression_methods (len=1)
        No Compression (0x00)
      extensions, length = 373
        extension_type=ec_point_formats(11), length=4
          uncompressed (0)
          ansiX962_compressed_prime (1)
          ansiX962_compressed_char2 (2)
        extension_type=supported_groups(10), length=12
          ecdh_x25519 (29)
          secp256r1 (P-256) (23)
          ecdh_x448 (30)
          secp521r1 (P-521) (25)
          secp384r1 (P-384) (24)
        extension_type=encrypt_then_mac(22), length=0
        extension_type=extended_master_secret(23), length=0
        extension_type=signature_algorithms(13), length=48
          ecdsa_secp256r1_sha256 (0x0403)
          ecdsa_secp384r1_sha384 (0x0503)
          ecdsa_secp521r1_sha512 (0x0603)
          ed25519 (0x0807)
          ed448 (0x0808)
          rsa_pss_pss_sha256 (0x0809)
          rsa_pss_pss_sha384 (0x080a)
          rsa_pss_pss_sha512 (0x080b)
          rsa_pss_rsae_sha256 (0x0804)
          rsa_pss_rsae_sha384 (0x0805)
          rsa_pss_rsae_sha512 (0x0806)
          rsa_pkcs1_sha256 (0x0401)
          rsa_pkcs1_sha384 (0x0501)
          rsa_pkcs1_sha512 (0x0601)
          ecdsa_sha224 (0x0303)
          ecdsa_sha1 (0x0203)
          rsa_pkcs1_sha224 (0x0301)
          rsa_pkcs1_sha1 (0x0201)
          dsa_sha224 (0x0302)
          dsa_sha1 (0x0202)
          dsa_sha256 (0x0402)
          dsa_sha384 (0x0502)
          dsa_sha512 (0x0602)
        extension_type=supported_versions(43), length=9
          TLS 1.3 (772)
          TLS 1.2 (771)
          TLS 1.1 (770)
          TLS 1.0 (769)
        extension_type=psk_key_exchange_modes(45), length=2
          psk_dhe_ke (1)
        extension_type=key_share(51), length=38
            NamedGroup: ecdh_x25519 (29)
            key_exchange:  (len=32): 3E7E05E66F3F978082E7445E0A6FA9C73F4F4C1E6423AA3FAB7B80C8E521F629
        extension_type=padding(21), length=224
          0000 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          000f - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          001e - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          002d - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          003c - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          004b - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          005a - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0069 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0078 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0087 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0096 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          00a5 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          00b4 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          00c3 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          00d2 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00      ..............

Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 88
    ServerHello, Length=84
      server_version=0x303 (TLS 1.2)
      Random:
        gmt_unix_time=0xCF21AD74
        random_bytes (len=28): E59A6111BE1D8C021E65B891C2A211167ABB8C5E079E09E2C8A8339C
      session_id (len=32): E028F6D32F2F0FB8CC112794C7AA4E97AD76EDF6B955F49B51CA837F6115ABE2
      cipher_suite {0x13, 0x02} TLS_AES_256_GCM_SHA384
      compression_method: No Compression (0x00)
      extensions, length = 12
        extension_type=supported_versions(43), length=2
            TLS 1.3 (772)
        extension_type=key_share(51), length=2
            NamedGroup: secp256r1 (P-256) (23)

Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ChangeCipherSpec (20)
  Length = 1
    change_cipher_spec (1)

Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 512
    ClientHello, Length=508
      client_version=0x303 (TLS 1.2)
      Random:
        gmt_unix_time=0x2CE5293F
        random_bytes (len=28): 60F8FD89D6BFFC32D30870CF534B271108BD7E00452949D9E2CECD7D
      session_id (len=32): E028F6D32F2F0FB8CC112794C7AA4E97AD76EDF6B955F49B51CA837F6115ABE2
      cipher_suites (len=62)
        {0x13, 0x02} TLS_AES_256_GCM_SHA384
        {0x13, 0x03} TLS_CHACHA20_POLY1305_SHA256
        {0x13, 0x01} TLS_AES_128_GCM_SHA256
        {0xC0, 0x2C} TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
        {0xC0, 0x30} TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
        {0x00, 0x9F} TLS_DHE_RSA_WITH_AES_256_GCM_SHA384
        {0xCC, 0xA9} TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
        {0xCC, 0xA8} TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256
        {0xCC, 0xAA} TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256
        {0xC0, 0x2B} TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
        {0xC0, 0x2F} TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
        {0x00, 0x9E} TLS_DHE_RSA_WITH_AES_128_GCM_SHA256
        {0xC0, 0x24} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384
        {0xC0, 0x28} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
        {0x00, 0x6B} TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
        {0xC0, 0x23} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256
        {0xC0, 0x27} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
        {0x00, 0x67} TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
        {0xC0, 0x0A} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
        {0xC0, 0x14} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
        {0x00, 0x39} TLS_DHE_RSA_WITH_AES_256_CBC_SHA
        {0xC0, 0x09} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA
        {0xC0, 0x13} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0x33} TLS_DHE_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0x9D} TLS_RSA_WITH_AES_256_GCM_SHA384
        {0x00, 0x9C} TLS_RSA_WITH_AES_128_GCM_SHA256
        {0x00, 0x3D} TLS_RSA_WITH_AES_256_CBC_SHA256
        {0x00, 0x3C} TLS_RSA_WITH_AES_128_CBC_SHA256
        {0x00, 0x35} TLS_RSA_WITH_AES_256_CBC_SHA
        {0x00, 0x2F} TLS_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0xFF} TLS_EMPTY_RENEGOTIATION_INFO_SCSV
      compression_methods (len=1)
        No Compression (0x00)
      extensions, length = 373
        extension_type=ec_point_formats(11), length=4
          uncompressed (0)
          ansiX962_compressed_prime (1)
          ansiX962_compressed_char2 (2)
        extension_type=supported_groups(10), length=12
          ecdh_x25519 (29)
          secp256r1 (P-256) (23)
          ecdh_x448 (30)
          secp521r1 (P-521) (25)
          secp384r1 (P-384) (24)
        extension_type=encrypt_then_mac(22), length=0
        extension_type=extended_master_secret(23), length=0
        extension_type=signature_algorithms(13), length=48
          ecdsa_secp256r1_sha256 (0x0403)
          ecdsa_secp384r1_sha384 (0x0503)
          ecdsa_secp521r1_sha512 (0x0603)
          ed25519 (0x0807)
          ed448 (0x0808)
          rsa_pss_pss_sha256 (0x0809)
          rsa_pss_pss_sha384 (0x080a)
          rsa_pss_pss_sha512 (0x080b)
          rsa_pss_rsae_sha256 (0x0804)
          rsa_pss_rsae_sha384 (0x0805)
          rsa_pss_rsae_sha512 (0x0806)
          rsa_pkcs1_sha256 (0x0401)
          rsa_pkcs1_sha384 (0x0501)
          rsa_pkcs1_sha512 (0x0601)
          ecdsa_sha224 (0x0303)
          ecdsa_sha1 (0x0203)
          rsa_pkcs1_sha224 (0x0301)
          rsa_pkcs1_sha1 (0x0201)
          dsa_sha224 (0x0302)
          dsa_sha1 (0x0202)
          dsa_sha256 (0x0402)
          dsa_sha384 (0x0502)
          dsa_sha512 (0x0602)
        extension_type=supported_versions(43), length=9
          TLS 1.3 (772)
          TLS 1.2 (771)
          TLS 1.1 (770)
          TLS 1.0 (769)
        extension_type=psk_key_exchange_modes(45), length=2
          psk_dhe_ke (1)
        extension_type=key_share(51), length=71
            NamedGroup: secp256r1 (P-256) (23)
            key_exchange:  (len=65): 04942A4A721CA99765B0FBEF01CB5B79C88011CCCECE4B93FA082CF7DBD3992D4602BBAC27DF4355243FC4B33C801A989BEC3BB1E818262CED50B7448DAF4C65B1
        extension_type=padding(21), length=191
          0000 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          000f - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          001e - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          002d - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          003c - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          004b - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          005a - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0069 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0078 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0087 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0096 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          00a5 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          00b4 - 00 00 00 00 00 00 00 00-00 00 00               ...........

Received Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ChangeCipherSpec (20)
  Length = 1

------------------------------------------------------------
S8 server side:
Received Record
Header:
  Version = TLS 1.0 (0x301)
  Content Type = Handshake (22)
  Length = 512
    ClientHello, Length=508
      client_version=0x303 (TLS 1.2)
      Random:
        gmt_unix_time=0x2CE5293F
        random_bytes (len=28): 60F8FD89D6BFFC32D30870CF534B271108BD7E00452949D9E2CECD7D
      session_id (len=32): E028F6D32F2F0FB8CC112794C7AA4E97AD76EDF6B955F49B51CA837F6115ABE2
      cipher_suites (len=62)
        {0x13, 0x02} TLS_AES_256_GCM_SHA384
        {0x13, 0x03} TLS_CHACHA20_POLY1305_SHA256
        {0x13, 0x01} TLS_AES_128_GCM_SHA256
        {0xC0, 0x2C} TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
        {0xC0, 0x30} TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
        {0x00, 0x9F} TLS_DHE_RSA_WITH_AES_256_GCM_SHA384
        {0xCC, 0xA9} TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
        {0xCC, 0xA8} TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256
        {0xCC, 0xAA} TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256
        {0xC0, 0x2B} TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
        {0xC0, 0x2F} TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
        {0x00, 0x9E} TLS_DHE_RSA_WITH_AES_128_GCM_SHA256
        {0xC0, 0x24} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384
        {0xC0, 0x28} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
        {0x00, 0x6B} TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
        {0xC0, 0x23} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256
        {0xC0, 0x27} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
        {0x00, 0x67} TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
        {0xC0, 0x0A} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
        {0xC0, 0x14} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
        {0x00, 0x39} TLS_DHE_RSA_WITH_AES_256_CBC_SHA
        {0xC0, 0x09} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA
        {0xC0, 0x13} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0x33} TLS_DHE_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0x9D} TLS_RSA_WITH_AES_256_GCM_SHA384
        {0x00, 0x9C} TLS_RSA_WITH_AES_128_GCM_SHA256
        {0x00, 0x3D} TLS_RSA_WITH_AES_256_CBC_SHA256
        {0x00, 0x3C} TLS_RSA_WITH_AES_128_CBC_SHA256
        {0x00, 0x35} TLS_RSA_WITH_AES_256_CBC_SHA
        {0x00, 0x2F} TLS_RSA_WITH_AES_128_CBC_SHA
        {0x00, 0xFF} TLS_EMPTY_RENEGOTIATION_INFO_SCSV
      compression_methods (len=1)
        No Compression (0x00)
      extensions, length = 373
        extension_type=ec_point_formats(11), length=4
          uncompressed (0)
          ansiX962_compressed_prime (1)
          ansiX962_compressed_char2 (2)
        extension_type=supported_groups(10), length=12
          ecdh_x25519 (29)
          secp256r1 (P-256) (23)
          ecdh_x448 (30)
          secp521r1 (P-521) (25)
          secp384r1 (P-384) (24)
        extension_type=encrypt_then_mac(22), length=0
        extension_type=extended_master_secret(23), length=0
        extension_type=signature_algorithms(13), length=48
          ecdsa_secp256r1_sha256 (0x0403)
          ecdsa_secp384r1_sha384 (0x0503)
          ecdsa_secp521r1_sha512 (0x0603)
          ed25519 (0x0807)
          ed448 (0x0808)
          rsa_pss_pss_sha256 (0x0809)
          rsa_pss_pss_sha384 (0x080a)
          rsa_pss_pss_sha512 (0x080b)
          rsa_pss_rsae_sha256 (0x0804)
          rsa_pss_rsae_sha384 (0x0805)
          rsa_pss_rsae_sha512 (0x0806)
          rsa_pkcs1_sha256 (0x0401)
          rsa_pkcs1_sha384 (0x0501)
          rsa_pkcs1_sha512 (0x0601)
          ecdsa_sha224 (0x0303)
          ecdsa_sha1 (0x0203)
          rsa_pkcs1_sha224 (0x0301)
          rsa_pkcs1_sha1 (0x0201)
          dsa_sha224 (0x0302)
          dsa_sha1 (0x0202)
          dsa_sha256 (0x0402)
          dsa_sha384 (0x0502)
          dsa_sha512 (0x0602)
        extension_type=supported_versions(43), length=9
          TLS 1.3 (772)
          TLS 1.2 (771)
          TLS 1.1 (770)
          TLS 1.0 (769)
        extension_type=psk_key_exchange_modes(45), length=2
          psk_dhe_ke (1)
        extension_type=key_share(51), length=38
            NamedGroup: ecdh_x25519 (29)
            key_exchange:  (len=32): 3E7E05E66F3F978082E7445E0A6FA9C73F4F4C1E6423AA3FAB7B80C8E521F629
        extension_type=padding(21), length=224
          0000 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          000f - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          001e - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          002d - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          003c - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          004b - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          005a - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0069 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0078 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0087 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          0096 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          00a5 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          00b4 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          00c3 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
          00d2 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00      ..............

Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = Handshake (22)
  Length = 88
    ServerHello, Length=84
      server_version=0x303 (TLS 1.2)
      Random:
        gmt_unix_time=0xCF21AD74
        random_bytes (len=28): E59A6111BE1D8C021E65B891C2A211167ABB8C5E079E09E2C8A8339C
      session_id (len=32): E028F6D32F2F0FB8CC112794C7AA4E97AD76EDF6B955F49B51CA837F6115ABE2
      cipher_suite {0x13, 0x02} TLS_AES_256_GCM_SHA384
      compression_method: No Compression (0x00)
      extensions, length = 12
        extension_type=supported_versions(43), length=2
            TLS 1.3 (772)
        extension_type=key_share(51), length=2
            NamedGroup: secp256r1 (P-256) (23)

Sent Record
Header:
  Version = TLS 1.2 (0x303)
  Content Type = ChangeCipherSpec (20)
  Length = 1
    change_cipher_spec (1)


clt.m1.pcap (3K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Matt Caswell-2


On 19/05/2020 11:49, Claus Assmann wrote:
> On Mon, May 18, 2020, Viktor Dukhovni wrote:
>
>> I'll strongly second Matt's request for a PCAP file.
>
> If tcpdump is "good enough" then that should be attached.
> If wireshark and some TLS decoding is needed, then I need
> some time to figure that out.

The pcap file doesn't have the required info - however the SSL_trace
output gives the same kind of data, so that's good enough for now.


> I've added SSL_trace as suggested and the output is below.

Thanks that's useful.

> When I compare M1 with openssl s_client the main difference
> is that s_client has
> extension_type=padding
> but I don't see where/how M1 would turn that off (or where
> s_client turns it on?)

This shouldn't make any difference. I'd be very surprised if it was to
do with that.

From the trace output I can see that the client sends a ClientHello to
the server. The server responds with an HRR, and the client re-issues a
new ClientHello. So far so good. However, at this point the server
doesn't like something about the new ClientHello and fails.


In your original email you got this output from the info callback on the
server side:

> SSL_accept:error in TLSv1.3 early data

This comes from this code in the info callback which you lifted from s_cb.c:

    } else if (where & SSL_CB_EXIT) {
        if (ret == 0)
            BIO_printf(bio_err, "%s:failed in %s\n",
                       str, SSL_state_string_long(s));
        else if (ret < 0)
            BIO_printf(bio_err, "%s:error in %s\n",
                       str, SSL_state_string_long(s));
    }

Please could you modify this as follows:

@@ -481,6 +481,7 @@ void apps_ssl_info_callback(const SSL *s, int where,
int ret)
         else if (ret < 0)
             BIO_printf(bio_err, "%s:error in %s\n",
                        str, SSL_state_string_long(s));
+        ERR_print_errors(bio_err);
     }
 }


Now retry the handshake and send the output.

Thanks

Matt




>
> ------------------------------------------------------------
> M8 client side:
> Sent Record
> Header:
>   Version = TLS 1.0 (0x301)
>   Content Type = Handshake (22)
>   Length = 512
>     ClientHello, Length=508
>       client_version=0x303 (TLS 1.2)
>       Random:
>         gmt_unix_time=0x2CE5293F
>         random_bytes (len=28): 60F8FD89D6BFFC32D30870CF534B271108BD7E00452949D9E2CECD7D
>       session_id (len=32): E028F6D32F2F0FB8CC112794C7AA4E97AD76EDF6B955F49B51CA837F6115ABE2
>       cipher_suites (len=62)
>         {0x13, 0x02} TLS_AES_256_GCM_SHA384
>         {0x13, 0x03} TLS_CHACHA20_POLY1305_SHA256
>         {0x13, 0x01} TLS_AES_128_GCM_SHA256
>         {0xC0, 0x2C} TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
>         {0xC0, 0x30} TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
>         {0x00, 0x9F} TLS_DHE_RSA_WITH_AES_256_GCM_SHA384
>         {0xCC, 0xA9} TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
>         {0xCC, 0xA8} TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256
>         {0xCC, 0xAA} TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256
>         {0xC0, 0x2B} TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
>         {0xC0, 0x2F} TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
>         {0x00, 0x9E} TLS_DHE_RSA_WITH_AES_128_GCM_SHA256
>         {0xC0, 0x24} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384
>         {0xC0, 0x28} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
>         {0x00, 0x6B} TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
>         {0xC0, 0x23} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256
>         {0xC0, 0x27} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
>         {0x00, 0x67} TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
>         {0xC0, 0x0A} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
>         {0xC0, 0x14} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
>         {0x00, 0x39} TLS_DHE_RSA_WITH_AES_256_CBC_SHA
>         {0xC0, 0x09} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA
>         {0xC0, 0x13} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA
>         {0x00, 0x33} TLS_DHE_RSA_WITH_AES_128_CBC_SHA
>         {0x00, 0x9D} TLS_RSA_WITH_AES_256_GCM_SHA384
>         {0x00, 0x9C} TLS_RSA_WITH_AES_128_GCM_SHA256
>         {0x00, 0x3D} TLS_RSA_WITH_AES_256_CBC_SHA256
>         {0x00, 0x3C} TLS_RSA_WITH_AES_128_CBC_SHA256
>         {0x00, 0x35} TLS_RSA_WITH_AES_256_CBC_SHA
>         {0x00, 0x2F} TLS_RSA_WITH_AES_128_CBC_SHA
>         {0x00, 0xFF} TLS_EMPTY_RENEGOTIATION_INFO_SCSV
>       compression_methods (len=1)
>         No Compression (0x00)
>       extensions, length = 373
>         extension_type=ec_point_formats(11), length=4
>           uncompressed (0)
>           ansiX962_compressed_prime (1)
>           ansiX962_compressed_char2 (2)
>         extension_type=supported_groups(10), length=12
>           ecdh_x25519 (29)
>           secp256r1 (P-256) (23)
>           ecdh_x448 (30)
>           secp521r1 (P-521) (25)
>           secp384r1 (P-384) (24)
>         extension_type=encrypt_then_mac(22), length=0
>         extension_type=extended_master_secret(23), length=0
>         extension_type=signature_algorithms(13), length=48
>           ecdsa_secp256r1_sha256 (0x0403)
>           ecdsa_secp384r1_sha384 (0x0503)
>           ecdsa_secp521r1_sha512 (0x0603)
>           ed25519 (0x0807)
>           ed448 (0x0808)
>           rsa_pss_pss_sha256 (0x0809)
>           rsa_pss_pss_sha384 (0x080a)
>           rsa_pss_pss_sha512 (0x080b)
>           rsa_pss_rsae_sha256 (0x0804)
>           rsa_pss_rsae_sha384 (0x0805)
>           rsa_pss_rsae_sha512 (0x0806)
>           rsa_pkcs1_sha256 (0x0401)
>           rsa_pkcs1_sha384 (0x0501)
>           rsa_pkcs1_sha512 (0x0601)
>           ecdsa_sha224 (0x0303)
>           ecdsa_sha1 (0x0203)
>           rsa_pkcs1_sha224 (0x0301)
>           rsa_pkcs1_sha1 (0x0201)
>           dsa_sha224 (0x0302)
>           dsa_sha1 (0x0202)
>           dsa_sha256 (0x0402)
>           dsa_sha384 (0x0502)
>           dsa_sha512 (0x0602)
>         extension_type=supported_versions(43), length=9
>           TLS 1.3 (772)
>           TLS 1.2 (771)
>           TLS 1.1 (770)
>           TLS 1.0 (769)
>         extension_type=psk_key_exchange_modes(45), length=2
>           psk_dhe_ke (1)
>         extension_type=key_share(51), length=38
>             NamedGroup: ecdh_x25519 (29)
>             key_exchange:  (len=32): 3E7E05E66F3F978082E7445E0A6FA9C73F4F4C1E6423AA3FAB7B80C8E521F629
>         extension_type=padding(21), length=224
>           0000 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           000f - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           001e - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           002d - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           003c - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           004b - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           005a - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0069 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0078 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0087 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0096 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           00a5 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           00b4 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           00c3 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           00d2 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00      ..............
>
> Received Record
> Header:
>   Version = TLS 1.2 (0x303)
>   Content Type = Handshake (22)
>   Length = 88
>     ServerHello, Length=84
>       server_version=0x303 (TLS 1.2)
>       Random:
>         gmt_unix_time=0xCF21AD74
>         random_bytes (len=28): E59A6111BE1D8C021E65B891C2A211167ABB8C5E079E09E2C8A8339C
>       session_id (len=32): E028F6D32F2F0FB8CC112794C7AA4E97AD76EDF6B955F49B51CA837F6115ABE2
>       cipher_suite {0x13, 0x02} TLS_AES_256_GCM_SHA384
>       compression_method: No Compression (0x00)
>       extensions, length = 12
>         extension_type=supported_versions(43), length=2
>             TLS 1.3 (772)
>         extension_type=key_share(51), length=2
>             NamedGroup: secp256r1 (P-256) (23)
>
> Sent Record
> Header:
>   Version = TLS 1.2 (0x303)
>   Content Type = ChangeCipherSpec (20)
>   Length = 1
>     change_cipher_spec (1)
>
> Sent Record
> Header:
>   Version = TLS 1.2 (0x303)
>   Content Type = Handshake (22)
>   Length = 512
>     ClientHello, Length=508
>       client_version=0x303 (TLS 1.2)
>       Random:
>         gmt_unix_time=0x2CE5293F
>         random_bytes (len=28): 60F8FD89D6BFFC32D30870CF534B271108BD7E00452949D9E2CECD7D
>       session_id (len=32): E028F6D32F2F0FB8CC112794C7AA4E97AD76EDF6B955F49B51CA837F6115ABE2
>       cipher_suites (len=62)
>         {0x13, 0x02} TLS_AES_256_GCM_SHA384
>         {0x13, 0x03} TLS_CHACHA20_POLY1305_SHA256
>         {0x13, 0x01} TLS_AES_128_GCM_SHA256
>         {0xC0, 0x2C} TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
>         {0xC0, 0x30} TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
>         {0x00, 0x9F} TLS_DHE_RSA_WITH_AES_256_GCM_SHA384
>         {0xCC, 0xA9} TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
>         {0xCC, 0xA8} TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256
>         {0xCC, 0xAA} TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256
>         {0xC0, 0x2B} TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
>         {0xC0, 0x2F} TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
>         {0x00, 0x9E} TLS_DHE_RSA_WITH_AES_128_GCM_SHA256
>         {0xC0, 0x24} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384
>         {0xC0, 0x28} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
>         {0x00, 0x6B} TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
>         {0xC0, 0x23} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256
>         {0xC0, 0x27} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
>         {0x00, 0x67} TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
>         {0xC0, 0x0A} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
>         {0xC0, 0x14} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
>         {0x00, 0x39} TLS_DHE_RSA_WITH_AES_256_CBC_SHA
>         {0xC0, 0x09} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA
>         {0xC0, 0x13} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA
>         {0x00, 0x33} TLS_DHE_RSA_WITH_AES_128_CBC_SHA
>         {0x00, 0x9D} TLS_RSA_WITH_AES_256_GCM_SHA384
>         {0x00, 0x9C} TLS_RSA_WITH_AES_128_GCM_SHA256
>         {0x00, 0x3D} TLS_RSA_WITH_AES_256_CBC_SHA256
>         {0x00, 0x3C} TLS_RSA_WITH_AES_128_CBC_SHA256
>         {0x00, 0x35} TLS_RSA_WITH_AES_256_CBC_SHA
>         {0x00, 0x2F} TLS_RSA_WITH_AES_128_CBC_SHA
>         {0x00, 0xFF} TLS_EMPTY_RENEGOTIATION_INFO_SCSV
>       compression_methods (len=1)
>         No Compression (0x00)
>       extensions, length = 373
>         extension_type=ec_point_formats(11), length=4
>           uncompressed (0)
>           ansiX962_compressed_prime (1)
>           ansiX962_compressed_char2 (2)
>         extension_type=supported_groups(10), length=12
>           ecdh_x25519 (29)
>           secp256r1 (P-256) (23)
>           ecdh_x448 (30)
>           secp521r1 (P-521) (25)
>           secp384r1 (P-384) (24)
>         extension_type=encrypt_then_mac(22), length=0
>         extension_type=extended_master_secret(23), length=0
>         extension_type=signature_algorithms(13), length=48
>           ecdsa_secp256r1_sha256 (0x0403)
>           ecdsa_secp384r1_sha384 (0x0503)
>           ecdsa_secp521r1_sha512 (0x0603)
>           ed25519 (0x0807)
>           ed448 (0x0808)
>           rsa_pss_pss_sha256 (0x0809)
>           rsa_pss_pss_sha384 (0x080a)
>           rsa_pss_pss_sha512 (0x080b)
>           rsa_pss_rsae_sha256 (0x0804)
>           rsa_pss_rsae_sha384 (0x0805)
>           rsa_pss_rsae_sha512 (0x0806)
>           rsa_pkcs1_sha256 (0x0401)
>           rsa_pkcs1_sha384 (0x0501)
>           rsa_pkcs1_sha512 (0x0601)
>           ecdsa_sha224 (0x0303)
>           ecdsa_sha1 (0x0203)
>           rsa_pkcs1_sha224 (0x0301)
>           rsa_pkcs1_sha1 (0x0201)
>           dsa_sha224 (0x0302)
>           dsa_sha1 (0x0202)
>           dsa_sha256 (0x0402)
>           dsa_sha384 (0x0502)
>           dsa_sha512 (0x0602)
>         extension_type=supported_versions(43), length=9
>           TLS 1.3 (772)
>           TLS 1.2 (771)
>           TLS 1.1 (770)
>           TLS 1.0 (769)
>         extension_type=psk_key_exchange_modes(45), length=2
>           psk_dhe_ke (1)
>         extension_type=key_share(51), length=71
>             NamedGroup: secp256r1 (P-256) (23)
>             key_exchange:  (len=65): 04942A4A721CA99765B0FBEF01CB5B79C88011CCCECE4B93FA082CF7DBD3992D4602BBAC27DF4355243FC4B33C801A989BEC3BB1E818262CED50B7448DAF4C65B1
>         extension_type=padding(21), length=191
>           0000 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           000f - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           001e - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           002d - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           003c - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           004b - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           005a - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0069 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0078 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0087 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0096 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           00a5 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           00b4 - 00 00 00 00 00 00 00 00-00 00 00               ...........
>
> Received Record
> Header:
>   Version = TLS 1.2 (0x303)
>   Content Type = ChangeCipherSpec (20)
>   Length = 1
>
> ------------------------------------------------------------
> S8 server side:
> Received Record
> Header:
>   Version = TLS 1.0 (0x301)
>   Content Type = Handshake (22)
>   Length = 512
>     ClientHello, Length=508
>       client_version=0x303 (TLS 1.2)
>       Random:
>         gmt_unix_time=0x2CE5293F
>         random_bytes (len=28): 60F8FD89D6BFFC32D30870CF534B271108BD7E00452949D9E2CECD7D
>       session_id (len=32): E028F6D32F2F0FB8CC112794C7AA4E97AD76EDF6B955F49B51CA837F6115ABE2
>       cipher_suites (len=62)
>         {0x13, 0x02} TLS_AES_256_GCM_SHA384
>         {0x13, 0x03} TLS_CHACHA20_POLY1305_SHA256
>         {0x13, 0x01} TLS_AES_128_GCM_SHA256
>         {0xC0, 0x2C} TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
>         {0xC0, 0x30} TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
>         {0x00, 0x9F} TLS_DHE_RSA_WITH_AES_256_GCM_SHA384
>         {0xCC, 0xA9} TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256
>         {0xCC, 0xA8} TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256
>         {0xCC, 0xAA} TLS_DHE_RSA_WITH_CHACHA20_POLY1305_SHA256
>         {0xC0, 0x2B} TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
>         {0xC0, 0x2F} TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
>         {0x00, 0x9E} TLS_DHE_RSA_WITH_AES_128_GCM_SHA256
>         {0xC0, 0x24} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384
>         {0xC0, 0x28} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
>         {0x00, 0x6B} TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
>         {0xC0, 0x23} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256
>         {0xC0, 0x27} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
>         {0x00, 0x67} TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
>         {0xC0, 0x0A} TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA
>         {0xC0, 0x14} TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA
>         {0x00, 0x39} TLS_DHE_RSA_WITH_AES_256_CBC_SHA
>         {0xC0, 0x09} TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA
>         {0xC0, 0x13} TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA
>         {0x00, 0x33} TLS_DHE_RSA_WITH_AES_128_CBC_SHA
>         {0x00, 0x9D} TLS_RSA_WITH_AES_256_GCM_SHA384
>         {0x00, 0x9C} TLS_RSA_WITH_AES_128_GCM_SHA256
>         {0x00, 0x3D} TLS_RSA_WITH_AES_256_CBC_SHA256
>         {0x00, 0x3C} TLS_RSA_WITH_AES_128_CBC_SHA256
>         {0x00, 0x35} TLS_RSA_WITH_AES_256_CBC_SHA
>         {0x00, 0x2F} TLS_RSA_WITH_AES_128_CBC_SHA
>         {0x00, 0xFF} TLS_EMPTY_RENEGOTIATION_INFO_SCSV
>       compression_methods (len=1)
>         No Compression (0x00)
>       extensions, length = 373
>         extension_type=ec_point_formats(11), length=4
>           uncompressed (0)
>           ansiX962_compressed_prime (1)
>           ansiX962_compressed_char2 (2)
>         extension_type=supported_groups(10), length=12
>           ecdh_x25519 (29)
>           secp256r1 (P-256) (23)
>           ecdh_x448 (30)
>           secp521r1 (P-521) (25)
>           secp384r1 (P-384) (24)
>         extension_type=encrypt_then_mac(22), length=0
>         extension_type=extended_master_secret(23), length=0
>         extension_type=signature_algorithms(13), length=48
>           ecdsa_secp256r1_sha256 (0x0403)
>           ecdsa_secp384r1_sha384 (0x0503)
>           ecdsa_secp521r1_sha512 (0x0603)
>           ed25519 (0x0807)
>           ed448 (0x0808)
>           rsa_pss_pss_sha256 (0x0809)
>           rsa_pss_pss_sha384 (0x080a)
>           rsa_pss_pss_sha512 (0x080b)
>           rsa_pss_rsae_sha256 (0x0804)
>           rsa_pss_rsae_sha384 (0x0805)
>           rsa_pss_rsae_sha512 (0x0806)
>           rsa_pkcs1_sha256 (0x0401)
>           rsa_pkcs1_sha384 (0x0501)
>           rsa_pkcs1_sha512 (0x0601)
>           ecdsa_sha224 (0x0303)
>           ecdsa_sha1 (0x0203)
>           rsa_pkcs1_sha224 (0x0301)
>           rsa_pkcs1_sha1 (0x0201)
>           dsa_sha224 (0x0302)
>           dsa_sha1 (0x0202)
>           dsa_sha256 (0x0402)
>           dsa_sha384 (0x0502)
>           dsa_sha512 (0x0602)
>         extension_type=supported_versions(43), length=9
>           TLS 1.3 (772)
>           TLS 1.2 (771)
>           TLS 1.1 (770)
>           TLS 1.0 (769)
>         extension_type=psk_key_exchange_modes(45), length=2
>           psk_dhe_ke (1)
>         extension_type=key_share(51), length=38
>             NamedGroup: ecdh_x25519 (29)
>             key_exchange:  (len=32): 3E7E05E66F3F978082E7445E0A6FA9C73F4F4C1E6423AA3FAB7B80C8E521F629
>         extension_type=padding(21), length=224
>           0000 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           000f - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           001e - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           002d - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           003c - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           004b - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           005a - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0069 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0078 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0087 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           0096 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           00a5 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           00b4 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           00c3 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00   ...............
>           00d2 - 00 00 00 00 00 00 00 00-00 00 00 00 00 00      ..............
>
> Sent Record
> Header:
>   Version = TLS 1.2 (0x303)
>   Content Type = Handshake (22)
>   Length = 88
>     ServerHello, Length=84
>       server_version=0x303 (TLS 1.2)
>       Random:
>         gmt_unix_time=0xCF21AD74
>         random_bytes (len=28): E59A6111BE1D8C021E65B891C2A211167ABB8C5E079E09E2C8A8339C
>       session_id (len=32): E028F6D32F2F0FB8CC112794C7AA4E97AD76EDF6B955F49B51CA837F6115ABE2
>       cipher_suite {0x13, 0x02} TLS_AES_256_GCM_SHA384
>       compression_method: No Compression (0x00)
>       extensions, length = 12
>         extension_type=supported_versions(43), length=2
>             TLS 1.3 (772)
>         extension_type=key_share(51), length=2
>             NamedGroup: secp256r1 (P-256) (23)
>
> Sent Record
> Header:
>   Version = TLS 1.2 (0x303)
>   Content Type = ChangeCipherSpec (20)
>   Length = 1
>     change_cipher_spec (1)
>
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Claus Assmann
On Tue, May 19, 2020, Matt Caswell wrote:

> > SSL_accept:error in TLSv1.3 early data

> This comes from this code in the info callback which you lifted from s_cb.c:

> Please could you modify this as follows:

> +        ERR_print_errors(bio_err);

That's basically already in the code:
while ((l = ERR_get_error_line_data((const char **) &file, &line,
                    (const char **) &data, &flags)) != 0)
  log it ...
but that does not generate any output. Even if I add
the line you suggested there's no extra output
(to make sure there would be something I also added
an BIO_fprintf() and that output is shown, so it's not
a problem with the BIO).

I guess I have to figure out how to use wireshark for this.
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Matt Caswell-2


On 19/05/2020 15:56, Claus Assmann wrote:

> That's basically already in the code:
> while ((l = ERR_get_error_line_data((const char **) &file, &line,
>    (const char **) &data, &flags)) != 0)
>   log it ...
> but that does not generate any output. Even if I add
> the line you suggested there's no extra output
> (to make sure there would be something I also added
> an BIO_fprintf() and that output is shown, so it's not
> a problem with the BIO).
>
> I guess I have to figure out how to use wireshark for this.
>

I doubt wireshark will tell you much more than the SSL_trace output
(although it is possible that it could).

After you see this on the server side:

SSL_accept:TLSv1.3 early data
info_callback where=0x2002, ret=-1
SSL_accept:error in TLSv1.3 early data


What happens in the application code? What was the function being called
(SSL_accept?) and what return value do you get? What does
SSL_get_error() return at this point?

Matt
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Claus Assmann
On Wed, May 20, 2020, Matt Caswell wrote:

> SSL_accept:TLSv1.3 early data

> What happens in the application code? What was the function being called
> (SSL_accept?) and what return value do you get? What does
> SSL_get_error() return at this point?

It's:
        r = SSL_accept(srv_ssl);
        if (r <= 0)
                ssl_err = SSL_get_error(srv_ssl, r);

return value=-1
ssl_err=5 SSL_ERROR_SYSCALL
errno=0

It seems to me server and client get "out of sync" at the I/O layer
if I understand the SSL traces correctly:

S8: sends 2 records at the end:
  - handshake
  - ChangeCipherSpec

M1: receives
  handshake
  but seemingly not
  ChangeCipherSpec
  Instead it sends only its own
  ChangeCipherSpec
  then its handshake again
  and only then it receives ChangeCipherSpec

and S8 seemingly tries to interprete the out-of-sync data as TLSv1.3
early data and fails, thus returning an error from SSL_accept().

If that analysis is correct (can someone check please?), then I
need to look at the I/O layers of both programs -- they are rather
different :-(
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Matt Caswell-2


On 20/05/2020 13:44, Claus Assmann wrote:

> On Wed, May 20, 2020, Matt Caswell wrote:
>
>> SSL_accept:TLSv1.3 early data
>
>> What happens in the application code? What was the function being called
>> (SSL_accept?) and what return value do you get? What does
>> SSL_get_error() return at this point?
>
> It's:
> r = SSL_accept(srv_ssl);
> if (r <= 0)
> ssl_err = SSL_get_error(srv_ssl, r);
>
> return value=-1
> ssl_err=5 SSL_ERROR_SYSCALL
> errno=0
>
> It seems to me server and client get "out of sync" at the I/O layer
> if I understand the SSL traces correctly:
>
> S8: sends 2 records at the end:
>   - handshake
>   - ChangeCipherSpec
>
> M1: receives
>   handshake
>   but seemingly not
>   ChangeCipherSpec
>   Instead it sends only its own
>   ChangeCipherSpec
>   then its handshake again
>   and only then it receives ChangeCipherSpec
>
> and S8 seemingly tries to interprete the out-of-sync data as TLSv1.3
> early data and fails, thus returning an error from SSL_accept().
>
> If that analysis is correct (can someone check please?), then I
> need to look at the I/O layers of both programs -- they are rather
> different :-(
>

The "early data" here is a red herring. It is normal for the internal
libssl state machine to (briefly) transition through the "early data"
state even though there is no early data being sent. In this case the
early data state is the last state that occurs after having written
change cipher spec, but before reading the second Client Hello following
an HRR.

I *think* what is happening here is that the server side state machine
has finished its writing tasks, and is now attempting to read data from
the client again (i.e. the 2nd ClientHello). Normally what would happen
at this point is that it would read the header of the next record that
is received from the client to check that the message type it has
received is sane. It is expecting the ClientHello message type, and only
at that point will it move the state machine on from the "early data"
state into the "SSLv3/TLS read client hello" state.

For some reason it is experiencing a failure while reading the client
hello from the client. Therefore it never makes the state transition out
of the "early data" state.

The SSL_ERROR_SYSCALL return suggests to me that the underlying system
call to read the data has failed for some reason. However errno being 0
indicates otherwise. There is actually a known scenario in 1.1.1 where
this can occur: if EOF is unexpectedly encountered on the socket. We
briefly fixed this (you should never normally get SSL_ERROR_SYSCALL with
errno == 0) but had to back the fix out because it broke some
applications which were written to expect this buggy behaviour.

I wonder if there could be some middlebox in between these two peers
that is interfering with the connection in some way and arbitrarily
closing it down?

Matt

Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Claus Assmann
On Wed, May 20, 2020, Matt Caswell wrote:

> I wonder if there could be some middlebox in between these two peers
> that is interfering with the connection in some way and arbitrarily
> closing it down?

No, it's being tested on localhost.  And it works fine if I use a
different server (e.g., openssl s_server) or a different client,
i.e., it is (so far) only this specific combination (M1 -> S8)
which does not work.
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Matt Caswell-2


On 20/05/2020 14:24, Claus Assmann wrote:

> On Wed, May 20, 2020, Matt Caswell wrote:
>
>> I wonder if there could be some middlebox in between these two peers
>> that is interfering with the connection in some way and arbitrarily
>> closing it down?
>
> No, it's being tested on localhost.  And it works fine if I use a
> different server (e.g., openssl s_server) or a different client,
> i.e., it is (so far) only this specific combination (M1 -> S8)
> which does not work.
>

Can you test the underlying socket to see if it has been closed down in
an orderly way (i.e. recv() should return 0 on the socket if so)? That
would confirm or deny the EOF theory.

Matt
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Claus Assmann
On Wed, May 20, 2020, Matt Caswell wrote:

[Thanks for still helping me with this!]

> Can you test the underlying socket to see if it has been closed down in
> an orderly way (i.e. recv() should return 0 on the socket if so)? That

Yes, that what happens.

So I added some debugging to the client and it shows:

SSL info:
read server hello
write change cipher spec
write client hello

and I/O layer (only last/relevant part):
want_write=523, want_read=5
... write ... and then
want_read=5 -< read=OK, num_read=5
want_write=0, want_read=1
want_read=1 -> read=OK, num_read=1
want_write=0, want_read=5
want_read=5 -> read=TIMEOUT, num_read=0

Explanation:
want_write = BIO_ctrl_pending(network_bio)
want_read = BIO_ctrl_get_read_request(network_bio)

I didn't instrument the write part, only the read part.
want_read>0 -> invoke read, check result:  read=STATUS, num_read=N
So the last read does not get the data the library wants,
and hence the client fails and closes the connection.
In that moment the server fails in SSL_accept and issues
the misleading error message.

Now the question seems to be:
did the server actually not send the data (not sure how to check
that, maybe looking at tcpdump?)
or has the client a bug not reading the data?
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Matt Caswell-2


On 20/05/2020 17:52, Claus Assmann wrote:

> On Wed, May 20, 2020, Matt Caswell wrote:
>
> [Thanks for still helping me with this!]
>
>> Can you test the underlying socket to see if it has been closed down in
>> an orderly way (i.e. recv() should return 0 on the socket if so)? That
>
> Yes, that what happens.
>
> So I added some debugging to the client and it shows:
>
> SSL info:
> read server hello
> write change cipher spec
> write client hello

So the client has written the first clientHello, read the serverhello,
and then written the CCS and 2nd clientHello. The next thing it will
expect to do is read the serverhello again.

>
> and I/O layer (only last/relevant part):
> want_write=523, want_read=5
> ... write ... and then
> want_read=5 -< read=OK, num_read=5
> want_write=0, want_read=1
> want_read=1 -> read=OK, num_read=1
> want_write=0, want_read=5
> want_read=5 -> read=TIMEOUT, num_read=0

So presumably this is an attempt to read the header data of the next
message (a TLS record header is 5 bytes in length), i.e. the next
ServerHello. But we already know from your earlier analysis that this is
never going to come because the server has already given up before it
gets that far.


>
> Explanation:
> want_write = BIO_ctrl_pending(network_bio)
> want_read = BIO_ctrl_get_read_request(network_bio)
>
> I didn't instrument the write part, only the read part.
> want_read>0 -> invoke read, check result:  read=STATUS, num_read=N
> So the last read does not get the data the library wants,
> and hence the client fails and closes the connection.

This sounds odd. Why does the client fail because it hasn't read the
expected data yet? Normally (with non-blocking sockets), a failure to
read the expected data will result in SSL_get_error() returning
SSL_ERROR_WANT_READ - indicating that the data is not currently
available and we should retry again later. That isn't a fatal error, so
the connection should not be closed.

So - when you say the client fails - what exactly happens? What does
SSL_get_error() return at that point?

Matt
Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Viktor Dukhovni
On Wed, May 20, 2020 at 09:21:25PM +0100, Matt Caswell wrote:

> > Explanation:
> > want_write = BIO_ctrl_pending(network_bio)
> > want_read = BIO_ctrl_get_read_request(network_bio)
> >
> > I didn't instrument the write part, only the read part.
> > want_read>0 -> invoke read, check result:  read=STATUS, num_read=N
> > So the last read does not get the data the library wants,
> > and hence the client fails and closes the connection.
>
> This sounds odd. Why does the client fail because it hasn't read the
> expected data yet? Normally (with non-blocking sockets), a failure to
> read the expected data will result in SSL_get_error() returning
> SSL_ERROR_WANT_READ - indicating that the data is not currently
> available and we should retry again later. That isn't a fatal error, so
> the connection should not be closed.
>
> So - when you say the client fails - what exactly happens? What does
> SSL_get_error() return at that point?

Speaking of which, I've recently discovered (a documented interface
landmine) that:

    status = SSL_read(ssl, ...);
    err = SSL_get_error(ssl, status);

is an anti-pattern, because the "correct" usage is:

    ERR_clear_error();
    status = SSL_read(ssl, ...);
    err = SSL_get_error(ssl, status);

without ERR_clear_error(), SSL_get_error() can randomly indicate false
positive connection failures, depending on what's left over on the
error stack:

    http://postfix.1071664.n5.nabble.com/quot-SSL-Shutdown-shutdown-while-in-init-quot-while-sending-and-receiving-td105822.html

My take is that this is a sufficiently nasty problem to warrant some
changes in SSL_read(), SSL_write, SSL_accept(), ... to internally
memoize the error status before returning, in a manner that does not
depend on the prior state of the error stack, and that then
SSL_get_error() must look only at the given (SSL *) handle and
not at the error stack.

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

Re: How to debug a TLSv1.3 protocol problem?

Matt Caswell-2


On 20/05/2020 21:36, Viktor Dukhovni wrote:
> My take is that this is a sufficiently nasty problem to warrant some
> changes in SSL_read(), SSL_write, SSL_accept(), ... to internally
> memoize the error status before returning, in a manner that does not
> depend on the prior state of the error stack, and that then
> SSL_get_error() must look only at the given (SSL *) handle and
> not at the error stack.

We actually have always cleared the error stack on entering the libssl
state machine. It appears we don't do that on IO functions that don't
enter the state  machine (such as SSL_read()/SSL_write()).

Matt

Reply | Threaded
Open this post in threaded view
|

Re: How to debug a TLSv1.3 protocol problem?

Viktor Dukhovni
On Wed, May 20, 2020 at 09:40:35PM +0100, Matt Caswell wrote:

> On 20/05/2020 21:36, Viktor Dukhovni wrote:
> > My take is that this is a sufficiently nasty problem to warrant some
> > changes in SSL_read(), SSL_write, SSL_accept(), ... to internally
> > memoize the error status before returning, in a manner that does not
> > depend on the prior state of the error stack, and that then
> > SSL_get_error() must look only at the given (SSL *) handle and
> > not at the error stack.
>
> We actually have always cleared the error stack on entering the libssl
> state machine. It appears we don't do that on IO functions that don't
> enter the state  machine (such as SSL_read()/SSL_write()).

Glad to hear that at least handshakes are less prone to unexpected
issues of that sort.  I'd be interested to hear your thoughts (perhaps a
separate thread) on what to do about SSL_read() and SSL_write().

In the mean-time, if Clauss is trying to complete a handshake, rather
than move data, his issue is then likely something different?

--
    Viktor.
12