Windows nghttp2 + schannel + tls 1.3 error: Received HTTP/0.9 when not allowed #9451

ehuss · 2022-09-07T22:16:22Z

I did this

Compiling curl with nghttp2 1.49 and schannel support with MSVC is causing TLS 1.3 connections to fail with the error Unsupported protocol (CURLE_UNSUPPORTED_PROTOCOL) with the details Received HTTP/0.9 when not allowed. This doesn't happen 100% of the time, but it almost always happens for me.

This only happens on Windows 11 or Windows Server 2022. Windows 10 does not seem affected.

Bisecting, this started with #8419.

Roughly I did:

Built nghttp2 with cmake
Built curl with cmake with options:
- -DCURL_USE_SCHANNEL=ON
- -DUSE_NGHTTP2=ON
- -DNGHTTP2_INCLUDE_DIR=...
- -DNGHTTP2_LIBRARY=...
Run curl.exe -O https://github.com/curl/curl/releases/download/curl-7_85_0/curl-7.85.0.zip (may need to run a few times)

The exact URL doesn't seem too important, as long as the server supports 1.3. It seems to fail more readily with larger files (very small files like https://example.com/ don't fail quite as often).

C:\Temp\curl\lib\Debug>..\..\src\Debug\curl.exe -O  https://github.com/curl/curl/releases/download/curl-7_85_0/curl-7.85.0.zip
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
curl: (1) Received HTTP/0.9 when not allowed

It also happens with really trivial programs like simple.c from the examples directory. Lowering the max TLS version below 1.3 makes the problem go away.

I expected the following

Should not fail.

curl/libcurl version

Latest tested version is 5390c9d. Seems to be happening with any version since #8419.

curl 7.86.0-DEV (Windows) libcurl/7.86.0-DEV Schannel nghttp2/1.49.0
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS HSTS HTTP2 IPv6 Kerberos Largefile NTLM SPNEGO SSL SSPI threadsafe UnixSockets

operating system

Windows 11 22000.856

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

bagder · 2022-09-08T09:13:44Z

if you add --tls-max 1.2 or --http1.1 to the command line, does any of them make the problem go away?

If the first fixes the problem, then 8beff43 certainly sounds like the culprit...

/cc @wyattoday @gvollant

wyattoday · 2022-09-08T10:41:57Z

We don't use HTTP2 or HTTP3 (and thus no ALPN either) in our products, and thus this got 0 internal testing from our side of things. I relied on CI tests to stress that functionality.

I haven't reproduced what @ehuss has seen (I don't have the time, currently). But I will if no one else picks up this thread.

Based on a quick glance of where things could go wrong (and where I would start poking around) is in schannel_connect_step1, namely the call to s_pSecFn->InitializeSecurityContext. The docs explicitly say that "Typically, the InitializeSecurityContext (Schannel) function is called in a loop until a sufficient security context is established." And as you can see that's not the case.

My guess is that when this original code was written and tested everything worked fine without the loop, and now that the black-box internals of SChannel have been modified to add TLS 1.3, the loop is now necessary.

It's just my first guess based on a similar finding (SChannel requesting more data at an "unexpected time" when it previously didn't) when adding TLS 1.3 support in the first place.

Also, can someone from @microsoft chime in? @Andrei-Popov or someone else working on networking and/or SChannel code internally at MS?

Microsoft uses curl with SChannel in Visual Studio (via Git) and in Windows itself. If you don't provide money or developers, then at least a peek inside the SChannel would be nice so this can be written in a robust way.

jay · 2022-09-08T15:46:49Z

Based on a quick glance of where things could go wrong (and where I would start poking around) is in schannel_connect_step1, namely the call to s_pSecFn->InitializeSecurityContext. The docs explicitly say that "Typically, the InitializeSecurityContext (Schannel) function is called in a loop until a sufficient security context is established." And as you can see that's not the case.

The initial handshake data is sent and then it moves on to step 2, where it receives whatever the initial reply is and continues to call InitializeSecurityContext until the handshake ie "security context" is complete. This is the same for all vtls, step 2 at least finishes the handshake and there may or may not be a step 3 for post-handshake logic. Sometimes that is in step2... For example openssl handles the ALPN result at the end of step2 and schannel handles it in step3. I would think the schannel way is more correct, but I wonder what happens if it's moved to the end of step2.

