openssl: don't log raw record headers #10299

Cherish98 · 2023-01-15T18:24:18Z

As stated in the comment:

Lines 2696 to 2699 in 6113dec

    
             /* Log progress for interesting records only (like Handshake or Alert), skip 
        
              * all raw record headers (content_type == SSL3_RT_HEADER or ssl_ver == 0). 
        
              * For TLS 1.3, skip notification of the decrypted inner Content-Type. 
        
              */

We should skip TLS record headers (content_type == SSL3_RT_HEADER), but that is never checked.

This patch fixes that and prevents useless TLS record headers from spamming the curl verbose output.
E.g., running a long-running curl -v will have the following two lines spamming the console and clobbering the progress meter:

* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]

update

As stated in the comment, we should log only interesting records and "skip all raw record headers (content_type == SSL3_RT_HEADER)", but that is never checked. This patch fixes that and prevents useless TLS record headers from spamming the curl verbose output.

jay · 2023-01-15T22:09:56Z

The comment you are referring to came from #3281 and I think may have been made by mistake. @Lekensteyn wrote:

curl/lib/vtls/openssl.c

Lines 2720 to 2728 in c12fb3d

    
             /* Log progress for interesting records only (like Handshake or Alert), skip 
        
              * all raw record headers (content_type == SSL3_RT_HEADER or ssl_ver == 0). 
        
              * For TLS 1.3, skip notification of the decrypted inner Content-Type. 
        
              */ 
        
             if(ssl_ver 
        
           #ifdef SSL3_RT_INNER_CONTENT_TYPE 
        
                && content_type != SSL3_RT_INNER_CONTENT_TYPE 
        
           #endif 
        
               ) {

Probably he meant content_type == SSL3_RT_INNER_CONTENT_TYPE in the comment. SSL3_RT_HEADER could be interesting though, like header certificate status received etc. If it's breaking up the progress bar for you I'd suggest turn off verbose. I don't remember what we decided about SSL3_RT_HEADER and it's unclear from the bug whether that comment was left in as a mistake or we actually intended to shut off those other headers.

Lekensteyn · 2023-01-15T23:47:48Z

The suggested code looks correct to me. We could probably improve the comment and commit message while at it.

See this diff in the verbose output without and with this patch below. The status messages TLSv1.0 (OUT), TLS header, Certificate Status (22), TLSv1.2 (OUT), TLS header, Finished (20), and TLSv1.2 (IN), TLS header, Supplemental data (23) messages are bogus. These are interpreted as handshake message types while they are record content types (Handshake (22), Change Cipher Spec (20), Application Data (23)).

@@ -1,97 +1,64 @@
 $ src/curl -svo /dev/null https://mirror.nl.leaseweb.net/speedtest/10mb.bin
 *   Trying [2001:1af8:4700:b210::33]:443...
 * Connected to mirror.nl.leaseweb.net (2001:1af8:4700:b210::33) port 443 (#0)
 * ALPN: offers http/1.1
 *  CAfile: /etc/ssl/certs/ca-certificates.crt
 *  CApath: /etc/ssl/certs
-* TLSv1.0 (OUT), TLS header, Certificate Status (22):
 } [5 bytes data]
 * TLSv1.3 (OUT), TLS handshake, Client hello (1):
 } [512 bytes data]
-* TLSv1.2 (IN), TLS header, Certificate Status (22):
-{ [5 bytes data]
 * TLSv1.3 (IN), TLS handshake, Server hello (2):
 { [88 bytes data]
-* TLSv1.2 (OUT), TLS header, Finished (20):
-} [5 bytes data]
 * TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
 } [1 bytes data]
-* TLSv1.2 (OUT), TLS header, Certificate Status (22):
-} [5 bytes data]
 * TLSv1.3 (OUT), TLS handshake, Client hello (1):
 } [512 bytes data]
