Bug 63690 - [HTTP/2] The socket [*] associated with this connection has been closed.
Summary: [HTTP/2] The socket [*] associated with this connection has been closed.
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Connectors (show other bugs)
Version: 9.0.24
Hardware: PC Linux
: P2 normal (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-08-23 15:36 UTC by Boris Petrov
Modified: 2019-09-05 14:10 UTC (History)
0 users



Attachments
Log (82.23 KB, text/plain)
2019-08-23 20:40 UTC, Boris Petrov
Details
Dump of the POST request (497.84 KB, text/plain)
2019-08-25 19:19 UTC, Boris Petrov
Details
Simple project demonstrating multipart issue (19.44 KB, application/x-zip-compressed)
2019-08-29 12:12 UTC, Chen Levy
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Boris Petrov 2019-08-23 15:36:43 UTC
Tomcat is version 9.0.24, APR 1.7.0, Tomcat Native 1.2.23.

When using HTTP/2, doing a multipart post request from any browser causes this exception 99% of the cases:

~~~
javax.ws.rs.ProcessingException: Failed to buffer the message content input stream.
        at org.glassfish.jersey.message.internal.InboundMessageContext.bufferEntity(InboundMessageContext.java:907)
        at user-code(SourceFile:58)
        ...
Caused by: org.apache.catalina.connector.ClientAbortException: java.io.IOException: The socket [140,613,069,382,992] associated with this connection has been closed.
        at org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:340)
        at org.apache.catalina.connector.InputBuffer.checkByteBufferEof(InputBuffer.java:632)
        at org.apache.catalina.connector.InputBuffer.read(InputBuffer.java:362)
        at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:132)
        at org.apache.catalina.connector.CoyoteInputStream.read(CoyoteInputStream.java:110)
        at org.glassfish.jersey.message.internal.ReaderWriter.writeTo(ReaderWriter.java:92)
        at org.glassfish.jersey.message.internal.InboundMessageContext.bufferEntity(InboundMessageContext.java:894)
        ... 52 common frames omitted
Caused by: java.io.IOException: The socket [140,613,069,382,992] associated with this connection has been closed.
        at org.apache.tomcat.util.net.AprEndpoint$AprSocketWrapper.doWrite(AprEndpoint.java:2315)
        at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:793)
        at org.apache.tomcat.util.net.SocketWrapperBase.writeBlocking(SocketWrapperBase.java:529)
        at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:454)
        at org.apache.coyote.http2.Http2UpgradeHandler.writeWindowUpdate(Http2UpgradeHandler.java:770)
        at org.apache.coyote.http2.Stream$StreamInputBuffer.doRead(Stream.java:1122)
        at org.apache.coyote.Request.doRead(Request.java:551)
        at org.apache.catalina.connector.InputBuffer.realReadBytes(InputBuffer.java:336)
        ... 58 common frames omitted
~~~

Switching back to HTTP/1.1 by commenting out `<UpgradeProtocol className="org.apache.coyote.http2.Http2Protocol"/>` in `conf/server.xml` fixes the issue.

I've no idea what could I have done wrong. GET requests are working fine as well as not-multipart post ones (or perhaps they are not so big and that's why they work). Not sure if that matters.

Please tell me how can I help to debug the issue. Thanks!
Comment 1 Mark Thomas 2019-08-23 19:08:49 UTC
Enable debug logging for org.apache.coyote.http2 and provide the output for a single, failed request.
Comment 2 Boris Petrov 2019-08-23 20:40:47 UTC
Created attachment 36734 [details]
Log

This is a dump of the logging for `org.apache.coyote.http2`.
Comment 3 Mark Thomas 2019-08-24 08:20:20 UTC
The request has triggered the overhead protection because it looks abusive (small non-final DATA frame). Setting overheadDataThreadhold to zero will disable the specific protection triggered.
A debug trace with that disabled would be interesting to see how many frames like that the client is producing. It would also be worth looking into why the client is behaving that way.
Comment 4 Boris Petrov 2019-08-24 08:31:15 UTC
Thank you for the support, Mark.