curl/lib/vtls/schannel.c

Lines 1702 to 1738 in 93d0928

    
           #ifdef HAS_ALPN 
        
             if(backend->use_alpn) { 
        
               sspi_status = 
        
                 s_pSecFn->QueryContextAttributes(&backend->ctxt->ctxt_handle, 
        
                                                  SECPKG_ATTR_APPLICATION_PROTOCOL, 
        
                                                  &alpn_result); 
        
               if(sspi_status != SEC_E_OK) { 
        
                 failf(data, "schannel: failed to retrieve ALPN result"); 
        
                 return CURLE_SSL_CONNECT_ERROR; 
        
               } 
        
               if(alpn_result.ProtoNegoStatus == 
        
                  SecApplicationProtocolNegotiationStatus_Success) { 
        
                 infof(data, VTLS_INFOF_ALPN_ACCEPTED_LEN_1STR, 
        
                       alpn_result.ProtocolIdSize, alpn_result.ProtocolId); 
        
           #ifdef USE_HTTP2 
        
                 if(alpn_result.ProtocolIdSize == ALPN_H2_LENGTH && 
        
                    !memcmp(ALPN_H2, alpn_result.ProtocolId, ALPN_H2_LENGTH)) { 
        
                   conn->negnpn = CURL_HTTP_VERSION_2; 
        
                 } 
        
                 else 
        
           #endif 
        
                   if(alpn_result.ProtocolIdSize == ALPN_HTTP_1_1_LENGTH && 
        
                      !memcmp(ALPN_HTTP_1_1, alpn_result.ProtocolId, 
        
                              ALPN_HTTP_1_1_LENGTH)) { 
        
                     conn->negnpn = CURL_HTTP_VERSION_1_1; 
        
                   } 
        
               } 
        
               else 
        
                 infof(data, VTLS_INFOF_NO_ALPN); 
        
               Curl_multiuse_state(data, conn->negnpn == CURL_HTTP_VERSION_2 ? 
        
                                   BUNDLE_MULTIPLEX : BUNDLE_NO_MULTIUSE); 
        
             } 
        
           #endif

I've started to set up a Windows 11 VM from ISO, and so far I've followed these directions and it at least boots. I will work on configuring it soon. If anyone is running Win 11 in VM anything I should know?

ehuss · 2022-09-08T22:12:46Z

if you add --tls-max 1.2 or --http1.1 to the command line, does any of them make the problem go away?

Confirmed that adding either flag makes the problem go away.

jay · 2022-09-09T05:31:35Z

What is the verbose output -v

ehuss · 2022-09-09T13:04:33Z

What is the verbose output -v

