Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

schannel http2 unable to post large content #5177

Closed
ajax16384 opened this issue Apr 2, 2020 · 17 comments
Closed

schannel http2 unable to post large content #5177

ajax16384 opened this issue Apr 2, 2020 · 17 comments
Labels

Comments

@ajax16384
Copy link
Contributor

@ajax16384 ajax16384 commented Apr 2, 2020

I did this

curl builded with schannel only ssl backend + http2
trying to post large content through http2
small.bin - 4bytes
large.bin - 550400bytes
curl.exe -v --http2 -X POST -F "image=@small.bin" "https://nghttp2.org/"
curl.exe -v --http2 -X POST -F "image=@large.bin" "https://nghttp2.org/"

small one produces sane answer

curl.exe -v --http2 -X POST -F "image=@small.bin" "https://nghttp2.org/"
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 139.162.123.134:443...
* Connected to nghttp2.org (139.162.123.134) port 443 (#0)
* schannel: ALPN, offering h2
* schannel: ALPN, offering http/1.1
* schannel: ALPN, server accepted to use h2
* 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 0x23ac4a9e4a0)
> POST / HTTP/2
> Host: nghttp2.org
> user-agent: curl/7.69.1
> accept: */*
> content-length: 206
> content-type: multipart/form-data; boundary=------------------------c829f3918ae6100f
>
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
* We are completely uploaded and fine
< HTTP/2 405
< date: Thu, 02 Apr 2020 22:39:05 GMT
< allow: GET, HEAD
< content-type: text/plain; charset=utf-8
< content-length: 18
< x-backend-header-rtt: 0.029245
< strict-transport-security: max-age=31536000
< server: nghttpx
< via: 2 nghttpx
< alt-svc: h3-23=":4433"; ma=3600
< x-frame-options: SAMEORIGIN
< x-xss-protection: 1; mode=block
< x-content-type-options: nosniff
<
method not allowed* Connection #0 to host nghttp2.org left intact

large one unable to complete request

Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 139.162.123.134:443...
* Connected to nghttp2.org (139.162.123.134) port 443 (#0)
* schannel: ALPN, offering h2
* schannel: ALPN, offering http/1.1
* schannel: ALPN, server accepted to use h2
* 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 0x2075f3f0990)
> POST / HTTP/2
> Host: nghttp2.org
> user-agent: curl/7.69.1
> accept: */*
> content-length: 550602
> content-type: multipart/form-data; boundary=------------------------e1d99eb1ee8c07ba
>
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
* schannel: timed out sending data (bytes sent: 0)
* Failed sending HTTP2 data
* schannel: timed out sending data (bytes sent: 0)
* Failed sending HTTP2 data
* Connection #0 to host nghttp2.org left intact
curl: (55) schannel: timed out sending data (bytes sent: 0)

if i try curl compiled with openssl backend then large.bin produces right output

Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 139.162.123.134:443...
* Connected to nghttp2.org (139.162.123.134) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: D:\curl-ca-bundle.crt
  CApath: none
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: CN=nghttp2.org
*  start date: Mar 20 00:00:08 2020 GMT
*  expire date: Jun 18 00:00:08 2020 GMT
*  subjectAltName: host "nghttp2.org" matched cert's "nghttp2.org"
*  issuer: C=US; O=Let's Encrypt; CN=Let's Encrypt Authority X3
*  SSL certificate verify ok.
* 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 0x1d63091aae0)
> POST / HTTP/2
> Host: nghttp2.org
> user-agent: curl/7.69.1
> accept: */*
> content-length: 550602
> content-type: multipart/form-data; boundary=------------------------6b0b455e2a843eb9
>
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 100)!
* We are completely uploaded and fine
< HTTP/2 405
< date: Thu, 02 Apr 2020 22:44:19 GMT
< allow: GET, HEAD
< content-type: text/plain; charset=utf-8
< content-length: 18
< x-backend-header-rtt: 2.198317
< strict-transport-security: max-age=31536000
< server: nghttpx
< via: 2 nghttpx
< alt-svc: h3-23=":4433"; ma=3600
< x-frame-options: SAMEORIGIN
< x-xss-protection: 1; mode=block
< x-content-type-options: nosniff
<
method not allowed* Connection #0 to host nghttp2.org left intact

405 and nghttp2.org was taken as most simple example. Case can also be reproduced by unabling to POST valid large form through http2.

curl/libcurl version

curl 7.69.1 (x86_64-pc-win32) libcurl/7.69.1 Schannel zlib/1.2.8 libssh2/1.9.0 nghttp2/1.40.0
Release-Date: 2020-03-11
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS HTTP2 Kerberos Largefile NTLM SPNEGO SSL SSPI UnixSockets libz

operating system

Windows 10

@bagder
Copy link
Member

@bagder bagder commented Apr 3, 2020

If you redirect the output somewhere and get the progress meter displayed, can you see how far it gets before it stops? Have you figured out a specific size limit when the problem appears? Do you know if this happens to all/most HTTP/2 servers or just this/a few?

@ajax16384
Copy link
Contributor Author

@ajax16384 ajax16384 commented Apr 4, 2020

  1. unfortunately --progress-bar does not show how far curl consumes input file.
  2. something around 65535 bytes (+- 100 for form prolog epilog). (i guess it's the key for understanding a bug)
  3. almost any http/2 public server (google.com, yandex.ru)
@ajax16384
Copy link
Contributor Author

@ajax16384 ajax16384 commented Apr 4, 2020

@ajax16384
Copy link
Contributor Author

@ajax16384 ajax16384 commented Apr 4, 2020

It seems winsock select() for write on non-block socket can return 0 and WSAGetLastError() == 0 ( just checked wsageetlasterror result then select returns 0). So i have made following changes and schannel starts to post large pieces properly:

      what = SOCKET_WRITABLE(conn->sock[sockindex], timeleft);
      if(what < 0) {
        /* fatal error */
        failf(conn->data, "select/poll on SSL socket, errno: %d", SOCKERRNO);
        *err = CURLE_SEND_ERROR;
        written = -1;
        break;
      }
      /* Non-Block socket may return 0 for select() write check
      else if(0 == what) {
        failf(conn->data, "schannel: timed out sending data "
              "(bytes sent: %zd)", written);
        *err = CURLE_OPERATION_TIMEDOUT;
        written = -1;
        break;
      }
    */
      /* socket is writable */

      result = Curl_write_plain(conn, conn->sock[sockindex], data + written,
                                len - written, &this_write);
      if(result == CURLE_AGAIN)
        continue;
      else if(result != CURLE_OK) {
        *err = result;
        written = -1;
        break;
      }

