Behaviour of https changed in curl 7.87.0 if 'Connection: close' header is present. #10172

hideishi-m · 2022-12-28T07:06:56Z

I did this

curl \
     --http1.1 \
     --cacert /etc/pki/tls/certs/ca-bundle.crt \
     -H 'Connection: close' \
     https://www.google.com >/dev/null
echo $?

Output with curl 7.87.0 is:

curl: (56) OpenSSL SSL_read: Connection closed abruptly, errno 0 (Fatal because this is a curl debug build)
56

Please note that I deliverately built curl with --enable-debug.

Following is the output with --verbose.

* STATE: INIT => CONNECT handle 0x25439b8; line 1909 (connection #-5000)
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => RESOLVING handle 0x25439b8; line 1955 (connection #0)
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* [CONN-0-0] setup, init filter chain
* [CONN-0-0] cf_add(filter=SOCKET)
* [CONN-0-0] cf_add(filter=SSL)
* [CONN-0-0][CF-SOCKET] setup(remotehost=www.google.com)
* STATE: RESOLVING => CONNECTING handle 0x25439b8; line 2029 (connection #0)
* family0 == v4, family1 == v6
*   Trying 172.217.161.36:443...
* [CONN-0-0] connect(block=0)-> 0, done=0
* [CONN-0-0] connect(block=0)-> 0, done=0
* [CONN-0-0] connect(block=0)-> 0, done=0
* [CONN-0-0] connect(block=0)-> 0, done=0
* Connected to www.google.com (172.217.161.36) port 443 (#0)
* ALPN: offers http/1.1
*  CAfile: /etc/pki/tls/certs/ca-bundle.crt
*  CApath: none
* [CONN-0] Didn't find Session ID in cache for host HTTPS://www.google.com:443
* [CONN-0-0][CF-SSL] TLSv1.0 (OUT), TLS header, Certificate Status (22):
} [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* [CONN-0-0] connect(block=0)-> 0, done=0
* [CONN-0-0] connect(block=0)-> 0, done=0
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Certificate Status (22):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Finished (20):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [21 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [4004 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [79 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Finished (20):
} [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
* [CONN-0-0][CF-SSL] 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=www.google.com
*  start date: Nov 28 08:19:01 2022 GMT
*  expire date: Feb 20 08:19:00 2023 GMT
*  subjectAltName: host "www.google.com" matched cert's "www.google.com"
*  issuer: C=US; O=Google Trust Services LLC; CN=GTS CA 1C3
*  SSL certificate verify ok.
* [CONN-0-0] connect(block=0)-> 0, done=1
* STATE: CONNECTING => PROTOCONNECT handle 0x25439b8; line 2073 (connection #0)
* [CONN-0-0] connect(block=0)-> 0, done=1
* STATE: PROTOCONNECT => DO handle 0x25439b8; line 2103 (connection #0)
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
> GET / HTTP/1.1
> Host: www.google.com
> User-Agent: curl/7.86.0
> Accept: */*
> Connection: close
>
* STATE: DO => DID handle 0x25439b8; line 2199 (connection #0)
* STATE: DID => PERFORMING handle 0x25439b8; line 2318 (connection #0)
* Curl_readwrite(handle=0x25439b8) -> 0
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [288 bytes data]
* [CONN-0] Didn't find Session ID in cache for host HTTPS://www.google.com:443
* [CONN-0] Added Session ID to cache for HTTPS://www.google.com:443 [server]
* [CONN-0-0][CF-SSL] TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [288 bytes data]
* [CONN-0] Found Session ID in cache for host HTTPS://www.google.com:443
* old SSL session ID is stale, removing
* [CONN-0] Added Session ID to cache for HTTPS://www.google.com:443 [server]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* Mark bundle as not supporting multiuse
* HTTP 1.1 or later with persistent connection
< HTTP/1.1 200 OK
< Date: Wed, 28 Dec 2022 07:05:21 GMT
< Expires: -1
< Cache-Control: private, max-age=0
< Content-Type: text/html; charset=ISO-8859-1
< Cross-Origin-Opener-Policy-Report-Only: same-origin-allow-popups; report-to="gws"
< Report-To: {"group":"gws","max_age":2592000,"endpoints":[{"url":"https://csp.withgoogle.com/csp/report-to/gws/other"}]}
< P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info."
< Server: gws
< X-XSS-Protection: 0
< X-Frame-Options: SAMEORIGIN
< Set-Cookie: 1P_JAR=2022-12-28-07; expires=Fri, 27-Jan-2023 07:05:22 GMT; path=/; domain=.google.com; Secure
< Set-Cookie: AEC=AakniGM3qBKL-bKwPhSSnCMkNYnctWuhS06yj_qB6bZIc0S_dAtdkFOcMA; expires=Mon, 26-Jun-2023 07:05:22 GMT; path=/; domain=.google.com; Secure; HttpOnly; SameSite=lax
< Set-Cookie: NID=511=DEs0VJ0bE1TjFIy9gP7eJ6kkbOSjSc6iaMdKpJtmq_OI07tQVeyQd8p1jbGR7UsiUCM8AHzoUJN9v-13ROJ0VFzLAJ-cNsSdGmVGJeJnwBPyHLlIoX0h9an8yuyzRT2t1gdpMPgqNWf1MKk9QHMsIM2PLlbUt8y5nWFN1burWGM; expires=Thu, 29-Jun-2023 07:05:21 GMT; path=/; domain=.google.com; HttpOnly
< Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
< Accept-Ranges: none
< Vary: Accept-Encoding
< Connection: close
< Transfer-Encoding: chunked
<
{ [75 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* OpenSSL SSL_read: Connection closed abruptly, errno 0 (Fatal because this is a curl debug build)
* readwrite_data(handle=0x25439b8) -> 56
* Curl_readwrite(handle=0x25439b8) -> 56
* multi_done: status: 56 prem: 1 done: 0
100 15087    0 15087    0     0  37253      0 --:--:-- --:--:-- --:--:-- 37344
* multi_done, not re-using connection=0, forbid=0, close=1, premature=1, stream=0
* The cache now contains 0 members
* Curl_disconnect(conn #0, dead=1)
* Closing connection 0
* [CONN-0-0][CF-SSL] TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
* [CONN-0-0][CF-SSL] TLSv1.3 (OUT), TLS alert, close notify (256):
} [2 bytes data]
* Expire cleared (transfer 0x25439b8)
curl: (56) OpenSSL SSL_read: Connection closed abruptly, errno 0 (Fatal because this is a curl debug build)
56

I expected the following

With curl 7.86.0, the same command return 0 (success) without any error even with --enable-debug.

Following is the output with --verbose.

* STATE: INIT => CONNECT handle 0x9f5938; line 1879 (connection #-5000)
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => RESOLVING handle 0x9f5938; line 1925 (connection #0)
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* family0 == v4, family1 == v6
*   Trying 172.217.161.68:443...
* STATE: RESOLVING => CONNECTING handle 0x9f5938; line 2009 (connection #0)
* Connected to www.google.com (172.217.161.68) port 443 (#0)
* STATE: CONNECTING => PROTOCONNECT handle 0x9f5938; line 2074 (connection #0)
* ALPN: offers http/1.1
*  CAfile: /etc/pki/tls/certs/ca-bundle.crt
*  CApath: none
* Didn't find Session ID in cache for host HTTPS://www.google.com:443
* TLSv1.0 (OUT), TLS header, Certificate Status (22):
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* STATE: PROTOCONNECT => PROTOCONNECTING handle 0x9f5938; line 2092 (connection #0)
* TLSv1.2 (IN), TLS header, Certificate Status (22):
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* TLSv1.2 (IN), TLS header, Finished (20):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [21 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [4004 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [80 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 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, 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=www.google.com
*  start date: Nov 28 08:19:01 2022 GMT
*  expire date: Feb 20 08:19:00 2023 GMT
*  subjectAltName: host "www.google.com" matched cert's "www.google.com"
*  issuer: C=US; O=Google Trust Services LLC; CN=GTS CA 1C3
*  SSL certificate verify ok.
* STATE: PROTOCONNECTING => DO handle 0x9f5938; line 2111 (connection #0)
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
> GET / HTTP/1.1
> Host: www.google.com
> User-Agent: curl/7.86.0
> Accept: */*
> Connection: close
>
* STATE: DO => DID handle 0x9f5938; line 2191 (connection #0)
* STATE: DID => PERFORMING handle 0x9f5938; line 2310 (connection #0)
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [288 bytes data]
* Didn't find Session ID in cache for host HTTPS://www.google.com:443
* Added Session ID to cache for HTTPS://www.google.com:443 [server]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [288 bytes data]
* Found Session ID in cache for host HTTPS://www.google.com:443
* old SSL session ID is stale, removing
* Added Session ID to cache for HTTPS://www.google.com:443 [server]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* Mark bundle as not supporting multiuse
* HTTP 1.1 or later with persistent connection
< HTTP/1.1 200 OK
< Date: Wed, 28 Dec 2022 07:03:32 GMT
< Expires: -1
< Cache-Control: private, max-age=0
< Content-Type: text/html; charset=ISO-8859-1
< Cross-Origin-Opener-Policy-Report-Only: same-origin-allow-popups; report-to="gws"
< Report-To: {"group":"gws","max_age":2592000,"endpoints":[{"url":"https://csp.withgoogle.com/csp/report-to/gws/other"}]}
< P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info."
< Server: gws
< X-XSS-Protection: 0
< X-Frame-Options: SAMEORIGIN
< Set-Cookie: 1P_JAR=2022-12-28-07; expires=Fri, 27-Jan-2023 07:03:32 GMT; path=/; domain=.google.com; Secure
< Set-Cookie: AEC=AakniGM6ONSrec_kmMy_a8LMmaiJP7sRUb-AhgzNvTFXtB2c_GepL3og9A; expires=Mon, 26-Jun-2023 07:03:32 GMT; path=/; domain=.google.com; Secure; HttpOnly; SameSite=lax
< Set-Cookie: NID=511=N9wTNwX5-bwrbQhVTWrCMmwNP2H0f9QYpcoMCoaPmUkhNZzC2948XlH-pdcK7_KNQMWGa8DlD8eT_hGZvy6tsUTOsH3N_px3aPcZIqVxEyGIqNZa-AJvaUq_Y3yh1EGMRlLENsl4DvQgA9nb-l70IjeO1DhfV_ySoL5lW03HI-I; expires=Thu, 29-Jun-2023 07:03:32 GMT; path=/; domain=.google.com; HttpOnly
< Alt-Svc: h3=":443"; ma=2592000,h3-29=":443"; ma=2592000,h3-Q050=":443"; ma=2592000,h3-Q046=":443"; ma=2592000,h3-Q043=":443"; ma=2592000,quic=":443"; ma=2592000; v="46,43"
< Accept-Ranges: none
< Vary: Accept-Encoding
< Connection: close
< Transfer-Encoding: chunked
<
{ [75 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* TLSv1.2 (IN), TLS header, Supplemental data (23):
{ [5 bytes data]
* STATE: PERFORMING => DONE handle 0x9f5938; line 2509 (connection #0)
* multi_done: status: 0 prem: 0 done: 0
100 15105    0 15105    0     0  67748      0 --:--:-- --:--:-- --:--:-- 68040
* The cache now contains 0 members
* Closing connection 0
* TLSv1.2 (OUT), TLS header, Supplemental data (23):
} [5 bytes data]
* TLSv1.3 (OUT), TLS alert, decode error (562):
} [2 bytes data]
* Expire cleared (transfer 0x9f5938)
0

curl/libcurl version

curl 7.87.0 (x86_64-redhat-linux-gnu) libcurl/7.87.0 OpenSSL/3.0.7 zlib/1.2.11 brotli/1.0.9 zstd/1.4.4 libidn2/2.2.0 libpsl/0.20.2 (+libidn2/2.2.0) libssh2/1.9.0 nghttp2/1.51.0 libgsasl/1.8.0
Release-Date: 2022-12-21
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli Debug gsasl GSS-API HSTS HTTP2 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM NTLM_WB PSL SPNEGO SSL threadsafe TLS-SRP TrackMemory UnixSockets zstd

operating system

Linux dev-kusanagi9.magisystem.net 4.18.0-408.el8.x86_64 #1 SMP Mon Jul 18 17:42:52 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

The text was updated successfully, but these errors were encountered:

bagder · 2022-12-28T08:13:39Z

This is not a bug, it is on purpose: "Fatal because this is a curl debug build"

Can you elaborate on why this is a problem for you?

hideishi-m · 2022-12-28T09:21:43Z

Hi @bagder , sure.

My point is that "Fatal because this is a curl debug build" did not appear in 7.86.0 with --enable-debug where it now appears in 7.87.0 with --enable-debug.
If it has been on purpose, then the message should have appeared in 7.86.0 as well.

I did a trace on both 7.86.0 and 7.87.0 and it seems that recent refactoring in lib/vtls/openssl.c has made a change in handling connection.
Therefore, I suspect that this might be a regression caused in 7.87.0.

hideishi-m · 2022-12-28T09:28:24Z

To be more precise,

https://github.com/curl/curl/blob/master/lib/vtls/openssl.c#L4683

In 7.86.0, err did not equal to SSL_ERROR_SYSCALL, hence no error message even with --enable-debug.
In 7.87.0, err equals to SSL_ERROR_SYSCALL, and because --enable-debug is on, it shows the above error message.

My point is that err was not SSL_ERROR_SYSCALL in the previous version regardless of --enable-debug and message.

When the RECV bit is cleared because the response reading for this transfer is complete, the read loop should be stopped. data_pending() can otherwise still return TRUE and another read would be attempted. Reported-by: Hide Ishikawa Fixes #10172 Closes #

hideishi-m · 2022-12-29T01:15:01Z

Thank you for the fix.
I applied your fix locally and confirmed that it works the same as 7.86.0 without any error message even with --enable-debug.
Looking forward to be merged in the next release.

bagder added TLS not-a-bug This is not a bug in curl labels Dec 28, 2022

bagder removed the not-a-bug This is not a bug in curl label Dec 28, 2022

bagder mentioned this issue Dec 28, 2022

transfer: break the read loop when RECV is cleared #10174

Closed

bagder closed this as completed in 54120ef Dec 30, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Behaviour of https changed in curl 7.87.0 if 'Connection: close' header is present. #10172

Behaviour of https changed in curl 7.87.0 if 'Connection: close' header is present. #10172

hideishi-m commented Dec 28, 2022

bagder commented Dec 28, 2022

hideishi-m commented Dec 28, 2022 •

edited

hideishi-m commented Dec 28, 2022

hideishi-m commented Dec 29, 2022

Behaviour of https changed in curl 7.87.0 if 'Connection: close' header is present. #10172

Behaviour of https changed in curl 7.87.0 if 'Connection: close' header is present. #10172

Comments

hideishi-m commented Dec 28, 2022

I did this

I expected the following

curl/libcurl version

operating system

bagder commented Dec 28, 2022

hideishi-m commented Dec 28, 2022 • edited

hideishi-m commented Dec 28, 2022

hideishi-m commented Dec 29, 2022

hideishi-m commented Dec 28, 2022 •

edited