curl(1) enters busy loop if header size >= 64KB (HTTP2 only)

[kazuho]

curl command seems to enter a busy loop if the size of header becomes greater than 65,534 bytes when HTTP/2 is used.

Steps to reproduce:

1. build h2o 1.7.0
2. run h2o with following configuration
3. run curl -k https://127.0.0.1:8081/

listen:
  port: 8081
  ssl:
    key-file: examples/h2o/server.key
    certificate-file: examples/h2o/server.crt
hosts:
  default:
    paths:
      /:
        mruby.handler: |
          Proc.new do |env|
            [200, {"x-foo" => "1" * 65530}, []]
          end

The command runs as expected if the size of the header value is 65,529 bytes.

EDIT: I am using curl 7.47.1 with nghttp2 @ 094168a on OS X 10.9.5.

[kazuho]

Similar issue seems to exist for the handling of request haeder as well.

When I use this configuration file for h2o (note: this one does not send a huge response header) and access the server with: curl -k -v -H foo:$(perl -e 'print "0"x16384') https://127.0.0.1:8081, the command enters an infinite loop.
It is likely a issue within the HTTP/2 implementation of curl, since nghttp command is capable of issuing a similar request (by running nghttp -v -H foo:$(perl -e 'print "0"x16384') https://127.0.0.1:8081/).

[jay]

It looks like anything over 16300 here. What's your curl -V?

curl 7.47.1 (x86_64-pc-linux-gnu) libcurl/7.47.1 OpenSSL/1.0.2f zlib/1.2.8 libidn/1.28 nghttp2/1.7.1 librtmp/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp smb smbs smtp smtps telnet tftp 
Features: IDN IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets 

[kazuho]

@jay Thank you for looking into this.

curl 7.47.1 (x86_64-apple-darwin13.4.0) libcurl/7.47.1 OpenSSL/1.0.2f zlib/1.2.5 nghttp2/1.8.0-DEV
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtsp smb smbs smtp smtps telnet tftp 
Features: IPv6 Largefile NTLM NTLM_WB SSL libz HTTP2 UnixSockets 

[jay]

I walked through it but I don't know what's causing it yet. I am looking at the case where a header larger than 16384 is sent by libcurl via http2. The header is broken into pieces if it's over 16384,
https://github.com/curl/curl/blob/curl-7_47_1/lib/http.c#L1148-L1173
Then later on when state perform it goes to send the rest of the header by calling readwrite_upload:
https://github.com/curl/curl/blob/curl-7_47_1/lib/transfer.c#L1080-L1086
which calls Curl_write
https://github.com/curl/curl/blob/curl-7_47_1/lib/sendf.c#L230
which calls http2_send, which does some code expecting that the headers have already been sent
https://github.com/curl/curl/blob/curl-7_47_1/lib/http2.c#L1341-L1370
but they haven't been fully sent. so I take it there shouldn't be a stream id at that point. probably at some earlier point it thinks it's done sending the headers.

the end result of this is it sends the leftover headers thinking it's the body. send keeps returning 0 and it keeps looping (expecting it will eventually return the amount sent). this is my output with a debug build of libcurl:

* nread <= 0, server closed connection, bailing
* http2_send len=62
* http2_send returns 0 for stream 1
* http2_send len=62
* http2_send returns 0 for stream 1
* http2_send len=62
* http2_send returns 0 for stream 1
* http2_send len=62
* http2_send returns 0 for stream 1
* http2_send len=62

62 is the leftover header data size.

[tatsuhiro-t]

I'll look into the receiver side.

[tatsuhiro-t]

The original issue @kazuho reported: First I has to mention that the maximum size of one header field (sum of name and value) when receiving header fields in libnghttp2 is limited to 65536 bytes.
The value is hard coded for now (we can make it configurable if it is desirable). h2o sends "x-foo" + "1"*65530, which in total 65535 bytes. libnghttp2 makes name and value NULL-terminated string, so it appends '\0' for each name and value. This exceeds the maximum buffer size, and libnghttp2 is going to fail HTTP/2 session. When libnghttp2 thought the underlying session now can be closed (GOAWAY frame was sent), nghttp2_session_want_read(...) ==0 && nghttp2_session_want_write(...) == 0 gets true. The thing is http2_recv does not check this condition, and always keep checking readability of socket, which enters loop. So I think one way to fix this issue is check the above condition in http2_recv like so:

diff --git a/lib/http2.c b/lib/http2.c
index 91abbf0..9d63cd9 100644
--- a/lib/http2.c
+++ b/lib/http2.c
@@ -1133,6 +1133,13 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex,
   if(stream->memlen == 0 && stream->closed) {
     return http2_handle_stream_close(conn, data, stream, err);
   }
+  if(!nghttp2_session_want_read(httpc->h2) &&
+     !nghttp2_session_want_write(httpc->h2)) {
+    if(stream->error_code == NGHTTP2_NO_ERROR) {
+      stream->error_code = NGHTTP2_INTERNAL_ERROR;
+    }
+    return http2_handle_stream_close(conn, data, stream, err);
+  }

   /* Nullify here because we call nghttp2_session_send() and they
      might refer to the old buffer. */

[tatsuhiro-t]

The second issue, that is curl hangs when it is instructed to send 16384 header value.
This is because I assumed that whole HTTP/1 header block is passed to http2_send function.
But it turns out that it is not true when TLS is enabled. The relevant portion of the code is

curl/lib/http.c

Line 1094 in 7139848

if(conn->handler->flags & PROTOPT_SSL) {

This is required when we are dealing with TLS layer directly. But in HTTP/2, the we don't require this 16KiB limit here, since it is nghttp2 callback that deals with TLS layer. So simple fix for this issue is handle HTTP/2 case specially like so:

diff --git a/lib/http.c b/lib/http.c
index 62952a8..1efdb75 100644
--- a/lib/http.c
+++ b/lib/http.c
@@ -1091,7 +1091,7 @@ CURLcode Curl_add_buffer_send(Curl_send_buffer *in,
   }


-  if(conn->handler->flags & PROTOPT_SSL) {
+  if(conn->httpversion != 20 && conn->handler->flags & PROTOPT_SSL) {
     /* We never send more than CURL_MAX_WRITE_SIZE bytes in one single chunk
        when we speak HTTPS, as if only a fraction of it is sent now, this data
        needs to fit into the normal read-callback buffer later on and that

[tatsuhiro-t]

While #659 (comment) fixes the original issue, but I'm not sure why returning error from http2_recv triggers HTTP/2 connection closure. This is stream error, and only the relevant stream is affected. It looks like the current implementation treats stream error as connection error.

[jay]

@tatsuhiro-t Thanks, the sending fix landed in b080a7c.

Regarding the receiving fix, I read the API (1.8.0-dev) and it seems to contradict that this is only a stream error:

If both nghttp2_session_want_read() and nghttp2_session_want_write() return 0, the application should drop the connection.

So if libcurl is triggering connection closure, wouldn't that be appropriate for this case?

[tatsuhiro-t]

@jay Yes, you are correct regarding those APIs. Sorry for the confusion, my point is the case where at least one of APIs returns false, and stream was closed with other than NGHTTP2_NO_ERROR (e.g., NGHTTP2_PROTOCOL_ERROR). This is stream level error and dropping connection is not required. The current implementation returns CURLE_HTTP2 in this case (code). In multi interface, we ended up here, and underlying TCP connection is dropped. This is not desirable, if we imagine that several streams are flowing, and only one stream is closed with stream error. There is no reason to close other streams which they are completely fine.
One possible solution is introduce new error code to tell upper layer that this is stream error, and no need to close TCP connection.

At this point, I've only checked the code path when reading from network. But stream closure can happen on sending side. I'll check what happens in sending side with stream error.

[tatsuhiro-t]

PR #663 is better version to fix the original issue. It also handles the case where one RST_STREAM kills entire session that I mentioned in the previous post. You might not like additional error code (including its naming). We can discuss that here.

I have not fully understand whether we need similar check (nghttp2_session_want_read() and nghttp2_session_want_write()) in http2_send. Somehow after http2_send, http2_recv is called, so apparently we don't need them. But I'm not sure. Anyway, the PR improves the situation a bit in receiver side.

[jay]

#663 looks good but:

The new option needs to be tied in a few places (libcurl-errors.3, strerror, etc). I can do that though it's fine.

I'd prefer leaving CURLE_HTTP2 documented as is. Saying it's now a connection only error closes some doors.

I notice you moved the check for nghttp2_session_want_read() and nghttp2_session_want_write() zero farther down in http2_recv. Wouldn't that be better back where it was? If we have a problem like that wouldn't we want to catch it as early in that function as possible? Also as far as http2_send wouldn't it be good there as well as a sanity check? Even if you walk the paths and see recv called (and therefore think it's covered by recv) those paths may change.

cc @bagder who may have some more experienced opinions about these things.

[tatsuhiro-t]

Thank you for reviewing my PR.

I'd prefer leaving CURLE_HTTP2 documented as is. Saying it's now a connection only error closes some doors.

OK, I will revert that portion of the code.

I notice you moved the check for nghttp2_session_want_read() and nghttp2_session_want_write() zero farther down in http2_recv. Wouldn't that be better back where it was? If we have a problem like that wouldn't we want to catch it as early in that function as possible?

The reason why I moved the check to the current location is to ensure that pending data is processed before closing session. We copy the received response body here. If it fits into per stream buffer, we don't pause the processing of libnghttp2. If we get then DATA+END_STREAM, and then GOAWAY, nghttp2_session_want_read() and nghttp2_session_want_write() will return 0. If we check that in previous position,the copied data may not be notified to the upper layer (see). But even the new position may not work if a stream other than the one which has the pending data is called first with http2_recv. If we can arrange the code so that stream with pending recv data gets called first, then my current code works better.

Also as far as http2_send wouldn't it be good there as well as a sanity check? Even if you walk the paths and see recv called (and therefore think it's covered by recv) those paths may change.

As a precaution, yes, it is good idea. I just worries that it may have the same problem I stated above. That is we might have stream with pending recv data while the nghttp2_session_want_read() and nghttp2_session_want_write() zero.

[jay]

I made a few minor changes to the PR, see the amended commit here.

But even the new position may not work if a stream other than the one which has the pending data is called first with http2_recv. If we can arrange the code so that stream with pending recv data gets called first, then my current code works better.

This sounds like an issue that the PR doesn't address is that correct? In other words are you saying that the position it's in now it could cause a bug?

[tatsuhiro-t]

Looks good.

This sounds like an issue that the PR doesn't address is that correct?

The issue I described is not fixed by PR #663.

In other words are you saying that the position it's in now it could cause a bug?

No, it does not. But because of the issue I described, it does not matter the position for now.
I'll revert the position of the check to where it used to be.

[tatsuhiro-t]

@jay I updated PR to move checks to the previous position along with your amends.

[tatsuhiro-t]

I added another commit to PR #663 to fix the issue I mentioned above. It also fixes the bug that sometimes libcurl processing hangs when multiple HTTP/2 streams are multiplexed.

[kazuho]

@tatsuhiro-t Thank you for working on the fix. Please let me know if you want me to verify on my side if the reported issue has been fixed.

[jay]

@kazuho if you could try his branch and let us know before wednesday that would be great.

[bagder]

@jay it is only the feature window that closes on Wednesday. We still have about 30 days for bugfixes until next release...

[jay]

@bagder Yes, I know :) This will likely add a unique error code CURLE_HTTP2_STREAM to signal HTTP2 bad stream when the HTTP2 connection is otherwise still good, therefore since there is a new define I figured it should be in before the close.

[bagder]

Ah, yes. That's good thinking. Way ahead of me! =) But I think we could perhaps allow that a little later too, as a return code is not really a too risky thing to add.

[tatsuhiro-t]

Let me check one more corner case where multiplexed streams are closed without pending buffered data. It is not directly related to the original issue.

[tatsuhiro-t]

I added another commit, which resolves the issue that I mentioned in the previous commit.

[kazuho]

@tatsuhiro-t @jay Tried using curl on #663 at 675a203, and got the following results. The former looks strange. The latter seems fine to me. Can you please confirm? Thank you in advance.

1. Receiving Huge Header

When running H2O with configuration found in this comment and running curl -vv -k https://127.0.0.1:8081/, the command seems to wait until the connection is closed by the peer and then emits curl: (56) Unexpected EOF. Full output of curl -vv can be found here.

2. Sending Huge Header

When running H2O with configuration found in this comment, sending request header up to 65349 bytes (name + value without counting \0) succeeds. When the sum exceeds the value, I see curl: (92) HTTP/2 stream 1 was not closed cleanly: error_code = 7 reported.

[jay]

Thanks for testing @kazuho. I haven't attempted to reproduce receiving yet but here is what I think about sending.

Error 7 is NGHTTP2_REFUSED_STREAM. I get the same error if I use a header with a long value length like 65535:

  struct curl_slist *header_list =
    curl_slist_append(NULL, ("foo:" + string(65535, '0')).c_str());
  curl_easy_setopt(curl, CURLOPT_HTTPHEADER, header_list);

Even with a header that is too long nghttp2_submit_request is creating the stream, but I don't see much in nghttp2d:

[id=14] [3230.961] send SETTINGS frame <length=6, flags=0x00, stream_id=0>
          (niv=1)
          [SETTINGS_MAX_CONCURRENT_STREAMS(0x03):100]
[id=14] [3230.965] recv SETTINGS frame <length=0, flags=0x00, stream_id=0>
          (niv=0)
[id=14] [3230.965] send SETTINGS frame <length=0, flags=0x01, stream_id=0>
          ; ACK
          (niv=0)
[id=14] [3231.220] closed

As Tatsuhiro said libnghttp2 doesn't handle large headers but I don't know if this is correct behavior.

I think we should check for large header lengths instead of casting down like this because if the header is particularly large like 66000 it's going to overflow and become 464. I'd rather we just error there, what if I change those places to do something like if((end - hdbuf) > (uint16_t)-1) err. That still wouldn't address the case where the name + val + nul len exceeds 65535 so that would have to be handled as well. But basically the idea is I add more checking in http2_send.

Another thing I think we should do is put the nghttp2_error_code enums in presentation format for the user. I don't see a strerror type function in libnghttp2 but I see something similar in app-helper. Either I could add something like that to libcurl or libnghttp2 so we can give more information to the user.

(92) HTTP/2 stream 1 was not closed cleanly: error_code = 7

but I'd change it to something like

    failf(data, "HTTP/2 stream %u was not closed cleanly: %s (err %d)",
          stream->stream_id, http2_str_err_code(stream->error_code),
          stream->error_code);

(92) HTTP/2 stream 1 was not closed cleanly: REFUSED_STREAM (err 7).

@tatsuhiro-t what do you think?

[jay]

@tatsuhiro-t thanks for all your hard work on this. Landed in b2a0376...3f57880. Though we may know there is a frame size error we don't know why, so I added a warning that appears in verbose mode when the cumulative header length is over 60000 (less than 64KB to account for some overhead) to provide some clue to the user in addition to the individual length checks.

Tested with nghttp2/1.9.2 (w/ OpenSSL 1.0.2g) and h2o 2.0.0-DEV (h2o/h2o@d299f6c 2016-04-12 w/ LibreSSL 2.2.6).

If an individual header to be sent is definitely too large (>64KB) libcurl will return an error:

Error: libcurl: (55) Failed sending HTTP request: Header overflow
Failed sending data to the peer

However as mentioned if the cumulative length to be sent may be too large we don't know for sure until after the fact so the error is more generic, although prefaced with a warning before the attempt:

* http2_send: Warning: The cumulative length of all headers exceeds 60000 bytes
and that could cause the stream to be rejected.

The headers are sent to nghttp2 which rejects them, and then this error:

Error: libcurl: (92) HTTP/2 stream 1 was not closed cleanly: REFUSED_STREAM (err 7)
Stream error in the HTTP/2 framing layer

[tatsuhiro-t]

The error and warning messages look good to me.

[jay]

Ok, thanks for the feedback. And thanks to @kazuho for your report and help reproducing.