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

cURL 8.1.0 POST fails, downgrading to 8.0.1 works as expected #11157

Closed
user8446 opened this issue May 19, 2023 · 30 comments
Closed

cURL 8.1.0 POST fails, downgrading to 8.0.1 works as expected #11157

user8446 opened this issue May 19, 2023 · 30 comments
Assignees
Labels
HTTP/2 Windows Windows-specific

Comments

@user8446
Copy link

user8446 commented May 19, 2023

Hi,

After upgrading to 8.1.0, a simple POST will timeout. The URL does not start with numbers as others have found.

API Call:

curl --request POST --max-time 60 --retry 4 --retry-delay 6 --progress-bar --output nul
    --url "https://api.trello.com/....."

curl: (28) Operation timed out after 60005 milliseconds with 0 bytes received
Warning: Problem : timeout. Will retry in 6 seconds. 4 retries left.
curl: (28) Operation timed out after 60006 milliseconds with 0 bytes received
Warning: Problem : timeout. Will retry in 6 seconds. 3 retries left.
curl: (28) Operation timed out after 60006 milliseconds with 0 bytes received
Warning: Problem : timeout. Will retry in 6 seconds. 2 retries left.
curl: (28) Operation timed out after 60002 milliseconds with 0 bytes received
Warning: Problem : timeout. Will retry in 6 seconds. 1 retries left.
curl: (28) Operation timed out after 60007 milliseconds with 0 bytes received

OS is Windows10

curl 8.1.0 (x86_64-w64-mingw32) libcurl/8.1.0 OpenSSL/3.1.0 (Schannel) zlib/1.2.13 brotli/1.0.9 zstd/1.5.5 WinIDN libssh2/1.10.0 nghttp2/1.53.0 ngtcp2/0.15.0 nghttp3/0.11.0 libgsasl/2.2.0
Release-Date: 2023-05-17
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 ws wss
Features: alt-svc AsynchDNS brotli gsasl HSTS HTTP2 HTTP3 HTTPS-proxy IDN IPv6 Kerberos Largefile libz MultiSSL NTLM SPNEGO SSL SSPI threadsafe UnixSockets zstd

Simply downgrading back to 8.0.1 resolves.

curl 8.0.1 (x86_64-w64-mingw32) libcurl/8.0.1 OpenSSL/3.0.8 (Schannel) zlib/1.2.13 brotli/1.0.9 zstd/1.5.4 WinIDN libssh2/1.10.0 nghttp2/1.52.0 ngtcp2/0.13.1 nghttp3/0.9.0 libgsasl/2.2.0
Release-Date: 2023-03-20
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 ws wss
Features: alt-svc AsynchDNS brotli gsasl HSTS HTTP2 HTTP3 HTTPS-proxy IDN IPv6 Kerberos Largefile libz MultiSSL NTLM SPNEGO SSL SSPI threadsafe TLS-SRP UnixSockets zstd

Does anyone else have this issue? What can I do to help debug?

@AngryPhantom

This comment was marked as off-topic.

@bagder
Copy link
Member

bagder commented May 19, 2023

What can I do to help debug?

First: add -v to the command line and show us more details.

@user8446
Copy link
Author

Thanks, here is the call on v8.1.0:

    curl -v --request POST --max-time 60 `
    --url "https://api.trello.com/1/cards?$APIKEY" `
    --form "idList=$LISTID" `
    --form "pos=top" `
    --form "name=<redacted>" `
    --form "fileSource=@<redacted>.pdf;type=application/pdf"
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 104.192.142.10:443...
* Connected to api.trello.com (104.192.142.10) port 443 (#0)
* ALPN: offers h2,http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
*  CAfile: C:\ProgramData\chocolatey\lib\curl\tools\curl-8.1.0_1-win64-mingw\bin\curl-ca-bundle.crt
*  CApath: none
* 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 h2
* Server certificate:
*  subject: C=AU; ST=New South Wales; L=Sydney; O=Atlassian Pty Ltd; CN=*.trello.com
*  start date: Jan 23 00:00:00 2023 GMT
*  expire date: Feb 23 23:59:59 2024 GMT
*  subjectAltName: host "api.trello.com" matched cert's "*.trello.com"
*  issuer: C=US; O=DigiCert Inc; CN=DigiCert TLS RSA SHA256 2020 CA1
*  SSL certificate verify ok.
* using HTTP/2
* h2 [:method: POST]
* h2 [:scheme: https]
* h2 [:authority: api.trello.com]
* h2 [:path: /1/cards?key=<redacted>&token=<redacted>]
* h2 [user-agent: curl/8.1.0]
* h2 [accept: */*]
* h2 [content-length: 315226]
* h2 [content-type: multipart/form-data; boundary=------------------------e1e8a8d84d1ad85e]
* Using Stream ID: 1 (easy handle 0x231cee5cae0)
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
> POST /1/cards?key=<redacted>&token=<redacted> HTTP/2
> Host: api.trello.com
> User-Agent: curl/8.1.0
> Accept: */*
> Content-Length: 315226
> Content-Type: multipart/form-data; boundary=------------------------e1e8a8d84d1ad85e
>
* We are completely uploaded and fine
* Operation timed out after 60005 milliseconds with 0 bytes received
* Connection #0 to host api.trello.com left intact
curl: (28) Operation timed out after 60005 milliseconds with 0 bytes received

The same call on v8.0.1:

   curl -v --request POST --max-time 60 --output nul `
    --url "https://api.trello.com/1/cards?$APIKEY" `
    --form "idList=$LISTID" `
    --form "pos=top" `
    --form "name=test portcount" `
    --form "fileSource=@C:<redacted>.pdf;type=application/pdf"