*   Trying 192.30.255.112:443...
* Connected to github.com (192.30.255.112) port 443 (#0)
* schannel: disabled automatic use of client certificate
* ALPN: offers h2
* ALPN: offers http/1.1
* ALPN: server accepted h2
* Using HTTP2, server supports multiplexing
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* h2h3 [:method: GET]
* h2h3 [:path: /curl/curl/releases/download/curl-7_85_0/curl-7.85.0.zip]
* h2h3 [:scheme: https]
* h2h3 [:authority: github.com]
* h2h3 [user-agent: curl/7.86.0-DEV]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x162d1e17a70)
> GET /curl/curl/releases/download/curl-7_85_0/curl-7.85.0.zip HTTP/2
> Host: github.com
> user-agent: curl/7.86.0-DEV
> accept: */*
>
* schannel: remote party requests renegotiation
* schannel: renegotiating SSL/TLS connection
* ALPN: server did not agree on a protocol. Uses default.
* schannel: SSL/TLS connection renegotiated
* schannel: remote party requests renegotiation
* schannel: renegotiating SSL/TLS connection
* ALPN: server did not agree on a protocol. Uses default.
* schannel: SSL/TLS connection renegotiated
* Received HTTP/0.9 when not allowed
* Connection #0 to host github.com left intact
curl: (1) Received HTTP/0.9 when not allowed

By the time schannel_recv is renegotiating the connection, libcurl has already decided on a protocol and it is too late for the server to select a protocol via ALPN. Ref: curl#9451 Closes #xxxx

jay · 2022-09-09T19:39:14Z

schannel: remote party requests renegotiation

schannel: renegotiating SSL/TLS connection

ALPN: server did not agree on a protocol. Uses default.

schannel: SSL/TLS connection renegotiated

That is interesting. I wonder whether or not schannel sends ALPN during renegotiation. In step1 we create the security context handle with the ALPN extension and then for further calls with the same handle to InitializeSecurityContext (like in step2) we do not set the extension. AFAICT this is correct @JDepooter

The code flow is basically (but not exactly) this

new tls transfer -> common -> step1 -> step2 -> step3 -> do transfer schannel_send/recv/etc -> renegotiation in recv (SEC_I_RENEGOTIATE received -> reset connection state to step2 -> common -> step2 -> step3 -> common returns when handshake complete -> recv attempts to decrypt any data and then returns) -> do transfer schannel_send/recv/etc and so on

schannel_recv renegotiate logic:

curl/lib/vtls/schannel.c

Lines 2284 to 2305 in 93d0928

    
           /* check if server wants to renegotiate the connection context */ 
        
           if(sspi_status == SEC_I_RENEGOTIATE) { 
        
             infof(data, "schannel: remote party requests renegotiation"); 
        
             if(*err && *err != CURLE_AGAIN) { 
        
               infof(data, "schannel: can't renegotiate, an error is pending"); 
        
               goto cleanup; 
        
             } 
        
             /* begin renegotiation */ 
        
             infof(data, "schannel: renegotiating SSL/TLS connection"); 
        
             connssl->state = ssl_connection_negotiating; 
        
             connssl->connecting_state = ssl_connect_2_writing; 
        
             *err = schannel_connect_common(data, conn, sockindex, FALSE, &done); 
        
             if(*err) { 
        
               infof(data, "schannel: renegotiation failed"); 
        
               goto cleanup; 
        
             } 
        
             /* now retry receiving data */ 
        
             sspi_status = SEC_E_OK; 
        
             infof(data, "schannel: SSL/TLS connection renegotiated"); 
        
             continue; 
        
           }

