Connection is retried via HTTP/2 after HTTP_1_1_REQUIRED is received in some cases

[ngg]

I did this

We have a server, where some endpoints require TLS client cert authentication. As HTTP/2 does not support TLS renegotiation, when this endpoint is called, the server replies with HTTP_1_1_REQUIRED and a new connection is necessary.

In curl 7.76.0, there was a fix for the simplest case by closing the connection: #6793
However, if there is another multiplexed connection which uses the same HTTP/2 connection, this solution does not work.

To reproduce with an Apache server, use the following Dockerfile:

FROM httpd:2.4
RUN apt-get -y update && apt-get install -y openssl && rm -rf /var/lib/apt/lists/*
RUN yes '' | openssl req -x509 -newkey rsa:4096 -keyout conf/server.key -out conf/server.crt -days 365 -nodes
RUN \
echo Include conf/extra/httpd-ssl.conf >> conf/httpd.conf && \
echo LoadModule http2_module modules/mod_http2.so >> conf/httpd.conf && \
echo LoadModule ssl_module modules/mod_ssl.so >> conf/httpd.conf && \
echo LoadModule socache_shmcb_module modules/mod_socache_shmcb.so >> conf/httpd.conf && \
echo Protocols h2 http/1.1 >> conf/httpd.conf && \
echo "<Location /secure>" >> conf/httpd.conf && \
echo SSLVerifyClient require >> conf/httpd.conf && \
echo "</Location>" >> conf/httpd.conf
RUN dd if=/dev/zero of=htdocs/largefile count=128 bs=1M

If this Dockerfile is saved to an empty directory, run the following command in that directory to start the server:

docker build -t tlsrenego . && docker run --rm -it -p 8443:443 tlsrenego

When the server is running, call curl with:

curl -k -v -Z -o x -o x2 https://localhost:8443/largefile https://localhost:8443/secure

Around 50% of the time on my machine (but it's timing dependant, the size of the largefile might need to be modified in the Dockerfile above) the call is retried over HTTP/2.

Click here for example curl output when it went wrong!

* Found bundle for host localhost: 0x55940b5fcab0 [serially]
* Server doesn't support multiplex yet, wait
* No connections available.
DL% UL%  Dled  Uled  Xfers  Live   Qd Total     Current  Left    Speed

--  --      0     0     2     2     0 --:--:-- --:--:-- --:--:-- -9223      *   Trying ::1:8443...
* Connected to localhost (::1) port 8443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [122 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [15 bytes data]
* TLSv1.3 (IN), TLS handshake, Certificate (11):
{ [1404 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [520 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 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 to use h2
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* 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
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x55940b609d10)
} [5 bytes data]
> GET /largefile HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.0-DEV
> accept: */*
> 
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* Found bundle for host localhost: 0x55940b5fcab0 [can multiplex]
* Multiplexed connection found!
* Re-using existing connection! (#0) with host localhost
* Transfer was pending, now try another
* Using Stream ID: 3 (easy handle 0x55940b60b1a0)
} [5 bytes data]
> GET /secure HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.0-DEV
> accept: */*
> 
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
} [5 bytes data]
< HTTP/2 200 
< date: Wed, 07 Apr 2021 13:51:32 GMT
< server: Apache/2.4.46 (Unix) OpenSSL/1.1.1d
< last-modified: Wed, 07 Apr 2021 13:51:15 GMT
< etag: "40000000-5bf6239719ac0"
< accept-ranges: bytes
< content-length: 1073741824
< 
{ [1154 bytes data]
* Connection died, retrying a fresh connect(retry count: 1)
* Issue another request to this URL: 'https://localhost:8443/secure'
* Found bundle for host localhost: 0x55940b5fcab0 [can multiplex]
* Hostname localhost was found in DNS cache
*   Trying ::1:8443...
* Transfer was pending, now try another
* Connected to localhost (::1) port 8443 (#1)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
* SSL re-using session ID
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [631 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [128 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [15 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 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 to use h2
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* 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
} [5 bytes data]
* Using Stream ID: 1 (easy handle 0x55940b60b1a0)
} [5 bytes data]
> GET /secure HTTP/2
> Host: localhost:8443
> user-agent: curl/7.76.0-DEV
> accept: */*
> 
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
} [5 bytes data]
* HTTP/2 stream 0 was not closed cleanly: HTTP_1_1_REQUIRED (err 13)
* Downgrades to HTTP/1.1!
* Empty reply from server
* Closing connection 1
} [5 bytes data]
* TLSv1.3 (OUT), TLS alert, close notify (256):
} [2 bytes data]
* Issue another request to this URL: 'https://localhost:8443/secure'
* Found bundle for host localhost: 0x55940b5fcab0 [can multiplex]
* Hostname localhost was found in DNS cache
*   Trying ::1:8443...
* Transfer was pending, now try another
* Connected to localhost (::1) port 8443 (#2)
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: /etc/ssl/certs/ca-certificates.crt
*  CApath: none
* SSL re-using session ID
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [628 bytes data]
* TLSv1.3 (IN), TLS handshake, Server hello (2):
{ [128 bytes data]
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
{ [21 bytes data]
* TLSv1.3 (IN), TLS handshake, Finished (20):
{ [52 bytes data]
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
} [1 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 to use http/1.1
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  start date: Apr  7 13:04:05 2021 GMT
*  expire date: Apr  7 13:04:05 2022 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
} [5 bytes data]
> GET /secure HTTP/1.1
> Host: localhost:8443
> User-Agent: curl/7.76.0-DEV
> Accept: */*
> 
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [265 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Request CERT (13):
{ [77 bytes data]
* TLSv1.3 (OUT), TLS handshake, Certificate (11):
} [40 bytes data]
* TLSv1.3 (OUT), TLS handshake, Finished (20):
} [52 bytes data]
* TLSv1.3 (IN), TLS alert, unknown (628):
{ [2 bytes data]
* OpenSSL SSL_read: error:1409445C:SSL routines:ssl3_read_bytes:tlsv13 alert certificate required, errno 0
* Closing connection 2
curl: (56) Empty reply from server
{ [5 bytes data]

 23 --   237M     0     2     1     0  0:00:02 --:--:--  0:00:01  474M      
 47 --   489M     0     2     1     0  0:00:02  0:00:01  0:00:01  488M      

I expected the following

Curl should have retried the connection via HTTP/1.1, but it's retried with HTTP/2. It seems like that the HTTP/2 connection can stay in the pool (which is actually not a problem because further requests might be able to use that), and when that happen, the retry is done over HTTP/2. I think the proper solution would be to check the wanted HTTP version when choosing a connection to re-use.

curl/libcurl version

I've compiled curl from the 7.76 tag (https://github.com/curl/curl/tree/curl-7_76_0)

> curl -V                                 
curl 7.76.0-DEV (x86_64-pc-linux-gnu) libcurl/7.76.0-DEV OpenSSL/1.1.1k zlib/1.2.11 brotli/1.0.9 zstd/1.4.9 libidn2/2.3.0 libpsl/0.21.0 (+libidn2/2.3.0) nghttp2/1.41.0
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp 
Features: alt-svc AsynchDNS brotli HTTP2 HTTPS-proxy IDN IPv6 Largefile libz NTLM NTLM_WB PSL SSL TLS-SRP UnixSockets zstd

operating system

> uname -a                                                                                                                                                                                                                                    
Linux bp1-dsklin-3010 5.10.27-gentoo #3 SMP Mon Apr 5 18:40:24 CEST 2021 x86_64 Intel(R) Core(TM) i7-8700K CPU @ 3.70GHz GenuineIntel GNU/Linux

[bagder]

I haven't worked on reproducing this yet, but I could imagine a fix could maybe be done something like this?

My idea is to make sure connection reuse isn't done if the existing connection uses HTTP version 2 or higher while the wanted HTTP version is lower than 2.

diff --git a/lib/url.c b/lib/url.c
index 19fcfb842..e576a7eb9 100644
--- a/lib/url.c
+++ b/lib/url.c
@@ -1313,10 +1313,15 @@ ConnectionExists(struct Curl_easy *data,
           /* one of them was different */
           continue;
         }
       }
 
+      if((needle->handler->protocol & PROTO_FAMILY_HTTP) &&
+         (check->httpversion >= 20) &&
+         (data->state.httpwant < CURL_HTTP_VERSION_2_0))
+        continue;
+
       if((needle->handler->flags&PROTOPT_SSL)
 #ifndef CURL_DISABLE_PROXY
          || !needle->bits.httpproxy || needle->bits.tunnel_proxy
 #endif
         ) {

[bagder]

@ngg any chance you can try this?

[ngg]

@ngg any chance you can try this?

This patch is not working for me, the same reproduction case still retries it with HTTP/2. I'll try to find out why.

[ngg]

I think that this new condition is ok, the connection reusing logic will work better this way, but it does not solve this exact problem because of another issue:

It looks like the first retry doesn't have the connection downgraded, because after calling Curl_readwrite(data->conn, data, &done, &comeback) from multi_runsingle, done will be true, so the if(done || (result == CURLE_RECV_ERROR)) branch will be taken instead of the next branch which would actually downgrade the connection.
done is true, result is CURLE_OK and Curl_h2_http_1_1_error(data->conn) would return true if it would be called in this case, but it is skipped.

I think the ordering of these branches is wrong, probably checking Curl_h2_http_1_1_error(data->conn) first would be the better choice even if result is CURLE_OK.

[bagder]

I'm not sure I see how that can work if HTTP_1_1_REQUIRED is actually what the server responds. If so, it seems to suggest that curl is already doing something wrong in an earlier step.

[bagder]

Is there a way to reproduce this issue against a public URL? Getting that thing up in a docker installation is a bit of a hurdle for me but if we can verify against something out there it would become a smaller effort.

[ngg]

I started that docker image on a public server https://13.74.64.165. To make it easier to reproduce there are multiple large files hosted, named 1mb, 2mb, 4mb, 8mb, 16mb, 32mb, 64mb, 128mb.

Somehow it seems easier to reproduce with 3 connections instead of 2 if the server is remote.
I can reliably (2 out of 3 times) reproduce the issue after applying the patch with the following command:

curl -k -v -Z -o x -o x2 -o x3 https://13.74.64.165/1mb https://13.74.64.165/1mb https://13.74.64.165/secure 2>&1 | grep GET          
> GET /1mb HTTP/2
> GET /1mb HTTP/2
> GET /secure HTTP/2
> GET /secure HTTP/2
> GET /secure HTTP/1.1

As you can see, there are 3 connections to /secure, and only the third one uses HTTP 1.1

[bagder]

Thanks! With this I'll be able to get a better understanding of what's going on...