Note: Unnecessary use of -X or --request, POST is already inferred.
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying 104.192.142.10:443...
* Connected to api.trello.com (104.192.142.10) port 443 (#0)
* ALPN: offers h2,http/1.1
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
*  CAfile: C:\ProgramData\chocolatey\lib\curl\tools\curl-8.0.1_1-win64-mingw\bin\curl-ca-bundle.crt
*  CApath: none
{ [5 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):
{ [2765 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [80 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 h2
* Server certificate:
*  subject: C=AU; ST=New South Wales; L=Sydney; O=Atlassian Pty Ltd; CN=*.trello.com
*  start date: Jan 23 00:00:00 2023 GMT
*  expire date: Feb 23 23:59:59 2024 GMT
*  subjectAltName: host "api.trello.com" matched cert's "*.trello.com"
*  issuer: C=US; O=DigiCert Inc; CN=DigiCert TLS RSA SHA256 2020 CA1
*  SSL certificate verify ok.
} [5 bytes data]
* using HTTP/2
* h2h3 [:method: POST]
* h2h3 [:path: /1/cards?key=<redacted>&token=<redacted>]
* h2h3 [:scheme: https]
* h2h3 [:authority: api.trello.com]
* h2h3 [user-agent: curl/8.0.1]
* h2h3 [accept: */*]
* h2h3 [content-length: 315226]
* h2h3 [content-type: multipart/form-data; boundary=------------------------d022603cd6cd3fe8]
* Using Stream ID: 1 (easy handle 0x2534d50a650)
} [5 bytes data]
> POST /1/cards?key=<redacted>&token=<redacted> HTTP/2
> Host: api.trello.com
> user-agent: curl/8.0.1
> accept: */*
> content-length: 315226
> content-type: multipart/form-data; boundary=------------------------d022603cd6cd3fe8
>
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [230 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [230 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
 41  307k    0     0   41  128k      0   149k  0:00:02 --:--:--  0:00:02  149k* We are completely uploaded and fine
100  307k    0     0  100  307k      0   113k  0:00:02  0:00:02 --:--:--  113k{ [5 bytes data]
< HTTP/2 200
< date: Fri, 19 May 2023 21:42:44 GMT
< content-type: application/json; charset=utf-8
< content-length: 1526
< x-dns-prefetch-control: off
< expect-ct: max-age=0
< x-frame-options: DENY
< x-download-options: noopen
< x-permitted-cross-domain-policies: none
< referrer-policy: strict-origin-when-cross-origin
< surrogate-control: no-store
< cache-control: max-age=0, must-revalidate, no-cache, no-store
< pragma: no-cache
< expires: Thu, 01 Jan 1970 00:00:00
< x-trello-version: 1.210455.0
< x-trello-environment: Production
< access-control-allow-origin: *
< access-control-allow-methods: GET, PUT, POST, DELETE
< access-control-allow-headers: Authorization, Accept, Content-Type
< access-control-expose-headers: x-rate-limit-api-key-interval-ms, x-rate-limit-api-key-max, x-rate-limit-api-key-remaining, x-rate-limit-api-token-interval-ms, x-rate-limit-api-token-max, x-rate-limit-api-token-remaining
< x-rate-limit-api-token-interval-ms: 10000
< x-rate-limit-api-token-max: 100
< x-rate-limit-api-token-remaining: 99
< x-rate-limit-db-query-time-interval-ms: 600000
< x-rate-limit-db-query-time-max: 7200000
< x-rate-limit-db-query-time-remaining: 7199990
< x-rate-limit-api-key-interval-ms: 10000
< x-rate-limit-api-key-max: 300
< x-rate-limit-api-key-remaining: 299
< x-rate-limit-member-interval-ms: 10000
< x-rate-limit-member-max: 375
< x-rate-limit-member-remaining: 374
< set-cookie: preAuthProps=<redacted>%3AisEnterpriseAdmin%3Dfalse.<redacted>; Path=/; HttpOnly
< x-server-time: 1684532564390
< server: AtlassianEdge
< x-content-type-options: nosniff
< x-xss-protection: 1; mode=block
< atl-traceid: a03cf89b7fba1a8c
< report-to: {"endpoints": [{"url": "https://dz8aopenkvv6s.cloudfront.net"}], "group": "endpoint-1", "include_subdomains": true, "max_age": 600}
< nel: {"failure_fraction": 0.001, "include_subdomains": true, "max_age": 600, "report_to": "endpoint-1"}
< strict-transport-security: max-age=63072000; preload
<
{ [1526 bytes data]
100  309k  100  1526  100  307k    521   105k  0:00:02  0:00:02 --:--:--  105k
* Connection #0 to host api.trello.com left intact

@bagder bagder added the HTTP/2 label May 19, 2023
@bagder
Copy link
Member

bagder commented May 19, 2023

@icing any ideas?

@bagder bagder added the Windows Windows-specific label May 19, 2023
icing added a commit to icing/curl that referenced this issue May 20, 2023
Make send buffer smaller to have progress and "upload done"
reporting closer to reality. Fix handling of send "drain"
condition to no longer trigger once the transfer loop
reports it is done sending. Also do not trigger the send
"drain" on RST streams.

Background:
- a upload stall was reported in curl#11157 that timed out
- test_07_33a reproduces a problem with such a stall if the
  server 404s the request and RSTs the stream.
- test_07_33b verifies a successful PUT, using the parameters
  from curl#11157 and checks success
@icing
Copy link
Contributor

icing commented May 20, 2023

Please see #11165 as a possible fix to address this. I was not able to reproduce exactly this problem, but a related one and fixed that.

In general, it seems your server is missing data from the curl client to send back an answer. Which is rather strange since both requests look the same, apart from the user-agent. I hope we are not dealing with someone sitting in the middle and blackholing us.

@AngryPhantom

This comment was marked as off-topic.

@bagder
Copy link
Member

bagder commented May 20, 2023

@AngryPhantom you have a different issue. Please don't hijack this issue. Yours is probably #11129

@AngryPhantom
Copy link

AngryPhantom commented May 20, 2023

@bagder Oh, I'm sorry, didn't intend to hijack at all, just thought it was relevant (didn't search the issues thoroughly). Ok, will be waiting for the new release. Thank you.

@user8446
Copy link
Author

Once #11165 is implemented is there a snapshot windows binary build available to help test?

bagder pushed a commit that referenced this issue May 20, 2023
Make send buffer smaller to have progress and "upload done" reporting
closer to reality. Fix handling of send "drain" condition to no longer
trigger once the transfer loop reports it is done sending. Also do not
trigger the send "drain" on RST streams.

Background:
- a upload stall was reported in #11157 that timed out
- test_07_33a reproduces a problem with such a stall if the
  server 404s the request and RSTs the stream.
- test_07_33b verifies a successful PUT, using the parameters
  from #11157 and checks success

Ref: #11157
Closes #11165
@bagder
Copy link
Member

bagder commented May 20, 2023

#11165 has been merged now, but I don't know of any provided builds of this for Windows

@vszakats
Copy link
Member

Here are the binaries for the latest curl (and libssh2) master:
https://ci.appveyor.com/project/curlorg/curl-for-win/builds/47099803/artifacts

@user8446
Copy link
Author

Thank you for pointing me in the direction of the latest build.

Unfortunately, #11165 didn't fix.

Using build:

curl-8.1.1-DEV_1d-win64-mingw-test\curl-8.1.1-DEV_1d-win64-mingw\bin\curl.exe -V

curl 8.1.1-DEV (x86_64-w64-mingw32) libcurl/8.1.1-DEV OpenSSL/3.1.0 (Schannel) zlib/1.2.13 brotli/1.0.9 zstd/1.5.5 WinIDN libssh2/1.10.1_DEV nghttp2/1.53.0 ngtcp2/0.15.0 nghttp3/0.11.0 libgsasl/2.2.0
Release-Date: [unreleased]
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 ws wss
Features: alt-svc AsynchDNS brotli gsasl HSTS HTTP2 HTTP3 HTTPS-proxy IDN IPv6 Kerberos Largefile libz MultiSSL NTLM SPNEGO SSL SSPI threadsafe UnixSockets zstd

Same API call:

    curl-8.1.1-DEV_1d-win64-mingw-test\curl-8.1.1-DEV_1d-win64-mingw\bin\curl.exe -v --request POST --max-time 60 `
    --url "https://api.trello.com/1/cards?$APIKEY" `
    --form "idList=$LISTID" `
    --form "pos=top" `
    --form "name=test portcount" `
    --form "fileSource=@C:<redacted>.pdf;type=application/pdf"
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 104.192.142.11:443...
* Connected to api.trello.com (104.192.142.11) port 443 (#0)
* ALPN: offers h2,http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
*  CAfile: curl-8.1.1-DEV_1d-win64-mingw-test\curl-8.1.1-DEV_1d-win64-mingw\bin\curl-ca-bundle.crt
*  CApath: none
* 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 h2
* Server certificate:
*  subject: C=AU; ST=New South Wales; L=Sydney; O=Atlassian Pty Ltd; CN=*.trello.com
*  start date: Jan 23 00:00:00 2023 GMT
*  expire date: Feb 23 23:59:59 2024 GMT
*  subjectAltName: host "api.trello.com" matched cert's "*.trello.com"
*  issuer: C=US; O=DigiCert Inc; CN=DigiCert TLS RSA SHA256 2020 CA1
*  SSL certificate verify ok.
* using HTTP/2
* h2 [:method: POST]
* h2 [:scheme: https]
* h2 [:authority: api.trello.com]
* h2 [:path: /1/cards?key=<redacted>&token=<redacted>]
* h2 [user-agent: curl/8.1.1-DEV]
* h2 [accept: */*]
* h2 [content-length: 315226]
* h2 [content-type: multipart/form-data; boundary=------------------------444a99b68d605bd7]
* Using Stream ID: 1 (easy handle 0x1c5fabaaaf0)
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
> POST /1/cards?key=<redacted>&token=<redacted> HTTP/2
> Host: api.trello.com
> User-Agent: curl/8.1.1-DEV
> Accept: */*
> Content-Length: 315226
> Content-Type: multipart/form-data; boundary=------------------------444a99b68d605bd7
>
* We are completely uploaded and fine
* Operation timed out after 60001 milliseconds with 0 bytes received
* Connection #0 to host api.trello.com left intact
curl: (28) Operation timed out after 60001 milliseconds with 0 bytes received

@icing icing self-assigned this May 22, 2023
icing added a commit to icing/curl that referenced this issue May 22, 2023
- refs curl#11157 and curl#11175 where uploads get stuck or lead to RST streams
- fixes our h2 send behaviour to continue sending in the nghttp2 session
  as long as it wants to. This will empty our send buffer as long as
  the remote stream/connection window allows.
- in case the window is exhausted, the data remaining in the send buffer
  will wait for a WINDOW_UPDATE from the server. Which is a socket event
  that engages our transfer loop again
- the problem in the issue was that we did not exhaust the window, but
  left data in the sendbuffer and no further socket events did happen.
  The server was just waiting for us to send more.
- relatedly, there was an issue fixed that closing a stream with KEEP_HOLD
  set kept the transfer from shutting down - as it should have - leading
  to a timeout.
@icing
Copy link
Contributor

icing commented May 22, 2023

Made myself a trello account and was able to replicate the issue. Curl is indeed stalling on the upload.

Please see #11176 as a fix for this.

@user8446
Copy link
Author

user8446 commented May 22, 2023

Nice work researching and figuring it out!

Once it's merged I'll test as well.

Thank you @icing @bagder @vszakats !

bagder pushed a commit that referenced this issue May 22, 2023
- refs #11157 and #11175 where uploads get stuck or lead to RST streams
- fixes our h2 send behaviour to continue sending in the nghttp2 session
  as long as it wants to. This will empty our send buffer as long as
  the remote stream/connection window allows.
- in case the window is exhausted, the data remaining in the send buffer
  will wait for a WINDOW_UPDATE from the server. Which is a socket event
  that engages our transfer loop again
- the problem in the issue was that we did not exhaust the window, but
  left data in the sendbuffer and no further socket events did happen.
  The server was just waiting for us to send more.
- relatedly, there was an issue fixed that closing a stream with KEEP_HOLD
  set kept the transfer from shutting down - as it should have - leading
  to a timeout.

Closes #11176
@vszakats
Copy link
Member

vszakats commented May 22, 2023

I've made fresh builds here:
https://ci.appveyor.com/project/curlorg/curl-for-win/builds/47111484/artifacts

(I'll see if this can be made automated with reasonable effort.)

@user8446
Copy link
Author

SUCCESS!

   curl-8.1.1-DEV_dev-20230522-win64-mingw-test\curl-8.1.1-DEV_dev-20230522-win64-mingw\bin\curl.exe -v --request POST --max-time 60 --output nul `
    --url "https://api.trello.com/1/cards?$APIKEY" `
    --form "idList=$LISTID" `
    --form "pos=top" `
    --form "name=test" `
    --form "fileSource=@C:<redacted>.pdf;type=application/pdf"
Note: Unnecessary use of -X or --request, POST is already inferred.
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying 104.192.142.9:443...
* Connected to api.trello.com (104.192.142.9) port 443 (#0)
* ALPN: offers h2,http/1.1
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
*  CAfile: curl-8.1.1-DEV_dev-20230522-win64-mingw-test\curl-8.1.1-DEV_dev-20230522-win64-mingw\bin\curl-ca-bundle.crt
*  CApath: none
{ [5 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):
{ [2765 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [79 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 h2
* Server certificate:
*  subject: C=AU; ST=New South Wales; L=Sydney; O=Atlassian Pty Ltd; CN=*.trello.com
*  start date: Jan 23 00:00:00 2023 GMT
*  expire date: Feb 23 23:59:59 2024 GMT
*  subjectAltName: host "api.trello.com" matched cert's "*.trello.com"
*  issuer: C=US; O=DigiCert Inc; CN=DigiCert TLS RSA SHA256 2020 CA1
*  SSL certificate verify ok.
} [5 bytes data]
* using HTTP/2
* h2 [:method: POST]
* h2 [:scheme: https]
* h2 [:authority: api.trello.com]
* h2 [:path: /1/cards?key=<redacted>&token=<redacted>]
* h2 [user-agent: curl/8.1.1-DEV]
* h2 [accept: */*]
* h2 [content-length: 315216]
* h2 [content-type: multipart/form-data; boundary=------------------------d283ea9dec38945b]
* Using Stream ID: 1 (easy handle 0x1a9b961acd0)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [230 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [230 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
> POST /1/cards?key=<redacted>&token=<redacted> HTTP/2
> Host: api.trello.com
> User-Agent: curl/8.1.1-DEV
> Accept: */*
> Content-Length: 315216
> Content-Type: multipart/form-data; boundary=------------------------d283ea9dec38945b
>
  0  307k    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0} [5 bytes data]
* We are completely uploaded and fine
{ [5 bytes data]
< HTTP/2 200
< date: Mon, 22 May 2023 21:57:54 GMT
< content-type: application/json; charset=utf-8
< content-length: 1505
< x-dns-prefetch-control: off
< expect-ct: max-age=0
< x-frame-options: DENY
< x-download-options: noopen
< x-permitted-cross-domain-policies: none
< referrer-policy: strict-origin-when-cross-origin
< surrogate-control: no-store
< cache-control: max-age=0, must-revalidate, no-cache, no-store
< pragma: no-cache
< expires: Thu, 01 Jan 1970 00:00:00
< x-trello-version: 1.210796.0
< x-trello-environment: Production
< access-control-allow-origin: *
< access-control-allow-methods: GET, PUT, POST, DELETE
< access-control-allow-headers: Authorization, Accept, Content-Type
< access-control-expose-headers: x-rate-limit-api-key-interval-ms, x-rate-limit-api-key-max, x-rate-limit-api-key-remaining, x-rate-limit-api-token-interval-ms, x-rate-limit-api-token-max, x-rate-limit-api-token-remaining
< x-rate-limit-api-token-interval-ms: 10000
< x-rate-limit-api-token-max: 100
< x-rate-limit-api-token-remaining: 99
< x-rate-limit-db-query-time-interval-ms: 600000
< x-rate-limit-db-query-time-max: 7200000
< x-rate-limit-db-query-time-remaining: 7199990
< x-rate-limit-api-key-interval-ms: 10000
< x-rate-limit-api-key-max: 300
< x-rate-limit-api-key-remaining: 299
< x-rate-limit-member-interval-ms: 10000
< x-rate-limit-member-max: 375
< x-rate-limit-member-remaining: 374
< set-cookie: preAuthProps=<redacted>; Path=/; HttpOnly
< x-server-time: 1684792674677
< server: AtlassianEdge
< x-content-type-options: nosniff
< x-xss-protection: 1; mode=block
< atl-traceid: 92b5b117c8ce1fd9
< report-to: {"endpoints": [{"url": "https://dz8aopenkvv6s.cloudfront.net"}], "group": "endpoint-1", "include_subdomains": true, "max_age": 600}
< nel: {"failure_fraction": 0.001, "include_subdomains": true, "max_age": 600, "report_to": "endpoint-1"}
< strict-transport-security: max-age=63072000; preload
<
{ [1505 bytes data]
100  309k  100  1505  100  307k    579   118k  0:00:02  0:00:02 --:--:--  119k
* Connection #0 to host api.trello.com left intact

Thank you again!

@bagder
Copy link
Member

bagder commented May 22, 2023

thanks @icing and @vszakats, great work!

@vszakats
Copy link
Member

vszakats commented May 23, 2023

I've added daily curl-for-win builds as an experiment. Runs at 20:29 UTC, with the current latest curl (and libssh2, and curl-for-win) sources. One download artifact is ~50MB. They are retained for 42 days. Let me know if any tweaks would these more useful:
https://github.com/curl/curl-for-win/actions/workflows/daily.yml

Binary package:
https://github.com/curl/curl-for-win/suites/13093591264/artifacts/710693106

They may be useful to check Windows-specific compiler warning/error fallouts, or verifying patch results like in this thread.

@user8446
Copy link
Author

Bookmarked, thank you @vszakats

@mohd-akram
Copy link

mohd-akram commented May 28, 2023

EDIT: The patch in 5c58cb0 resolves this issue. Hope it's released soon.

This is still an issue in curl 8.1.1 that I'm experiencing through git. git gets stuck when trying to push a large commit.

Curl version:

curl 8.1.1 (x86_64-apple-darwin22.5.0) libcurl/8.1.1 OpenSSL/3.1.0 zlib/1.2.13 brotli/1.0.9 zstd/1.5.5 libidn2/2.3.4 libpsl/0.21.2 (+libidn2/2.3.4) nghttp2/1.53.0
Release-Date: 2023-05-23
Protocols: dict file ftp ftps gopher gophers http https imap imaps mqtt pop3 pop3s rtsp smb smbs smtp smtps telnet tftp
Features: alt-svc AsynchDNS brotli HSTS HTTP2 HTTPS-proxy IDN IPv6 Largefile libz NTLM NTLM_WB PSL SSL threadsafe TLS-SRP UnixSockets zstd

Git version:

git version 2.40.1

Log:

22:57:24.876021 http.c:646              => Send header, 0000000359 bytes (0x00000167)
22:57:24.876043 http.c:658              => Send header: POST /user/repo.git/git-receive-pack HTTP/2
22:57:24.876050 http.c:658              => Send header: Host: github.com
22:57:24.876056 http.c:658              => Send header: Authorization: Basic <redacted>
22:57:24.876061 http.c:658              => Send header: User-Agent: git/2.40.1
22:57:24.876067 http.c:658              => Send header: Accept-Encoding: deflate, gzip, br, zstd
22:57:24.876072 http.c:658              => Send header: Content-Type: application/x-git-receive-pack-request
22:57:24.876076 http.c:658              => Send header: Accept: application/x-git-receive-pack-result
22:57:24.876080 http.c:658              => Send header: Accept-Language: en-US, *;q=0.9
22:57:24.876084 http.c:658              => Send header:
Writing objects: 100% (1145/1145), 1.57 MiB | 1.70 MiB/s, done.
Total 1145 (delta 1127), reused 249 (delta 243), pack-reused 0
22:57:37.209255 http.c:646              <= Recv header, 0000000013 bytes (0x0000000d)
22:57:37.209299 http.c:658              <= Recv header: HTTP/2 408
22:57:37.209316 http.c:646              <= Recv header, 0000000026 bytes (0x0000001a)
22:57:37.209330 http.c:658              <= Recv header: server: GitHub-Babel/3.0
22:57:37.209345 http.c:646              <= Recv header, 0000000054 bytes (0x00000036)
22:57:37.209360 http.c:658              <= Recv header: content-security-policy: default-src 'none'; sandbox
22:57:37.209386 http.c:646              <= Recv header, 0000000041 bytes (0x00000029)
22:57:37.209410 http.c:658              <= Recv header: content-type: text/plain; charset=UTF-8
22:57:37.209420 http.c:646              <= Recv header, 0000000019 bytes (0x00000013)
22:57:37.209428 http.c:658              <= Recv header: content-length: 0
22:57:37.209436 http.c:646              <= Recv header, 0000000037 bytes (0x00000025)
22:57:37.209442 http.c:658              <= Recv header: date: Sun, 28 May 2023 18:57:37 GMT
22:57:37.209450 http.c:646              <= Recv header, 0000000023 bytes (0x00000017)
22:57:37.209455 http.c:658              <= Recv header: x-frame-options: DENY
22:57:37.209462 http.c:646              <= Recv header, 0000000055 bytes (0x00000037)
22:57:37.209468 http.c:658              <= Recv header: x-github-request-id: DE1A:60AC:D35E15:F7FE37:6473A415
22:57:37.209478 http.c:699              == Info: HTTP error before end of send, stop sending
22:57:37.209488 http.c:646              <= Recv header, 0000000002 bytes (0x00000002)
22:57:37.209527 http.c:658              <= Recv header:

@icing
Copy link
Contributor

icing commented May 28, 2023

Release 8.1.2 is planed for Tuesday.

@user8446
Copy link
Author

user8446 commented Jun 2, 2023

Unfortunately I sometimes still see the issue in 8.1.2 as well. It seems random:

curl -v --request POST --max-time 20 --progress-bar --output nul `
    --url "https://api.trello.com/1/cards?$APIKEY" `
    --form "idList=$LISTID" `
    --form "pos=top" `
    --form "name=test" `
    --form "fileSource=@C:<redacted>.pdf;type=application/pdf"
Note: Unnecessary use of -X or --request, POST is already inferred.
*   Trying 104.192.142.11:443...
* Connected to api.trello.com (104.192.142.11) port 443 (#0)
* ALPN: offers h2,http/1.1
} [5 bytes data]
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
} [512 bytes data]
*  CAfile: C:\ProgramData\chocolatey\lib\curl\tools\curl-8.1.2_1-win64-mingw\bin\curl-ca-bundle.crt
*  CApath: none
{ [5 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):
{ [2765 bytes data]
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
{ [80 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 h2
* Server certificate:
*  subject: C=AU; ST=New South Wales; L=Sydney; O=Atlassian Pty Ltd; CN=*.trello.com
*  start date: Jan 23 00:00:00 2023 GMT
*  expire date: Feb 23 23:59:59 2024 GMT
*  subjectAltName: host "api.trello.com" matched cert's "*.trello.com"
*  issuer: C=US; O=DigiCert Inc; CN=DigiCert TLS RSA SHA256 2020 CA1
*  SSL certificate verify ok.
} [5 bytes data]
* using HTTP/2
* h2 [:method: POST]
* h2 [:scheme: https]
* h2 [:authority: api.trello.com]
* h2 [:path: /1/cards?key=<redacted>&token=<redacted>]
* h2 [user-agent: curl/8.1.2]
* h2 [accept: */*]
* h2 [content-length: 323337]
* h2 [content-type: multipart/form-data; boundary=------------------------8b5add20126e4d09]
* Using Stream ID: 1 (easy handle 0x1e34e49a980)
{ [5 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [230 bytes data]
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
{ [230 bytes data]
* old SSL session ID is stale, removing
{ [5 bytes data]
> POST /1/cards?key=<redacted>&token=<redacted> HTTP/2
> Host: api.trello.com
> User-Agent: curl/8.1.2
> Accept: */*
> Content-Length: 323337
> Content-Type: multipart/form-data; boundary=------------------------8b5add20126e4d09
>
} [5 bytes data]
#####################################################################################################                                                                    60.8%* We are completely uploaded and fine
####################################################################################################################################################################### 100.0%* Operation timed out after 20011 milliseconds with 0 bytes received
* Connection #0 to host api.trello.com left intact
curl: (28) Operation timed out after 20011 milliseconds with 0 bytes received

PS> curl -V
curl 8.1.2 (x86_64-w64-mingw32) libcurl/8.1.2 OpenSSL/3.1.0 (Schannel) zlib/1.2.13 brotli/1.0.9 zstd/1.5.5 WinIDN libssh2/1.10.0 nghttp2/1.53.0 ngtcp2/0.15.0 nghttp3/0.11.0 libgsasl/2.2.0
Release-Date: 2023-05-30
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 ws wss
Features: alt-svc AsynchDNS brotli gsasl HSTS HTTP2 HTTP3 HTTPS-proxy IDN IPv6 Kerberos Largefile libz MultiSSL NTLM SPNEGO SSL SSPI threadsafe UnixSockets zstd

@icing
Copy link
Contributor

icing commented Jun 3, 2023

My question would be if there are situations where the trello API takes long time to process an uploaded document and your 20 seconds are not sufficient.

When the message "We are completely uploaded and fine" is printed, curl 8.1.2 has sent the complete request body and the EOF indicator to the server. After that it is waiting for the server to send the response. That does not seem to happen sometimes for you.

There might still be an unforeseen condition lurking here. But I would be interested to know what results you get with a timeout of 60 seconds or more.

@user8446
Copy link
Author

user8446 commented Jun 3, 2023

In my script I actually have a 60 second timeout:

curl --request POST --max-time 60 --retry 4 --retry-delay 6 --progress-bar --output nul

When it timed out, I ran it manually and didn't want to wait for all of the retries so I shortened the time. It really is random as I used the exact same file to upload and a few tries later it works.

@icing
Copy link
Contributor

icing commented Jun 4, 2023

Thanks. What is the CPU usage you see while curl is timing out? I'd expect this to be almost 0, but we have #11242 reported, just checking.

@user8446
Copy link
Author

user8446 commented Jun 5, 2023

Ok I will check on the next incident

@icing
Copy link
Contributor

icing commented Jun 5, 2023

I just re-created my TRELLO API key and tokens for testing and when I try your upload example of a document, it takes a long time for trello to send me back:

< HTTP/2 503
< date: Mon, 05 Jun 2023 15:32:32 GMT
< content-type: text/plain
< content-length: 95
< server: AtlassianEdge
< x-content-type-options: nosniff
< x-xss-protection: 1; mode=block
< atl-traceid: 84ea8d86501f0886
< report-to: {"endpoints": [{"url": "https://dz8aopenkvv6s.cloudfront.net"}], "group": "endpoint-1", "include_subdomains": true, "max_age": 600}
< nel: {"failure_fraction": 0.001, "include_subdomains": true, "max_age": 600, "report_to": "endpoint-1"}
* Parsed STS header fine (1 entries)
< strict-transport-security: max-age=63072000; preload

which points to a problem on the server side. Not sure, if this helps. But may you can reproduce when you test without timeout.

@user8446
Copy link
Author

user8446 commented Jun 5, 2023

Thank you for testing... was it longer than 60 seconds for the response? That is what I have in production and when it did fail all 4 retries at 60 seconds would fail.

@icing
Copy link
Contributor

icing commented Jun 5, 2023

What I see is, for example:

18:21:53.543501 * We are completely uploaded and fine
...
18:22:53.894887 < HTTP/2 503

@user8446
Copy link
Author

user8446 commented Jun 5, 2023

Thanks, I will report back on the next incident

bch pushed a commit to bch/curl that referenced this issue Jul 19, 2023
Make send buffer smaller to have progress and "upload done" reporting
closer to reality. Fix handling of send "drain" condition to no longer
trigger once the transfer loop reports it is done sending. Also do not
trigger the send "drain" on RST streams.

Background:
- a upload stall was reported in curl#11157 that timed out
- test_07_33a reproduces a problem with such a stall if the
  server 404s the request and RSTs the stream.
- test_07_33b verifies a successful PUT, using the parameters
  from curl#11157 and checks success

Ref: curl#11157
Closes curl#11165
bch pushed a commit to bch/curl that referenced this issue Jul 19, 2023
- refs curl#11157 and curl#11175 where uploads get stuck or lead to RST streams
- fixes our h2 send behaviour to continue sending in the nghttp2 session
  as long as it wants to. This will empty our send buffer as long as
  the remote stream/connection window allows.
- in case the window is exhausted, the data remaining in the send buffer
  will wait for a WINDOW_UPDATE from the server. Which is a socket event
  that engages our transfer loop again
- the problem in the issue was that we did not exhaust the window, but
  left data in the sendbuffer and no further socket events did happen.
  The server was just waiting for us to send more.
- relatedly, there was an issue fixed that closing a stream with KEEP_HOLD
  set kept the transfer from shutting down - as it should have - leading
  to a timeout.

Closes curl#11176
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
HTTP/2 Windows Windows-specific
Development

No branches or pull requests

6 participants