As I said, this happens with both the latest Chrome and Firefox, as well as Firefox 47 (these are the three browsers I tested with). Only when using HTTP/2. The client side is making a POST request to upload a file. The library that we use is "jQuery File Upload" (https://github.com/blueimp/jQuery-File-Upload). We split the file in 1 MB chunks with that library. In 99% of the cases the first request fails. Does that give you any ideas?

I'll try setting `overheadDataThreadhold` to 0 on Monday and post the findings. You need the same logging as I already provided, just with that setting, correct?

Thanks again!
Comment 5 Mark Thomas 2019-08-24 14:48:40 UTC
Correct. Tx.
Comment 6 Boris Petrov 2019-08-25 19:19:15 UTC
Created attachment 36736 [details]
Dump of the POST request

This is a dump of the POST request for uploading a file (there should be 2 POST multiform requests because the file was 1.5 MB) after disabling the `overheadDataThreadhold` limit. The upload works in that case by the way.

Anything you can figure out from the dump?
Comment 7 Mark Thomas 2019-08-27 06:36:36 UTC
Take a look at the following lines in the log:

Connection [1], Stream [7], Frame type [DATA], Flags [0], Payload size [...]

It looks like there is some buffering going on.

The first 6 data frames are 5x2852 bytes and 1x2124 bytes for a total of exactly 16k.

The first 24 packets are 20x2852, 3x2124 and 1x2123 for a total of 64k-1. The 25th packet is 1 byte giving a total of 64k.

A similar (but not completely identical pattern) follows for the rest of the upload. It looks like the library you are using has various internal buffers and what you are seeing (in terms of data packet size) is the result of interactions between those buffers (I'm assuming there is no HTTP/2 proxy between the client and Tomcat else things will get more complicated).

Small HTTP/2 packets are inefficient. Lots of them are considered to be abusive and in some servers (not Tomcat) result in a DoS. Tomcat has expanded its overhead protection to protect against such abusive traffic. The default settings considers any non-final DATA frame of less than 1024 bytes abusive. The smaller the DATA frame, the more abusive it is considered.

I'd recommend opening an issue against the library you are using as it could be argued it should be sending fewer, larger HTTP/2 frames.

It could also be argued that Tomcat should use a lower overheadDataThreadhold. However, the counter argument is that a lower threshold is only required for inefficient clients. Where inefficient becomes abusive is an interesting question and the answer will vary from server to server. As I said, in Tomcat's case it is never abusive, only inefficient, but we want to encourage clients to be efficient.

I'm leaning towards leaving the default as is for now but is is definitely something we should keep an eye on as more users pick up the latest 9.0.x and 8.5.x releases. If we see a lot of issues like this then we may need to review the default. I'll leave this open for now but I am leaning towards resolving it as some form of "not a Tomcat issue".
Comment 8 Boris Petrov 2019-08-27 06:48:16 UTC
Hi, thanks for the detailed answer.

There is no intermediate HTTP/2 proxy.

Before I open an issue somewhere, could you please explain me something. I'm not sure I fully understand what's going on but how can a JavaScript library manage the HTTP/2 frames at all? As I said above, we're using "jQuery File Upload" (https://github.com/blueimp/jQuery-File-Upload) which splits the file in 1 MB chunks. Then, I guess, they do the POST request. Isn't then splitting that request with its body a Chrome/Firefox responsibility? If by "client" you mean Chrome/Firefox... is it possible that both of them are so inefficient/not-clever? If you mean a JavaScript library - then I probably am missing something. Some insight would be appreciated. Thanks!
Comment 9 Christopher Schultz 2019-08-28 03:10:06 UTC
(In reply to Mark Thomas from comment #7)
> Small HTTP/2 packets are inefficient. Lots of them are considered to be
> abusive and in some servers (not Tomcat) result in a DoS. Tomcat has
> expanded its overhead protection to protect against such abusive traffic.
> The default settings considers any non-final DATA frame of less than 1024
> bytes abusive. The smaller the DATA frame, the more abusive it is considered.

1024 might be too high for a default, but the good news is that the "abusive" threshold can be changed (right?).

Imagine an endpoint that is supposed to receive messages from a smart phone tracking a user's geographical location. Let's think about the kinds of packets you'd maybe expect to get. Let's assume JSON for a moment and that there isn't a huge amount of other BS in the application: it's just doing what you'd expect. An update message might look like this:

{
  "MessageType" : "LOC-Update",
  "Timestamp" : "2019-08-27T23:02:00Z",
  "Latitude" : 51.508107,
  "Longitude" : -0.075938
}

Including the trailing newline, that message is a mere 128 bytes. Imagine sending one of those messages per second per client (which is pretty chatty, but hey there are lots of crappy mobile apps out there, aren't there). If I were designing such a service, I would even arrange to have the messages be even smaller. There's no need to have such verbose JSON. Property names could be changed, or, if the data format is relatively simple and/or fixed, a JSON object could be converted into a JSON array and the property names are removed entirely. The message could be as short as:

["2019-08-27T23:02:00Z",51.508107,-0.075938]

That's a scant 44 bytes.

Not every application will be sending large documents around.
Comment 10 Mark Thomas 2019-08-28 07:09:19 UTC
(In reply to Boris Petrov from comment #8)
> Hi, thanks for the detailed answer.
> 
> There is no intermediate HTTP/2 proxy.
> 
> Before I open an issue somewhere, could you please explain me something. I'm
> not sure I fully understand what's going on but how can a JavaScript library
> manage the HTTP/2 frames at all?

It will depend on the API it uses to pass data to the browser. For example, if the API offers the capability to a) control the write buffer size and b) flush writes then the client can - broadly - control the size of the DATA frames written. I'm not at all familiar with the API in use. What I would suggest is to test a simple POST with the same file and no Javascript library and see how that behaves.


(In reply to Christopher Schultz from comment #9)
> 1024 might be too high for a default, but the good news is that the
> "abusive" threshold can be changed (right?).

Right.

<snip/>

> That's a scant 44 bytes.
> 
> Not every application will be sending large documents around.

Which is why the threshold doesn't apply to DATA frames with the EOS (end of stream) flag set. Sending a small request body in a single DATA frame is fine even if the body is just a single byte. Sending lots of small (less than 1024 bytes by default) DATA frames when you could send one larger DATA frame is not.
Comment 11 Chen Levy 2019-08-28 18:49:01 UTC
I encountered a similar issue where multipart form submission resulted in none of the form parameters being visible from the servlet (no exception or error).
I created a small test project containing a single HTML file with a multipart form, and a single servlet.
No Java or JavaScript libraries are involved

Using the latest Firefox and Chrome I encounter the issue when uploading a 3MB file. The overheadDataThreadhold="0" setting seem to resolve it

I'd expect the default Tomcat distribution to allow these kind of activities without additional configuration

I can supply/attach additional information if needed
Thanks
Comment 12 Christopher Schultz 2019-08-28 19:16:23 UTC
(In reply to Mark Thomas from comment #10)
> Which is why the threshold doesn't apply to DATA frames with the EOS (end of
> stream) flag set. Sending a small request body in a single DATA frame is
> fine even if the body is just a single byte. Sending lots of small (less
> than 1024 bytes by default) DATA frames when you could send one larger DATA
> frame is not.

Aha, thanks for pointing out the difference.
Comment 13 Boris Petrov 2019-08-29 05:50:40 UTC
(In reply to Chen Levy from comment #11)
> I encountered a similar issue where multipart form submission resulted in
> none of the form parameters being visible from the servlet (no exception or
> error).
> I created a small test project containing a single HTML file with a
> multipart form, and a single servlet.
> No Java or JavaScript libraries are involved
> 
> Using the latest Firefox and Chrome I encounter the issue when uploading a
> 3MB file. The overheadDataThreadhold="0" setting seem to resolve it
> 
> I'd expect the default Tomcat distribution to allow these kind of activities
> without additional configuration
> 
> I can supply/attach additional information if needed
> Thanks

Chen Levy, if you could provide a simple sample project that, as you say, has no external dependencies and breaks with the default Tomcat configuration on the latest Chrome/Firefox, please do so that Tomcat's team could perhaps take a look and reevaluate the default settings.
Comment 14 Chen Levy 2019-08-29 12:12:44 UTC
Created attachment 36744 [details]
Simple project demonstrating multipart issue
Comment 15 Chen Levy 2019-08-29 12:22:02 UTC
(In reply to Boris Petrov from comment #13)
> Chen Levy, if you could provide a simple sample project that, as you say,
> has no external dependencies and breaks with the default Tomcat
> configuration on the latest Chrome/Firefox, please do so that Tomcat's team
> could perhaps take a look and reevaluate the default settings.

I've attached a simple project:
The issue is noticeable when filling the form fields, including the file upload, in which case the form fields are not accessible from the servlet.

The issue appears with Tomcat 9.0.24 but not with 9.0.21
The issue appears with HTTPS but not with HTTP
The issue appears when there's an upload file, but not without it

The Tomcat server has HTTP2 enabled
Comment 16 Mark Thomas 2019-09-04 18:17:46 UTC
The 2852*5, 2124, 2852*5, 2124, 2852*5, 2124, 2852*5, 2123, 1, etc pattern occurs (in Chrome at least) with a direct POST request with no libraries present. That points to Chrome being responsible for the 1 byte DATA frame. I'll try and reach out to a contact in the Chrome dev team.
Comment 17 Mark Thomas 2019-09-04 22:51:51 UTC
https://bugs.chromium.org/p/chromium/issues/detail?id=1000809

The root cause currently looks to be a combination of how Chrome's buffering interacts with flow control windows that do not have an initial size of n*16k and Tomcat's recently added dislike of small, inefficient DATA frames as potentially abusive.

While investigating this issue I have found that Tomcat needs to make some changes to ensure that non-default initial window sizes are communicated to the client as early as possible. I'll commit those after I have completed some more testing.

I'm also looking into modifying Tomcat's overhead protection so a single DATA frame with a 1 byte payload isn't seen as abusive.
Comment 18 Mark Thomas 2019-09-05 14:10:01 UTC
I've made a couple of changes in light of my research.

1. I have added some code to ensure that, if a larger than default initial window size is configured, then Tomcat will follow the initial SETTINGS frame (typically in the same TCP packet) with a WINDOW_UPDATE frame to increase the size of the flow control window for the connection.

2. I have switched to using the average size of the current and previous DATA and WINDOW_UPDATE frames to test against their respective thresholds. This allows some smaller frames (e.g. those caused by the buggering behaviour seen here) when surrounded by larger frames but will still close the connection quickly if lots of small frames are used.

These changes will are in:
- master for 9.0.25 onwards
- 8.5.x for 8.5.46 onwards

I'm still hopeful that Chrome will make some changes to reduce the number of small, non-final DATA frames it sends during an upload.