Regardless of where the alpn result logic is handled (for schannel it's step3) conn->alpn isn't changed when there is no ALPN result:

curl/lib/vtls/schannel.c

Lines 1702 to 1738 in 93d0928

    
           #ifdef HAS_ALPN 
        
             if(backend->use_alpn) { 
        
               sspi_status = 
        
                 s_pSecFn->QueryContextAttributes(&backend->ctxt->ctxt_handle, 
        
                                                  SECPKG_ATTR_APPLICATION_PROTOCOL, 
        
                                                  &alpn_result); 
        
               if(sspi_status != SEC_E_OK) { 
        
                 failf(data, "schannel: failed to retrieve ALPN result"); 
        
                 return CURLE_SSL_CONNECT_ERROR; 
        
               } 
        
               if(alpn_result.ProtoNegoStatus == 
        
                  SecApplicationProtocolNegotiationStatus_Success) { 
        
                 infof(data, VTLS_INFOF_ALPN_ACCEPTED_LEN_1STR, 
        
                       alpn_result.ProtocolIdSize, alpn_result.ProtocolId); 
        
           #ifdef USE_HTTP2 
        
                 if(alpn_result.ProtocolIdSize == ALPN_H2_LENGTH && 
        
                    !memcmp(ALPN_H2, alpn_result.ProtocolId, ALPN_H2_LENGTH)) { 
        
                   conn->negnpn = CURL_HTTP_VERSION_2; 
        
                 } 
        
                 else 
        
           #endif 
        
                   if(alpn_result.ProtocolIdSize == ALPN_HTTP_1_1_LENGTH && 
        
                      !memcmp(ALPN_HTTP_1_1, alpn_result.ProtocolId, 
        
                              ALPN_HTTP_1_1_LENGTH)) { 
        
                     conn->negnpn = CURL_HTTP_VERSION_1_1; 
        
                   } 
        
               } 
        
               else 
        
                 infof(data, VTLS_INFOF_NO_ALPN); 
        
               Curl_multiuse_state(data, conn->negnpn == CURL_HTTP_VERSION_2 ? 
        
                                   BUNDLE_MULTIPLEX : BUNDLE_NO_MULTIUSE); 
        
             } 
        
           #endif

So in other words if ALPN returns h2 the first time (the initial handshake) but no result after that (!=SecApplicationProtocolNegotiationStatus_Success) then conn->alpn should stay CURL_HTTP_VERSION_2.

I don't think any of this explains what is causing the bug, maybe it's a total red herring, but it's still interesting. I've filed #9463 to ban server ALPN selection during recv renegotiation.

ehuss · 2022-09-09T22:19:39Z

I've been poking around. I'm not at all familiar with curl's internals or schannel, so I'm not sure I can provide much insight.

Here's the debug output when it fails to get the initial HTTP/2 header:

CLICK ME

src\Debug\curl -v -O https://github.com/curl/curl/releases/download/curl-7_85_0/curl-7.85.0.zip
* STATE: INIT => CONNECT handle 0x2156f290428; line 1881 (connection #-5000)
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => RESOLVING handle 0x2156f290428; line 1927 (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 192.30.255.112:443...
* STATE: RESOLVING => CONNECTING handle 0x2156f290428; line 2011 (connection #0)
* Connected to github.com (192.30.255.112) port 443 (#0)
* STATE: CONNECTING => PROTOCONNECT handle 0x2156f290428; line 2076 (connection #0)
* schannel: SSL/TLS connection with github.com port 443 (step 1/3)
* Didn't find Session ID in cache for host HTTPS://github.com:443
* schannel: checking server certificate revocation
* schannel: disabled automatic use of client certificate
* ALPN: offers h2
* ALPN: offers http/1.1
* schannel: sending initial handshake data: sending 292 bytes.
* schannel: sent initial handshake data: sent 292 bytes
* schannel: SSL/TLS connection with github.com port 443 (step 2/3)
* schannel: failed to receive handshake, need more data
* STATE: PROTOCONNECT => PROTOCONNECTING handle 0x2156f290428; line 2094 (connection #0)
* schannel: SSL/TLS connection with github.com port 443 (step 2/3)
* schannel: encrypted data got 2814
* schannel: encrypted data buffer: offset 2814 length 4096
* schannel: sending next handshake data: sending 64 bytes.
* schannel: SSL/TLS handshake complete
* schannel: SSL/TLS connection with github.com port 443 (step 3/3)
* ALPN: server accepted h2
* Didn't find Session ID in cache for host HTTPS://github.com:443
* Added Session ID to cache for HTTPS://github.com:443 [server]
* schannel: stored credential handle in session cache
* STATE: PROTOCONNECTING => DO handle 0x2156f290428; line 2113 (connection #0)
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* Using HTTP2, server supports multiplexing
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* h2h3 [:method: GET]
* h2h3 [:path: /curl/curl/releases/download/curl-7_85_0/curl-7.85.0.zip]
* h2h3 [:scheme: https]
* h2h3 [:authority: github.com]
* h2h3 [user-agent: curl/7.86.0-DEV]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x2156f290428)
> GET /curl/curl/releases/download/curl-7_85_0/curl-7.85.0.zip HTTP/2
> Host: github.com
> user-agent: curl/7.86.0-DEV
> accept: */*
>
* STATE: DO => DID handle 0x2156f290428; line 2193 (connection #0)
* multi changed, check CONNECT_PEND queue
* STATE: DID => PERFORMING handle 0x2156f290428; line 2312 (connection #0)
* schannel: client wants to read 32768 bytes
* schannel: encdata_buffer resized 33792
* schannel: encrypted data buffer: offset 0 length 33792
* schannel: encrypted data got 216
* schannel: encrypted data buffer: offset 216 length 33792
* schannel: decrypted data length: 0
* schannel: decrypted data added: 0
* schannel: decrypted cached: offset 0 length 32768
* schannel: encrypted data length: 216
* schannel: encrypted cached: offset 216 length 33792
* schannel: remote party requests renegotiation
* schannel: renegotiating SSL/TLS connection
* schannel: SSL/TLS connection with github.com port 443 (step 2/3)
* schannel: encrypted data buffer: offset 216 length 33792
* schannel: encrypted data length: 137
* schannel: SSL/TLS handshake complete
* schannel: SSL/TLS connection with github.com port 443 (step 3/3)
* ALPN: server did not agree on a protocol. Uses default.
* Found Session ID in cache for host HTTPS://github.com:443
* schannel: SSL/TLS connection renegotiated
* schannel: decrypted data length: 0
* schannel: decrypted data added: 0
* schannel: decrypted cached: offset 0 length 32768
* schannel: encrypted data length: 137
* schannel: encrypted cached: offset 137 length 33792
* schannel: remote party requests renegotiation
* schannel: renegotiating SSL/TLS connection
* schannel: SSL/TLS connection with github.com port 443 (step 2/3)
* schannel: encrypted data buffer: offset 137 length 33792
* schannel: encrypted data length: 58
* schannel: SSL/TLS handshake complete
* schannel: SSL/TLS connection with github.com port 443 (step 3/3)
* ALPN: server did not agree on a protocol. Uses default.
* Found Session ID in cache for host HTTPS://github.com:443
* schannel: SSL/TLS connection renegotiated
* schannel: decrypted data length: 36
* schannel: decrypted data added: 36
* schannel: decrypted cached: offset 36 length 32768
* schannel: encrypted data buffer: offset 0 length 33792
* schannel: decrypted data buffer: offset 36 length 32768
* schannel: schannel_recv cleanup
* schannel: decrypted data returned 36
* schannel: decrypted data buffer: offset 0 length 32768
* schannel: client wants to read 102400 bytes
* schannel: encdata_buffer resized 103424
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: encrypted data got 2783
* schannel: encrypted data buffer: offset 2783 length 103424
* schannel: decrypted data length: 1370
* schannel: decrypted data added: 1370
* schannel: decrypted cached: offset 1370 length 102400
* schannel: encrypted data length: 1391
* schannel: encrypted cached: offset 1391 length 103424
* schannel: decrypted data length: 1369
* schannel: decrypted data added: 1369
* schannel: decrypted cached: offset 2739 length 102400
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: decrypted data buffer: offset 2739 length 102400
* schannel: schannel_recv cleanup
* schannel: decrypted data returned 2739
* schannel: decrypted data buffer: offset 0 length 102400
* first header: 2
* Received HTTP/0.9 when not allowed
* multi_done: status: 1 prem: 1 done: 0
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
* Connection #0 to host github.com left intact
* Expire cleared (transfer 0x2156f290428)
curl: (1) Received HTTP/0.9 when not allowed

The first two bytes of str_start in Curl_http_readwrite_headers is 0x00 0x0a.

Here's what it looks like when it is able to get past reading the headers:

CLICK ME

\Debug\curl -v -O https://github.com/curl/curl/releases/download/curl-7_85_0/curl-7.85.0.zip
* STATE: INIT => CONNECT handle 0x26127bf1e78; line 1881 (connection #-5000)
* Added connection 0. The cache now contains 1 members
* STATE: CONNECT => RESOLVING handle 0x26127bf1e78; line 1927 (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 192.30.255.112:443...
* STATE: RESOLVING => CONNECTING handle 0x26127bf1e78; line 2011 (connection #0)
* Connected to github.com (192.30.255.112) port 443 (#0)
* STATE: CONNECTING => PROTOCONNECT handle 0x26127bf1e78; line 2076 (connection #0)
* schannel: SSL/TLS connection with github.com port 443 (step 1/3)
* Didn't find Session ID in cache for host HTTPS://github.com:443
* schannel: checking server certificate revocation
* schannel: disabled automatic use of client certificate
* ALPN: offers h2
* ALPN: offers http/1.1
* schannel: sending initial handshake data: sending 292 bytes.
* schannel: sent initial handshake data: sent 292 bytes
* schannel: SSL/TLS connection with github.com port 443 (step 2/3)
* schannel: failed to receive handshake, need more data
* STATE: PROTOCONNECT => PROTOCONNECTING handle 0x26127bf1e78; line 2094 (connection #0)
* schannel: SSL/TLS connection with github.com port 443 (step 2/3)
* schannel: encrypted data got 2814
* schannel: encrypted data buffer: offset 2814 length 4096
* schannel: sending next handshake data: sending 64 bytes.
* schannel: SSL/TLS handshake complete
* schannel: SSL/TLS connection with github.com port 443 (step 3/3)
* ALPN: server accepted h2
* Didn't find Session ID in cache for host HTTPS://github.com:443
* Added Session ID to cache for HTTPS://github.com:443 [server]
* schannel: stored credential handle in session cache
* STATE: PROTOCONNECTING => DO handle 0x26127bf1e78; line 2113 (connection #0)
* Using HTTP2, server supports multiplexing
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* h2h3 [:method: GET]
* h2h3 [:path: /curl/curl/releases/download/curl-7_85_0/curl-7.85.0.zip]
* h2h3 [:scheme: https]
* h2h3 [:authority: github.com]
* h2h3 [user-agent: curl/7.86.0-DEV]
* h2h3 [accept: */*]
* Using Stream ID: 1 (easy handle 0x26127bf1e78)
> GET /curl/curl/releases/download/curl-7_85_0/curl-7.85.0.zip HTTP/2
> Host: github.com
> user-agent: curl/7.86.0-DEV
> accept: */*
>
* STATE: DO => DID handle 0x26127bf1e78; line 2193 (connection #0)
* multi changed, check CONNECT_PEND queue
* STATE: DID => PERFORMING handle 0x26127bf1e78; line 2312 (connection #0)
* schannel: client wants to read 32768 bytes
* schannel: encdata_buffer resized 33792
* schannel: encrypted data buffer: offset 0 length 33792
* schannel: encrypted data got 2999
* schannel: encrypted data buffer: offset 2999 length 33792
* schannel: decrypted data length: 0
* schannel: decrypted data added: 0
* schannel: decrypted cached: offset 0 length 32768
* schannel: encrypted data length: 2999
* schannel: encrypted cached: offset 2999 length 33792
* schannel: remote party requests renegotiation
* schannel: renegotiating SSL/TLS connection
* schannel: SSL/TLS connection with github.com port 443 (step 2/3)
* schannel: encrypted data buffer: offset 2999 length 33792
* schannel: encrypted data length: 2920
* schannel: SSL/TLS handshake complete
* schannel: SSL/TLS connection with github.com port 443 (step 3/3)
* ALPN: server did not agree on a protocol. Uses default.
* Found Session ID in cache for host HTTPS://github.com:443
* schannel: SSL/TLS connection renegotiated
* schannel: decrypted data length: 0
* schannel: decrypted data added: 0
* schannel: decrypted cached: offset 0 length 32768
* schannel: encrypted data length: 2920
* schannel: encrypted cached: offset 2920 length 33792
* schannel: remote party requests renegotiation
* schannel: renegotiating SSL/TLS connection
* schannel: SSL/TLS connection with github.com port 443 (step 2/3)
* schannel: encrypted data buffer: offset 2920 length 33792
* schannel: encrypted data length: 2841
* schannel: SSL/TLS handshake complete
* schannel: SSL/TLS connection with github.com port 443 (step 3/3)
* ALPN: server did not agree on a protocol. Uses default.
* Found Session ID in cache for host HTTPS://github.com:443
* schannel: SSL/TLS connection renegotiated
* schannel: decrypted data length: 36
* schannel: decrypted data added: 36
* schannel: decrypted cached: offset 36 length 32768
* schannel: encrypted data length: 2783
* schannel: encrypted cached: offset 2783 length 33792
* schannel: decrypted data length: 1370
* schannel: decrypted data added: 1370
* schannel: decrypted cached: offset 1406 length 32768
* schannel: encrypted data length: 1391
* schannel: encrypted cached: offset 1391 length 33792
* schannel: decrypted data length: 1369
* schannel: decrypted data added: 1369
* schannel: decrypted cached: offset 2775 length 32768
* schannel: encrypted data buffer: offset 0 length 33792
* schannel: decrypted data buffer: offset 2775 length 32768
* schannel: schannel_recv cleanup
* schannel: decrypted data returned 2775
* schannel: decrypted data buffer: offset 0 length 32768
* first header: 13 HTTP/2 302
* HTTP/2 found, allow multiplexing
< HTTP/2 302
< server: GitHub.com
< date: Fri, 09 Sep 2022 22:04:12 GMT
< content-type: text/html; charset=utf-8
< vary: X-PJAX, X-PJAX-Container, Turbo-Visit, Turbo-Frame, Accept-Encoding, Accept, X-Requested-With
< permissions-policy: interest-cohort=()
< location: https://objects.githubusercontent.com/github-production-release-asset-2e65be/569041/abdf82e3-624c-4307-8d41-a9bf109bbac5?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Credential=AKIAIWNJYAX4CSVEH53A%2F20220909%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Date=20220909T220412Z&X-Amz-Expires=300&X-Amz-Signature=2cd5f85c79435cd09820025f48c192b776f03175834bc246f611cabd94814bc8&X-Amz-SignedHeaders=host&actor_id=0&key_id=0&repo_id=569041&response-content-disposition=attachment%3B%20filename%3Dcurl-7.85.0.zip&response-content-type=application%2Foctet-stream
< cache-control: no-cache
< strict-transport-security: max-age=31536000; includeSubdomains; preload
< x-frame-options: deny
< x-content-type-options: nosniff
< x-xss-protection: 0
< referrer-policy: no-referrer-when-downgrade
< expect-ct: max-age=2592000, report-uri="https://api.github.com/_private/browser/errors"
< content-security-policy: default-src 'none'; base-uri 'self'; block-all-mixed-content; child-src github.com/assets-cdn/worker/ gist.github.com/assets-cdn/worker/; connect-src 'self' uploads.github.com objects-origin.githubusercontent.com www.githubstatus.com collector.github.com raw.githubusercontent.com api.github.com github-cloud.s3.amazonaws.com github-production-repository-file-5c1aeb.s3.amazonaws.com github-production-upload-manifest-file-7fdce7.s3.amazonaws.com github-production-user-asset-6210df.s3.amazonaws.com cdn.optimizely.com logx.optimizely.com/v1/events *.actions.githubusercontent.com wss://*.actions.githubusercontent.com online.visualstudio.com/api/v1/locations github-production-repository-image-32fea6.s3.amazonaws.com github-production-release-asset-2e65be.s3.amazonaws.com insights.github.com wss://alive.github.com; font-src github.githubassets.com; form-action 'self' github.com gist.github.com objects-origin.githubusercontent.com; frame-ancestors 'none'; frame-src render.githubusercontent.com viewscreen.githubusercontent.com notebooks.githubusercontent.com; img-src 'self' data: github.githubassets.com identicons.github.com github-cloud.s3.amazonaws.com secured-user-images.githubusercontent.com/ github-production-user-asset-6210df.s3.amazonaws.com customer-stories-feed.github.com spotlights-feed.github.com *.githubusercontent.com; manifest-src 'self'; media-src github.com user-images.githubusercontent.com/ secured-user-images.githubusercontent.com/; script-src github.githubassets.com; style-src 'unsafe-inline' github.githubassets.com; worker-src github.com/assets-cdn/worker/ gist.github.com/assets-cdn/worker/
< content-length: 0
< x-github-request-id: 1406:5742:2C83305:2EC590C:631BB8D9
<
* schannel: client wants to read 102400 bytes
* schannel: encdata_buffer resized 103424
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: Curl_read_plain returned CURLE_AGAIN
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: decrypted data buffer: offset 0 length 32768
* schannel: schannel_recv cleanup
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* Curl_readwrite: forcibly told to drain data
* schannel: client wants to read 102400 bytes
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: Curl_read_plain returned CURLE_AGAIN
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: decrypted data buffer: offset 0 length 32768
* schannel: schannel_recv cleanup
* Curl_readwrite: forcibly told to drain data
* schannel: client wants to read 102400 bytes
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: Curl_read_plain returned CURLE_AGAIN
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: encrypted data buffer: offset 0 length 103424
* schannel: decrypted data buffer: offset 0 length 32768
* schannel: schannel_recv cleanup
  0     0    0     0    0     0      0      0 --:--:--  0:00:01 --:--:--     0^C

However, it gets stuck while transferring the body repeatedly saying Curl_readwrite: forcibly told to drain data.

By the time schannel_recv is renegotiating the connection, libcurl has already decided on a protocol and it is too late for the server to select a protocol via ALPN. Ref: curl#9451 Closes #xxxx

By the time schannel_recv is renegotiating the connection, libcurl has already decided on a protocol and it is too late for the server to select a protocol via ALPN except for the originally selected protocol. Ref: #9451 Closes #9463

JDepooter · 2022-10-18T16:45:00Z

I have run into this problem myself, and did a bit of digging. I have a proposed fix in #9756 .

Essentially this is what happens:

The initial TLS handshake succeeds, and the connection recv/send function pointers are set to schannel_recv and schannel_send.
When the HTTP/2 upgrade happens, the connection recv/send function pointers are set to http2_recv and http2_send. These functions will call the underlying schannel_xxxx functions as necessary.
After the TLS renegotiation, the schannel code was again setting the connection recv/send function pointers to the schannel_xxxx functions, thereby removing the http2_xxxx functions from the connection. This is why curl was suddenly reporting errors regarding HTTP/0.9, because the regular HTTP code was being used to handle HTTP/2 data.

The fix is to not reset a connections recv and send functions after a renegotiation. They will have been set after the first handshake. If they have not changed, there is no need to reset them. If they have changed, we don't want to override that change.

Thanks to @jay for introducing the recv_renegotiating flag in #9463, that made it very easy to implement a fix for this problem.

By the time schannel_recv is renegotiating the connection, libcurl has already decided on a protocol and it is too late for the server to select a protocol via ALPN except for the originally selected protocol. Ref: curl/curl#9451 Closes curl/curl#9463

ehuss mentioned this issue Sep 7, 2022

Received HTTP/0.9 when not allowed with http2 feature alexcrichton/curl-rust#460

Closed

bagder added TLS Windows Windows-specific labels Sep 8, 2022

jay mentioned this issue Sep 9, 2022

schannel: ban server ALPN selection during recv renegotiation #9463

Closed

wyattoday mentioned this issue Sep 12, 2022

CURLE_RECV_ERROR schannel: SEC_E_DECRYPT_FAILURE #9431

Closed

ehuss mentioned this issue Sep 27, 2022

Release updated curl-sys (7.85.0) to crates.io alexcrichton/curl-rust#465

Closed

JDepooter mentioned this issue Oct 18, 2022

schannel: Don't reset recv/send function pointers on renegotiation #9756

Closed

jay closed this as completed in 3f5a797 Oct 19, 2022

jw013 mentioned this issue Oct 21, 2022

SChannel SSL backend does not use HTTP2 (HTTP/2) git-for-windows/git#4077

Closed

1 task

bradking mentioned this issue Nov 9, 2022

Windows schannel error SEC_E_DECRYPT_FAILURE with tls 1.3 support #9879

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Windows nghttp2 + schannel + tls 1.3 error: Received HTTP/0.9 when not allowed #9451

Windows nghttp2 + schannel + tls 1.3 error: Received HTTP/0.9 when not allowed #9451

ehuss commented Sep 7, 2022

bagder commented Sep 8, 2022

wyattoday commented Sep 8, 2022

jay commented Sep 8, 2022

ehuss commented Sep 8, 2022

jay commented Sep 9, 2022

ehuss commented Sep 9, 2022

jay commented Sep 9, 2022

ehuss commented Sep 9, 2022

JDepooter commented Oct 18, 2022

Windows nghttp2 + schannel + tls 1.3 error: Received HTTP/0.9 when not allowed #9451

Windows nghttp2 + schannel + tls 1.3 error: Received HTTP/0.9 when not allowed #9451

Comments

ehuss commented Sep 7, 2022

I did this

I expected the following

curl/libcurl version

operating system

bagder commented Sep 8, 2022

wyattoday commented Sep 8, 2022

jay commented Sep 8, 2022

ehuss commented Sep 8, 2022

jay commented Sep 9, 2022

ehuss commented Sep 9, 2022

jay commented Sep 9, 2022

ehuss commented Sep 9, 2022

JDepooter commented Oct 18, 2022