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

h2/h2c: better error handling when CURL_MAX_HTTP_HEADER is exceeded #16535

Closed
starrify opened this issue Mar 2, 2025 · 15 comments
Closed

h2/h2c: better error handling when CURL_MAX_HTTP_HEADER is exceeded #16535

starrify opened this issue Mar 2, 2025 · 15 comments
Assignees
Labels

Comments

@starrify
Copy link
Contributor

starrify commented Mar 2, 2025

I did this

Using curl for an h2/h2c request where the web server unexpectedly sends a header larger than CURL_MAX_HTTP_HEADER (currently 100 KB).

Observed behavior:

  • Case 1: When the header payload slightly goes beyond CURL_MAX_HTTP_HEADER (e.g. 101 KB), curl aborts the response with: curl: (56) process_pending_input: nghttp2_session_mem_recv() returned -902:The user callback function failed which may be not clear enough.
  • Case 2: When the header payload is larger (e.g. 105 KB), curl blocks indefinitely until either party terminates the underlying TCP connection due to timeout (e.g. curl: (16) Error in the HTTP2 framing layer).

A PoC web server

(click to expand)

nginx.conf (requires the njs module):

daemon off;
pid /tmp/nginx.pid;
load_module /usr/lib/nginx/modules/ngx_http_js_module.so;

events {
}

http {
  access_log /dev/stderr;

  server {
    listen localhost:8080;
    http2 on;

    js_import foo.js;
    js_set $foo foo;

    location ~ / {
      add_header "foo" $foo;
      return 200 "foobar";
    }
  }
}

foo.js:

export default (req) => {
  const targetSize = parseInt(req.uri.split("/").pop());
  return "a".repeat(targetSize);
}

To launch the service:

$ nginx -c $(pwd)/nginx.conf

Reproducing the issue (with the above PoC web server)

Case 0: 99 KB -- good

$ curl localhost:8080/foo/101376 --http2-prior-knowledge -v 2>&1 | grep '^< foo:' | wc
      1       3  101385

Case 1: 101 KB -- could use better error message

$ curl http://localhost:8080/foo/103424 --http2-prior-knowledge
curl: (56) process_pending_input: nghttp2_session_mem_recv() returned -902:The user callback function failed

Case 2: 105 KB -- blocks indefinitely (until timeout)

$ time curl http://localhost:8080/foo/107520 --http2-prior-knowledge
curl: (16) Error in the HTTP2 framing layer

real	1m15.042s
user	0m0.004s
sys	0m0.002s

I expected the following

Expected behavior:

  • curl shall not block indefinitely.
  • curl shall emit an error message that better indicate the cause of issue.

BTW with HTTP/1.1 curl handles this properly and emits the CURLE_TOO_LARGE error message.

curl/libcurl version

Said behavior may be reproduced using my distro's curl release at 8.12.1:

$ curl -V
curl 8.12.1 (x86_64-pc-linux-gnu) libcurl/8.12.1 OpenSSL/3.4.1 zlib/1.3.1 brotli/1.1.0 zstd/1.5.7 libidn2/2.3.7 libpsl/0.21.5 libssh2/1.11.1 nghttp2/1.64.0 nghttp3/1.8.0
Release-Date: 2025-02-13
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns mqtt pop3 pop3s rtsp scp sftp smb smbs smtp smtps telnet tftp ws wss
Features: alt-svc AsynchDNS brotli GSS-API HSTS HTTP2 HTTP3 HTTPS-proxy IDN IPv6 Kerberos Largefile libz NTLM PSL SPNEGO SSL threadsafe TLS-SRP UnixSockets zstd

Also using a local build at df67269:

$ ./src/curl -V
curl 8.13.0-DEV (x86_64-pc-linux-gnu) libcurl/8.13.0-DEV OpenSSL/3.4.1 zlib/1.3.1 brotli/1.1.0 zstd/1.5.7 libidn2/2.3.7 libpsl/0.21.5 nghttp2/1.64.0 librtmp/2.3 OpenLDAP/2.6.9
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher gophers http https imap imaps ipfs ipns ldap ldaps mqtt pop3 pop3s rtmp rtsp smb smbs smtp smtps telnet tftp ws wss
Features: alt-svc AsynchDNS brotli HSTS HTTP2 HTTPS-proxy IDN IPv6 Largefile libz NTLM PSL SSL threadsafe TLS-SRP UnixSockets zstd

operating system