BTW gopther send buffer implementation also check only fatal error on select() for write: https://github.com/curl/curl/blob/curl-7_69_1/lib/gopher.c#L151

@bagder If you think it's appropriate change then i may create pull request.

@mback2k
Copy link
Member

@mback2k mback2k commented Apr 4, 2020

This should be correctly handled in our wrapper functions Curl_socket_check/Curl_select to make sure that our select calls stay cross-platform compatible (even though schannel of course is only available on Windows). I would like to take a look at this tomorrow.

If the socket is not processing a connect call, writability means a send, sendto, or WSASendto are guaranteed to succeed. However, they can block on a blocking socket if the len parameter exceeds the amount of outgoing system buffer space available. It is not specified how long these guarantees can be assumed to be valid, particularly in a multithreaded environment

Source: https://docs.microsoft.com/en-us/windows/win32/api/winsock2/nf-winsock2-select#remarks

@bagder
Copy link
Member

@bagder bagder commented Apr 4, 2020

I find it highly unlikely that this is a select() issue. We use select with all TLS backends and all protocols so we would get this problem widely and frequently if it was. curl is used on Windows by many users very often after all.

I rather suspect that this is a Schannel specific problem. Like perhaps it doesn't drain the TLS buffers correctly.

@mback2k
Copy link
Member

@mback2k mback2k commented Apr 4, 2020

This is what I was thinking too. But if it is a schannel specific problem, then it should happen regardless of HTTP/2.

@ajax16384
Copy link
Contributor Author

@ajax16384 ajax16384 commented Apr 5, 2020

Some trace info:
curl -v --http1.1 -X POST -H "Expect:" -F "image=@large6MB.bin" "https://nghttp2.org/"

swrite 191
swrite 93
schannel_send 187
swrite 216
schannel_send 65536
swrite 16413
schannel_send 49152
swrite 16413
schannel_send 32768
swrite 16413
swrite 31

curl -v --http2.0 -X POST -H "Expect:" -F "image=@large6MB.bin" "https://nghttp2.org/"

swrite 194
swrite 93
schannel_send 24
swrite 53
schannel_send 27
swrite 56
schannel_send 13
swrite 42
schannel_send 99
swrite 128
schannel_send 16393
swrite 16413
schannel_send 9
swrite 38
schannel_send 16393
swrite 16413
schannel_send 9
swrite 38
schannel_send 16393
swrite 16413
schannel_send 9
swrite 38
schannel_send 16392
swrite 16413
schannel_send 8
swrite 37 <<< select() for write returns 0 before this call
schannel_send 9
swrite 38

So as i mentioned earlier SOCKET_WRITABLE (while doing buffer send routing) was checked for zero only at schannel (gopher does only below zero check). And all Curl_socket_check(writefd) at connection routines treat 0 for nonblock as unfinished connection(non fatal state). May be select(writefd)==0 for nonblock sockets is a valid state?

@bagder
Copy link
Member

@bagder bagder commented Apr 5, 2020

But if it is a schannel specific problem, then it should happen regardless of HTTP/2.

Perhaps, but HTTP/2 creates a pretty unique pattern of use with incoming/outgoing packages that is quite different than HTTP/1, so we've seen several issues in the past only trigger with HTTP/2.

@mback2k
Copy link
Member