-* TLSv1.2 (IN), TLS header, Finished (20):
-{ [5 bytes data]
-* TLSv1.2 (IN), TLS header, Certificate Status (22):
-{ [5 bytes data]
 * TLSv1.3 (IN), TLS handshake, Server hello (2):
 { [187 bytes data]
-* TLSv1.2 (IN), TLS header, Supplemental data (23):
-{ [5 bytes data]
 * TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
 { [25 bytes data]
-* TLSv1.2 (IN), TLS header, Supplemental data (23):
-{ [5 bytes data]
 * TLSv1.3 (IN), TLS handshake, Certificate (11):
 { [4785 bytes data]
-* TLSv1.2 (IN), TLS header, Supplemental data (23):
-{ [5 bytes data]
 * TLSv1.3 (IN), TLS handshake, CERT verify (15):
 { [264 bytes data]
-* TLSv1.2 (IN), TLS header, Supplemental data (23):
-{ [5 bytes data]
 * TLSv1.3 (IN), TLS handshake, Finished (20):
 { [52 bytes data]
-* TLSv1.2 (OUT), TLS header, Supplemental data (23):
-} [5 bytes data]
 * TLSv1.3 (OUT), TLS handshake, Finished (20):
 } [52 bytes data]
 * SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
 * ALPN: server accepted http/1.1
 * Server certificate:
 *  subject: CN=mirror.leaseweb.com
 *  start date: Dec 14 11:30:38 2022 GMT
 *  expire date: Mar 14 11:30:37 2023 GMT
 *  subjectAltName: host "mirror.nl.leaseweb.net" matched cert's "mirror.nl.leaseweb.net"
 *  issuer: C=US; O=Let's Encrypt; CN=R3
 *  SSL certificate verify ok.
-* TLSv1.2 (OUT), TLS header, Supplemental data (23):
 } [5 bytes data]
 > GET /speedtest/10mb.bin HTTP/1.1
 > Host: mirror.nl.leaseweb.net
 > User-Agent: curl/7.87.1-DEV
 > Accept: */*
 > 
-* TLSv1.2 (IN), TLS header, Supplemental data (23):
 { [5 bytes data]
 * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
 { [57 bytes data]
-* TLSv1.2 (IN), TLS header, Supplemental data (23):
-{ [5 bytes data]
 * TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
 { [57 bytes data]
 * old SSL session ID is stale, removing
-* TLSv1.2 (IN), TLS header, Supplemental data (23):
 { [5 bytes data]
 < HTTP/1.1 200 OK
 < Server: nginx
-< Date: Sun, 15 Jan 2023 23:22:17 GMT
+< Date: Sun, 15 Jan 2023 23:23:04 GMT
 < Content-Type: application/octet-stream
 < Content-Length: 10000000
 < Last-Modified: Mon, 08 Aug 2011 22:26:16 GMT
 < Connection: keep-alive
 < ETag: "4e406288-989680"
 < Strict-Transport-Security: max-age=31536000
 < X-Frame-Options: DENY
 < X-Content-Type-Options: nosniff
 < Accept-Ranges: bytes
 < 
 { [16029 bytes data]
-* TLSv1.2 (IN), TLS header, Supplemental data (23):
-{ [5 bytes data]
-* TLSv1.2 (IN), TLS header, Supplemental data (23):
-{ [5 bytes data]
-<... elided 1214 lines ...>
-* TLSv1.2 (IN), TLS header, Supplemental data (23):
-{ [5 bytes data]
 * Connection #0 to host mirror.nl.leaseweb.net left intact

Lekensteyn · 2023-01-15T23:57:56Z

The comment you are referring to came from #3281 and I think may have been made by mistake. @Lekensteyn wrote:

curl/lib/vtls/openssl.c

Lines 2720 to 2728 in c12fb3d

/* Log progress for interesting records only (like Handshake or Alert), skip

* all raw record headers (content_type == SSL3_RT_HEADER or ssl_ver == 0).

* For TLS 1.3, skip notification of the decrypted inner Content-Type.

*/

if(ssl_ver

#ifdef SSL3_RT_INNER_CONTENT_TYPE

&& content_type != SSL3_RT_INNER_CONTENT_TYPE

#endif

) {

Probably he meant content_type == SSL3_RT_INNER_CONTENT_TYPE in the comment. SSL3_RT_HEADER could be interesting though, like header certificate status received etc. If it's breaking up the progress bar for you I'd suggest turn off verbose. I don't remember what we decided about SSL3_RT_HEADER and it's unclear from the bug whether that comment was left in as a mistake or we actually intended to shut off those other headers.

I think that the comment is right. There are two conditions according to the comment:

raw record headers (content_type == SSL3_RT_HEADER or ssl_ver == 0)
For TLS 1.3, skip notification of the decrypted inner Content-Type

I only checked for ssl_ver != 0 because the SSL_CTX_set_msg_callback manual page says this about the version (sslver) parameter:

This is set to 0 for the SSL3_RT_HEADER pseudo content type (see NOTES below).

Then further in NOTES we have:

Due to automatic protocol version negotiation, version is not necessarily the protocol version used by the sender of the message: If a TLS 1.0 ClientHello message is received by an SSL 3.0-only server, version will be SSL3_VERSION.
[..]
SSL3_RT_HEADER
Used when a record is sent or received. The buf contains the record header bytes only.

Somehow this version must have become non-zero for the SSL3_RT_HEADER. I don't remember this being the case, but I do recall seeing a bunch of excessive status messages, potentially after upgrading to openssl 3.0.x on Arch Linux.

There might be a bug in OpenSSL, but the workaround in this PR looks good. We can dig deeper to find the cause and try to include that in the commit message.

Cherish98 · 2023-01-16T01:48:55Z

Somehow this version must have become non-zero for the SSL3_RT_HEADER. I don't remember this being the case, but I do recall seeing a bunch of excessive status messages, potentially after upgrading to openssl 3.0.x on Arch Linux.

Yes, these excessive logs came after upgrading to openssl 3.0.x. True, in openssl 1.1.1, sslver is always 0 for SSL3_RT_HEADER:

~/openssl (git)-[OpenSSL_1_1_1-stable] % git grep SSL3_RT_HEADER,
ssl/d1_lib.c:            s->msg_callback(0, 0, SSL3_RT_HEADER, buf,
ssl/d1_lib.c:                s->msg_callback(1, 0, SSL3_RT_HEADER, buf,
ssl/record/rec_layer_d1.c:        s->msg_callback(1, 0, SSL3_RT_HEADER, pseq - DTLS1_RT_HEADER_LENGTH,
ssl/record/rec_layer_s3.c:            s->msg_callback(1, 0, SSL3_RT_HEADER, recordstart,
ssl/record/ssl3_record.c:                    s->msg_callback(0, 0, SSL3_RT_HEADER, p, 5, s,
ssl/record/ssl3_record.c:            s->msg_callback(0, 0, SSL3_RT_HEADER, p, DTLS1_RT_HEADER_LENGTH,

And it is no longer the case for openssl 3.0:

~/openssl (git)-[openssl-3.0] % git grep SSL3_RT_HEADER,
ssl/d1_lib.c:            s->msg_callback(0, 0, SSL3_RT_HEADER, buf,
ssl/d1_lib.c:                s->msg_callback(1, 0, SSL3_RT_HEADER, buf,
ssl/record/rec_layer_d1.c:        s->msg_callback(1, 0, SSL3_RT_HEADER, pseq - DTLS1_RT_HEADER_LENGTH,
ssl/record/rec_layer_s3.c:            s->msg_callback(1, thiswr->rec_version, SSL3_RT_HEADER, recordstart,
ssl/record/ssl3_record.c:                        s->msg_callback(0, 0, SSL3_RT_HEADER, p, 5, s,
ssl/record/ssl3_record.c:                    s->msg_callback(0, version, SSL3_RT_HEADER, p, 5, s,
ssl/record/ssl3_record.c:            s->msg_callback(0, 0, SSL3_RT_HEADER, p, DTLS1_RT_HEADER_LENGTH,

git blame shows that the second-to-last line came from this commit: openssl/openssl@fcc3a52

jay · 2023-01-24T08:54:31Z

Thanks

- Skip content type SSL3_RT_HEADER in verbose TLS output. This commit prevents bogus and misleading verbose TLS header messages as discussed in curl#10299. Assisted-by: Peter Wu Closes curl#10299

Cherish98 added 4 commits December 23, 2020 12:51

Merge pull request #2 from curl/master

e4b8b06

update

Merge pull request #3 from curl/master

0ef8ce2

update

Merge branch 'curl:master' into master

e64457c

jay added the TLS label Jan 15, 2023

jay closed this in bde24fa Jan 24, 2023

csalinezh mentioned this pull request Jan 30, 2023

SSL_CTX_set_msg_callback - cb function version argument in 3.0.0 does not match documentation openssl/openssl#17262

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

openssl: don't log raw record headers #10299

openssl: don't log raw record headers #10299

Cherish98 commented Jan 15, 2023

jay commented Jan 15, 2023

Lekensteyn commented Jan 15, 2023

Lekensteyn commented Jan 15, 2023

Cherish98 commented Jan 16, 2023

jay commented Jan 24, 2023

	/* Log progress for interesting records only (like Handshake or Alert), skip
	* all raw record headers (content_type == SSL3_RT_HEADER or ssl_ver == 0).
	* For TLS 1.3, skip notification of the decrypted inner Content-Type.
	*/

openssl: don't log raw record headers #10299

openssl: don't log raw record headers #10299

Conversation

Cherish98 commented Jan 15, 2023

jay commented Jan 15, 2023

Lekensteyn commented Jan 15, 2023

Lekensteyn commented Jan 15, 2023

Cherish98 commented Jan 16, 2023

jay commented Jan 24, 2023