Linux ingoldo 6.13.5-arch1-1 #1 SMP PREEMPT_DYNAMIC Thu, 27 Feb 2025 18:09:44 +0000 x86_64 GNU/Linux
@bagder bagder added the HTTP/2 label Mar 2, 2025
starrify added a commit to starrify/curl that referenced this issue Mar 2, 2025
This is a partial fix of curl#16535. The error message format is borrowed
from the existing code[1].

Sample message before:
    curl: (56) process_pending_input: nghttp2_session_mem_recv() returned -902:The user callback function failed

Sample message after:
    curl: (56) Error receiving HTTP2 header: 100(A value or data field grew larger than allowed)

[1]: https://github.com/curl/curl/blob/df672695e5992ad9b99819e9950de682e243cb48/lib/http2.c#L1999-L2000
starrify added a commit to starrify/curl that referenced this issue Mar 2, 2025
This is a partial fix of curl#16535. The error message format is borrowed
from the existing code[1].

Sample message before:
    curl: (56) process_pending_input: nghttp2_session_mem_recv() returned -902:The user callback function failed

Sample message after:
    curl: (56) Error receiving HTTP2 header: 100(A value or data field grew larger than allowed)

[1]: https://github.com/curl/curl/blob/df672695e5992ad9b99819e9950de682e243cb48/lib/http2.c#L1999-L2000
bagder pushed a commit that referenced this issue Mar 3, 2025
This is a partial fix of #16535. The error message format is borrowed
from the existing code[1].

Sample message before:
    curl: (56) process_pending_input: nghttp2_session_mem_recv() returned -902:The user callback function failed

Sample message after:
    curl: (56) Error receiving HTTP2 header: 100(A value or data field grew larger than allowed)

[1]: https://github.com/curl/curl/blob/df672695e5992ad9b99819e9950de682e243cb48/lib/http2.c#L1999-L2000

Closes #16536
@icing icing self-assigned this Mar 3, 2025
@icing
Copy link
Contributor

icing commented Mar 3, 2025

In my testing, the server never seems to send the response header frame and curl just waits for a reply.

Can you increase the tracing in curl via -vvv and have a look what FRAMEs are sent and received in your setup? Thanks.

@starrify
Copy link
Contributor Author

starrify commented Mar 3, 2025

