'TLS Unknown' message during negotiation for TLSv1.3

[iz8mbw]

Running curl 7.59.0 on Linux built from source with OpenSSL openssl v1.1.1-pre2 and Nghttp2 nghttp2 v1.31.0.

curl -V

root@server:~# curl -V
curl 7.59.0 (armv7l-unknown-linux-gnueabihf) libcurl/7.59.0 OpenSSL/1.1.1 zlib/1.2.11 libidn2/2.0.4 nghttp2/1.31.0 librtmp/2.3
Release-Date: 2018-03-14
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp smb smbs smtp smtps telnet tftp
Features: AsynchDNS Debug TrackMemory IDN Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy

When curl on a HTTPS TLS1.3 website, during negotiation, there are various "TLS Unknown" (IN or OUT).
See here:

root@server:/usr/local/lib# curl https://blog.cloudflare.com/ -v
* STATE: INIT => CONNECT handle 0x200e758; line 1404 (connection #-5000)
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => WAITRESOLVE handle 0x200e758; line 1440 (connection #0)
*   Trying 190.93.244.35...
* TCP_NODELAY set
* STATE: WAITRESOLVE => WAITCONNECT handle 0x200e758; line 1521 (connection #0)
* Connected to blog.cloudflare.com (190.93.244.35) port 443 (#0)
* STATE: WAITCONNECT => SENDPROTOCONNECT handle 0x200e758; line 1573 (connection #0)
* Marked for [keep alive]: HTTP default
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
  CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* STATE: SENDPROTOCONNECT => PROTOCONNECT handle 0x200e758; line 1587 (connection #0)
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Unknown (8):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Client hello (1):
* TLSv1.3 (OUT), TLS Unknown, Certificate Status (22):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS13-AES-256-GCM-SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: OU=Domain Control Validated; OU=PositiveSSL Multi-Domain; CN=blog.cloudflare.com
*  start date: Jun  1 00:00:00 2017 GMT
*  expire date: Jun  1 23:59:59 2018 GMT
*  subjectAltName: host "blog.cloudflare.com" matched cert's "blog.cloudflare.com"
*  issuer: C=GB; ST=Greater Manchester; L=Salford; O=COMODO CA Limited; CN=COMODO ECC Domain Validation Secure Server CA 2
*  SSL certificate verify ok.
* STATE: PROTOCONNECT => DO handle 0x200e758; line 1608 (connection #0)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* Using Stream ID: 1 (easy handle 0x200e758)
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
> GET / HTTP/2
> Host: blog.cloudflare.com
> User-Agent: curl/7.59.0
> Accept: */*
>
* STATE: DO => DO_DONE handle 0x200e758; line 1670 (connection #0)
* multi changed, check CONNECT_PEND queue!
* STATE: DO_DONE => WAITPERFORM handle 0x200e758; line 1795 (connection #0)
* STATE: WAITPERFORM => PERFORM handle 0x200e758; line 1811 (connection #0)
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS Unknown, Certificate Status (22):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
* Connection state changed (MAX_CONCURRENT_STREAMS == 128)!
* TLSv1.3 (OUT), TLS Unknown, Unknown (23):
* multi changed, check CONNECT_PEND queue!
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
* TLSv1.3 (IN), TLS Unknown, Unknown (23):
* HTTP/2 found, allow multiplexing
< HTTP/2 200
< date: Mon, 19 Mar 2018 16:09:26 GMT
< content-type: text/html; charset=utf-8
< content-length: 26123
< set-cookie: __cfduid=d84d147f8cd629fd762b5171b2b6989c21521475766; expires=Tue, 19-Mar-19 16:09:26 GMT; path=/; domain=.blog.cloudflare.com; HttpOnly
< cache-control: public, max-age=0
< cf-railgun: 3811b32861 0.01 0.005419 0030 e6be
< last-modified: Mon, 19 Mar 2018 16:03:00 GMT
< status: 200 OK
< vary: Accept-Encoding
< x-ghost-cache-status: From Cache
< x-powered-by: Express,Phusion Passenger 5.1.12
< x-request-id: d82d9344cf4d7e6fc08387272e7a8d8d
< expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
< server: cloudflare
< cf-ray: 3fe13412adc64340-MXP
<

The curl connection is OK but why these "TLS Unknown" message?

"TLS Unknown" is not present for TLSv1.2, see here the same curl with TLSv1.2:

root@server:~# curl https://blog.cloudflare.com/ --tlsv1.2 -v
* STATE: INIT => CONNECT handle 0xaf3758; line 1404 (connection #-5000)
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => WAITRESOLVE handle 0xaf3758; line 1440 (connection #0)
*   Trying 141.101.115.35...
* TCP_NODELAY set
* STATE: WAITRESOLVE => WAITCONNECT handle 0xaf3758; line 1521 (connection #0)
* Connected to blog.cloudflare.com (141.101.115.35) port 443 (#0)
* STATE: WAITCONNECT => SENDPROTOCONNECT handle 0xaf3758; line 1573 (connection #0)
* Marked for [keep alive]: HTTP default
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
  CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* STATE: SENDPROTOCONNECT => PROTOCONNECT handle 0xaf3758; line 1587 (connection #0)
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-ECDSA-CHACHA20-POLY1305
* ALPN, server accepted to use h2
* Server certificate:
*  subject: OU=Domain Control Validated; OU=PositiveSSL Multi-Domain; CN=blog.cloudflare.com
*  start date: Jun  1 00:00:00 2017 GMT
*  expire date: Jun  1 23:59:59 2018 GMT
*  subjectAltName: host "blog.cloudflare.com" matched cert's "blog.cloudflare.com"
*  issuer: C=GB; ST=Greater Manchester; L=Salford; O=COMODO CA Limited; CN=COMODO ECC Domain Validation Secure Server CA 2
*  SSL certificate verify ok.
* STATE: PROTOCONNECT => DO handle 0xaf3758; line 1608 (connection #0)
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0xaf3758)
> GET / HTTP/2
> Host: blog.cloudflare.com
> User-Agent: curl/7.59.0
> Accept: */*
>
* STATE: DO => DO_DONE handle 0xaf3758; line 1670 (connection #0)
* multi changed, check CONNECT_PEND queue!
* STATE: DO_DONE => WAITPERFORM handle 0xaf3758; line 1795 (connection #0)
* STATE: WAITPERFORM => PERFORM handle 0xaf3758; line 1811 (connection #0)
* Connection state changed (MAX_CONCURRENT_STREAMS == 128)!
* multi changed, check CONNECT_PEND queue!
* HTTP/2 found, allow multiplexing
< HTTP/2 200
< date: Mon, 19 Mar 2018 16:19:39 GMT
< content-type: text/html; charset=utf-8
< set-cookie: __cfduid=d23150d522ca97b8420c3156d3297e37e1521476379; expires=Tue, 19-Mar-19 16:19:39 GMT; path=/; domain=.blog.cloudflare.com; HttpOnly
< cache-control: public, max-age=0
< cf-railgun: direct (starting new WAN connection)
< last-modified: Mon, 19 Mar 2018 16:03:00 GMT
< status: 200 OK
< vary: Accept-Encoding
< x-ghost-cache-status: From Cache
< x-powered-by: Express,Phusion Passenger 5.1.12
< x-request-id: 9c528365ecf1433e80092af02e842133
< expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
< server: cloudflare
< cf-ray: 3fe1430beae50e06-MXP
<

[jay]

The content type is 257 (0x101) which is include/openssl/ssl3.h:# define SSL3_RT_INNER_CONTENT_TYPE 0x101

According to SSL_CTX_set_msg_callback doc the content type is the first byte in buf in that case.

The patch below helps for the handshake bit but it's still missing something because 23 shows as * TLSv1.3 (IN), TLS app data, Unknown (23):

diff --git a/lib/vtls/openssl.c b/lib/vtls/openssl.c
index 0d7baca..2c3e0d8 100644
--- a/lib/vtls/openssl.c
+++ b/lib/vtls/openssl.c
@@ -1818,8 +1818,15 @@ static void ssl_tls_trace(int direction, int ssl_ver, int content_type,
      * always pass-up content-type as 0. But the interesting message-type
      * is at 'buf[0]'.
      */
-    if(ssl_ver == SSL3_VERSION_MAJOR && content_type)
-      tls_rt_name = tls_rt_type(content_type);
+    if(ssl_ver == SSL3_VERSION_MAJOR && content_type) {
+#if (OPENSSL_VERSION_NUMBER >= 0x10100000L) && /* OpenSSL 1.1.0+ */ \
+  !defined(LIBRESSL_VERSION_NUMBER)
+      if(content_type == SSL3_RT_INNER_CONTENT_TYPE && len == 1)
+        tls_rt_name = tls_rt_type(*(unsigned char *)buf);
+      else
+#endif
+        tls_rt_name = tls_rt_type(content_type);
+    }
     else
       tls_rt_name = "";
 

[jay]

next draft in master...jay:fix_ossl111_trace

in the case of SSL3_RT_INNER_CONTENT_TYPE there's only one byte which is actually the content type. in that case rather than show for example * TLSv1.3 (IN), TLS handshake, (0): I changed it to * TLSv1.3 (IN), TLS handshake but doing that added a lot of crud because I appended via snprintf and checked that return value for -1. does house snprintf need such a check? I see some "foo += snprintf" already in the code

output:

* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* TLSv1.3 (IN), TLS handshake
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [15 bytes data]
* TLSv1.3 (IN), TLS handshake
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [2929 bytes data]
* TLSv1.3 (IN), TLS handshake
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [79 bytes data]
* TLSv1.3 (IN), TLS handshake
{ [1 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Client hello (1):
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake
} [1 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]

seems kind of superfluous but OTOH it's verbose mode.

edit: in the most recent draft I changed it to [no content], for example:

* TLSv1.3 (OUT), TLS handshake, [no content], (0):

[bagder]

I think our snprintf() function only returns -1 if there's a syntax error in the format string. Not sure that changes anything...

[jay]

I don't know what the point of the inner content is if there's no actual content with it. Like why would a user want to know TLS handshake if it's not telling what it's actually doing until the next callback. We are dumping that byte to the user but maybe we should skip it. doc says

SSL3_RT_INNER_CONTENT_TYPE
Used when an encrypted TLSv1.3 record is sent or received. In encrypted
TLSv1.3 records the content type in the record header is always
SSL3_RT_APPLICATION_DATA. The real content type for the record is
contained in an "inner" content type. buf contains the encoded "inner"
content type byte.

[jay]

any more thoughts on this

[bagder]

This seems to be a step forward for TLS 1.3.