@mback2k mback2k commented Apr 5, 2020

Quick question: @ajax16384 why are you talking about non-blocking sockets here? My understanding is that curl is using blocking socket operations with select. cc @bagder, right?

@ajax16384
Copy link
Contributor Author

@ajax16384 ajax16384 commented Apr 5, 2020

@mback2k singleipconnect marks socket with curlx_nonblock as nonblock ( https://github.com/curl/curl/blob/curl-7_69_1/lib/connect.c#L1205 ). That's why swrite-send can fail with WSAEWOULDBLOCK and return CURLE_AGAIN wrom Curl_write_*, so caller may wait and retry operation.

@mback2k
Copy link
Member

@mback2k mback2k commented Apr 5, 2020

Sorry, I am unable to dive deeper into this quickly at the moment, because I have never build curl with HTTP/2 support. Maybe @jay or @MarcelRaad can take a look at this and reproduce the issue?

@bagder
Copy link
Member

@bagder bagder commented Apr 5, 2020

curl is using non-blocking sockets to never risk a blocking network call

@jay
Copy link
Member

@jay jay commented Apr 5, 2020

We don't have decryption for schannel so we can't see the HTTP/2 in wireshark. Schannel decryption involves getting the master key from somewhere in the OS memory. I've read it's possible but it looks time consuming.

I don't have a debugging setup in Windows 10 to reproduce what was reported, maybe Marcel does. My guess is it's actually timing out. The reporter could print the timeout value passed to select before the call and GetTickCount() before and after to see if it's actually timing out.

@ajax16384
Copy link
Contributor Author

@ajax16384 ajax16384 commented Apr 6, 2020

@jay you do not need to involve decryption analysis cause bug happens at encryption state:

>	libcurl.dll!schannel_send(connectdata * conn, int sockindex, const void * buf, unsigned __int64 len, CURLcode * err) Line 1564	C
 	libcurl.dll!send_callback(nghttp2_session * h2, const unsigned char * data, unsigned __int64 length, int flags, void * userp) Line 360	C
 	libcurl.dll!nghttp2_session_send(nghttp2_session * session) Line 3250	C
 	libcurl.dll!h2_session_send(Curl_easy * data, nghttp2_session * h2) Line 1507	C
 	libcurl.dll!http2_send(connectdata * conn, int sockindex, const void * mem, unsigned __int64 len, CURLcode * err) Line 1858	C
 	libcurl.dll!Curl_write(connectdata * conn, unsigned __int64 sockfd, const void * mem, unsigned __int64 len, __int64 * written) Line 349	C
 	libcurl.dll!readwrite_upload(Curl_easy * data, connectdata * conn, int * didwhat) Line 1129	C
 	libcurl.dll!Curl_readwrite(connectdata * conn, Curl_easy * data, bool * done, bool * comeback) Line 1247	C
 	libcurl.dll!multi_runsingle(Curl_multi * multi, curltime now, Curl_easy * data) Line 2091	C
 	libcurl.dll!curl_multi_perform(Curl_multi * multi, int * running_handles) Line 2359	C
 	libcurl.dll!easy_transfer(Curl_multi * multi) Line 602	C
 	libcurl.dll!easy_perform(Curl_easy * data, bool events) Line 691	C
 	libcurl.dll!curl_easy_perform(Curl_easy * data) Line 711	C

as of possible timeout - i guess it's not in this case cause:

a) -w "@curl-format.txt"

time_namelookup: %{time_namelookup} time_connect: %{time_connect} time_appconnect: %{time_appconnect} time_pretransfer: %{time_pretransfer} time_redirect: %{time_redirect} time_starttransfer: %{time_starttransfer} time_total: %{time_total}

and fault request shows:
time_namelookup: 0.004688 time_connect: 0.299161 time_appconnect: 0.892617 time_pretransfer: 0.892932 time_redirect: 0.000000 time_starttransfer: 0.892983 time_total: 0.893292

b) SOCKET_WRITABLE checks socket with timeleft==0, (in both http1.1 and http2 variants). So nonblock socket immediatly return it's state.

@jay
Copy link
Member

@jay jay commented Apr 7, 2020

b) SOCKET_WRITABLE checks socket with timeleft==0, (in both http1.1 and http2 variants). So nonblock socket immediatly return it's state.

Ok. It seems to me technically it is timing out though. select is supposed to return the ready sockets even if 0 timeout (AFAIK). So there is no ready socket and it times out immediately. This is probably a race condition like #1410 which is why you don't see the server reply. We could probably improve on this in schannel. I'm playing around with making the schannel send not block on sending a full record. That requires that the function be called again with the same parameters but we have a similar situation with OpenSSL SSL_write so I'm thinking it should work..

@mback2k
Copy link
Member

@mback2k mback2k commented Apr 10, 2020

Could this error be related? 8843678#comments

I do not get the warning/error then I compile curl using autotools/mingw, but the CMake build on AppVeyor started to fail after that commit.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
4 participants
You can’t perform that action at this time.