Hi @icing , thanks for helping look into this! Please find attached a local traffic capture on the sample request described above: a2.pcap.zip
(zipped because GitHub doesn't seem to accept .pcap files)

From the traffic capture it may be observed that:

  1. The server does not include that foo: header within the HEADERS frame.
  2. Instead it sends CONTINUATION frames for that header.
  3. Both of which above are understandable due to the large size. (same behavior also for the other cases like 99 KB).
  4. The client then sends GOAWAY prior to the server's finishing the request (subsequent CONTINUATION frames for that header + DATA frame for the body). (edit: also it has got the COMPRESSION_ERROR error code included.)

Thus I would assume it's an issue related to nghttp2, which might come from either nghttp2 itself or curl's configuration of it.

Besides, the sample server appears to work properly with other HTTP clients (e.g. Chromium[1]) with the 105 KB case.

[1]: That won't work directly though due to the lack of h2c support. That however may be verified by introducing TLS+ALPN (e.g. to add a self-signed cert to the Nginx configuration or to put that service behind a TLS terminator) to suggest h2.

@icing
Copy link
Contributor

icing commented Mar 3, 2025

@starrify just for clarification: you do not see curl "hanging", it gets the headers, errors and sends GOAWAY? (And I assume the curl command exist code is 16 - at least in my tests).

@starrify
Copy link
Contributor Author

starrify commented Mar 3, 2025

Hi, sorry for the confusion. It indeed appears to be hanging to me.

Please also refer to the traffic capture shared above:

  1. curl sends GOAWAY whilst receiving the header (before the server finishes sending them).
  2. curl then stays idle (hanging) for more than 60 seconds. (edit: it could, and should IMO, terminate the TCP connection at this stage already)
  3. At around T+62s the client sends TCP keepalive which the server acks.
  4. At around T+75s the server sends GOAWAY then terminates the TCP connection.

After that curl exits by emitting the curl: (16) Error in the HTTP2 framing layer error message and the exit code is 16.

@icing
Copy link
Contributor

icing commented Mar 3, 2025

Thanks, I see now the delay in the pcap. Hmm, but that does not tell me what curl is doing here. Curl wants to terminate the transfer (that is why it sends the GOAWAY), but somehow stumbles during the CONTINUATION frames incoming.

Could you produce a trace with -vvv? That would give me more insight. Thanks!

Update: I have an idea and will make a PR.

icing added a commit to icing/curl that referenced this issue Mar 3, 2025
refs curl#16535

We send a GOAWAY, but some servers ignore that and happily continue
sending the stream response. RST the stream when response header
errors are encountered.
@icing
Copy link
Contributor

icing commented Mar 3, 2025

@starrify can you check if #16544 solves the issue for you?

@starrify
Copy link
Contributor Author

starrify commented Mar 3, 2025

Hi @icing sorry for the delay and thanks for the follow-up work!

Please find attached here the -vvv log from my curl installation (8.12.1): a.log
(recorded via curl http://localhost:8080/foo/1075200 --http2-prior-knowledge -vvv 2> a3.log)

Please find attached here the respective -vvv log and traffic capture from a local build of your branch at ff28c1e (same command): ff28c1e8e.log ff28c1e8e.pcap.zip

With the local build the issue persists (hanging for ~75s / curl doesn't seem to terminate the connection after sending that GOAWAY frame).

@icing
Copy link
Contributor

icing commented Mar 4, 2025

@starrify having some problems piecing things together here:

  • the ff28c1e.log and pcap files to not really match up. In the log, a GOAWAY frame is sent by curl, but this does not appear in the pcap.
  • the ff28c1e.log does not show any of the error message that your PR added for reporting failure.

Could you double check that the log is actually produced by a curl with #16544 and that the pcap file matches? Thanks.

@starrify
Copy link
Contributor Author

starrify commented Mar 4, 2025

Hi @icing , hmm that's weird. I do see the client-sent GOAWAY frame. Sample output from tshark:

$ tshark -nr ff28c1e8e.pcap -Y 'tcp.dstport == 8080 && http2.type == 7'
   16   0.014297    127.0.0.1 → 127.0.0.1    HTTP2 83 0 [TCP ZeroWindow] , GOAWAY[0]

Sample output from wireshark:

Image

Just in case I happened to have sent a wrong file, could you please also verify that the SHA256 checksum of ff28c1e8e.pcap is a86e4eda51f370ae28756dd0aede02f7c6961d01c348412123a98f4c9eb4d557?

Could you double check that the log is actually produced by a curl with #16544

I went verifying my shell history and to the best of my knowledge it is indeed at that branch where I made a local build and recorded the ff28c1e8e.{log,pcap} files.

the https://github.com/curl/curl/commit/ff28c1e8e077be4c9e44702414b0c2c1591339bd.log does not show any of the error message that your PR added for reporting failure.

Hmm.. I do not expect it to. In the main text of this issue report I described two cases observed. My other PR specifically targets case 1 (e.g. 101 KB payload) and here we've been talking about case 2 (e.g. 105 KB payload). I would assume that this is also the reason why #16544 doesn't fix it.

@icing
Copy link
Contributor

icing commented Mar 4, 2025

Tried to get the sample server running locally, but the installation instructions for ngx_http_js_module.so do not work on a modern debian. sigh

icing added a commit to icing/curl that referenced this issue Mar 4, 2025
refs curl#16535

We send a GOAWAY, but some servers ignore that and happily continue
sending the stream response. RST the stream when response header
errors are encountered.
@icing
Copy link
Contributor

icing commented Mar 4, 2025

@starrify I made additions to #16544 so that we detect nghttp2 having shut down the connection and react properly. Could you verify this in your setup? I believe this should now fix nginx ignoring the GOAWAY.

@starrify
Copy link
Contributor Author

starrify commented Mar 4, 2025

Hi @icing I'm sorry for the inconvenience. :( That PR at 819733b indeed seems to fix the issue, where curl sends a RST immediately following that GOAWAY. Thanks a lot for the help! :)

Attached for reference are the same -vvv logs and traffic capture for the same sample payload: 819733b51.pcap.zip / 819733b51.log

@icing
Copy link
Contributor

icing commented Mar 5, 2025

Thanks for confirming!

@bagder
Copy link
Member

bagder commented Mar 5, 2025

That's a 👍 for #16544, right?

@icing
Copy link
Contributor

icing commented Mar 5, 2025

Yes.

@bagder bagder closed this as completed in e7de83a Mar 5, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Development

No branches or pull requests

3 participants