Chunks get lost using http client request with setChunked(true)

[Peter Fischer]

Hi,

I wanted to send json objects I get from a stream via a chunked client request to the server - but sometimes a complete chunk (= json object) gets lost / does not reach the server code.
 
I've simplified the code as far as possible and with smaller json strings this happens less often, so you have to run the test (see attached zip - test calls doPost() 1000 times) up to 5 times till you run into the issue (BTW - it's the same for GET requests):

Client - one request with 10 chunks (plus one end call)    

   private void doPost() {
          HttpClient client = Vertx.vertx().createHttpClient();
          CompletableFuture<Boolean> postRequestWorked = new CompletableFuture<>();

          HttpClientRequest request = client.post(4747, "localhost", "/", response -> {
              response.bodyHandler(body -> {
                  System.out.println("testPost() " + body.toString());
                  postRequestWorked.complete(response.statusCode() == HttpURLConnection.HTTP_OK);
              });
          }).setChunked(true);
         
          for(int i= 0; i < 10; i++) {
              // no json object to simplify string creation
              String json = "{\"identifier\" : \""+i+"\", \"type_of_item\" : \"hardcover_book\", \"title_of_item\" : \"test record "+i+"\"}";

              // happens almost never with such short strings:
              //String json = "test record "+i;
              if(i>0) json = ", " + json;
             
              System.out.println(json);
              request.write(json);
          }
          request.end("...");

          try {
              assertTrue(postRequestWorked.get(10, TimeUnit.SECONDS));
          } catch (Exception e) {
              fail(e.getMessage());
          }
      }

Server - checking if all chunks are there

@Override
    public void start(Future<Void> fut) {

        vertx.createHttpServer(new HttpServerOptions().setReceiveBufferSize(5000)).requestHandler(request -> {

            StringBuffer body = new StringBuffer();
            request.handler(buffer -> {
                System.out.println(buffer.toString());
                body.append(buffer.toString());
            });

            request.endHandler(end -> {
                int missingDoc = -1;
                for (int i=0; i<10; i++) {
                    if (!body.toString().contains("test record " + i)) {
                        missingDoc = i;
                        break;
                    }
                }
                if (missingDoc >= 0) {
                    request.response().setStatusCode(500);
                    request.response().end("missing doc: " + missingDoc);
                } else {
                    request.response().setStatusCode(200);
                    request.response().end("done processing");
                }

            });
        }
                ).listen(4747, res -> {
                    if (res.succeeded()) {
                        System.out.println("listening on port " + 4747);
                    } else {
                        System.out.println("failed to bind port " + 4747);
                    }
                });
    }

this is what is written to the console if chunk 9 is missing:

...

testPost() done processing

{"identifier" : "0", "type_of_item" : "hardcover_book", "title_of_item" : "test record 0"}
, {"identifier" : "1", "type_of_item" : "hardcover_book", "title_of_item" : "test record 1"}
, {"identifier" : "2", "type_of_item" : "hardcover_book", "title_of_item" : "test record 2"}
, {"identifier" : "3", "type_of_item" : "hardcover_book", "title_of_item" : "test record 3"}
, {"identifier" : "4", "type_of_item" : "hardcover_book", "title_of_item" : "test record 4"}
, {"identifier" : "5", "type_of_item" : "hardcover_book", "title_of_item" : "test record 5"}
, {"identifier" : "6", "type_of_item" : "hardcover_book", "title_of_item" : "test record 6"}
, {"identifier" : "7", "type_of_item" : "hardcover_book", "title_of_item" : "test record 7"}
, {"identifier" : "8", "type_of_item" : "hardcover_book", "title_of_item" : "test record 8"}
, {"identifier" : "9", "type_of_item" : "hardcover_book", "title_of_item" : "test record 9"}
testPost() missing doc: 9

[Hendrik Haddorp]

Hi,

I can easily reproduce the problem with different versions of Vert.x and also when forcing it to use the latest Netty 4.0.x version. I then tried to check what data is actually send using Wireshark and it looks like in the working cases the data is actually not send in chunks, even when setting the max chunk size to 100 more data is send in a chunk. I get this for example:

POST / HTTP/1.1
Host: localhost:4747
Transfer-Encoding: chunked
 
399
{"identifier" : "0", "type_of_item" : "hardcover_book", "title_of_item" : "test record 0"}, {"identifier" : "1", "type_of_item" : "hardcover_book", "title_of_item" : "test record 1"}, {"identifier" : "2", "type_of_item" : "hardcover_book", "title_of_item" : "test record 2"}, {"identifier" : "3", "type_of_item" : "hardcover_book", "title_of_item" : "test record 3"}, {"identifier" : "4", "type_of_item" : "hardcover_book", "title_of_item" : "test record 4"}, {"identifier" : "5", "type_of_item" : "hardcover_book", "title_of_item" : "test record 5"}, {"identifier" : "6", "type_of_item" : "hardcover_book", "title_of_item" : "test record 6"}, {"identifier" : "7", "type_of_item" : "hardcover_book", "title_of_item" : "test record 7"}, {"identifier" : "8", "type_of_item" : "hardcover_book", "title_of_item" : "test record 8"}, {"identifier" : "9", "type_of_item" : "hardcover_book", "title_of_item" : "test record 9"}...
0
 
HTTP/1.1 200 OK
Content-Length: 15
 
done processing

In the failing case I see this:

POST / HTTP/1.1
Host: localhost:4747
Transfer-Encoding: chunked
 
112

{"identifier" : "0", "type_of_item" : "hardcover_book", "title_of_item" : "test record 0"}, {"identifier" : "1", "type_of_item" : "hardcover_book", "title_of_item" : "test record 1"}, {"identifier" : "2", "type_of_item" : "hardcover_book", "title_of_item" : "test record 2"}

5c

, {"identifier" : "4", "type_of_item" : "hardcover_book", "title_of_item" : "test record 4"}

5c

, {"identifier" : "5", "type_of_item" : "hardcover_book", "title_of_item" : "test record 5"}

5c

, {"identifier" : "6", "type_of_item" : "hardcover_book", "title_of_item" : "test record 6"}

5c

, {"identifier" : "7", "type_of_item" : "hardcover_book", "title_of_item" : "test record 7"}

5c

, {"identifier" : "8", "type_of_item" : "hardcover_book", "title_of_item" : "test record 8"}

5c

, {"identifier" : "9", "type_of_item" : "hardcover_book", "title_of_item" : "test record 9"}

3
...
0
 
HTTP/1.1 500 Internal Server Error
Content-Length: 14
 
missing doc: 3

So in this case the first transfer was again larger then the max chunk size and only after that the chunks have the correct size. The missing data is also always what should have been send after the first chunk.

[Tim Fox]

Just had a quick look at your test program, some observations:

* You aren't waiting for the verticle to be deployed before starting test - there's a possibility the server won't be deployed before the test starts
* You're calling doPost 1000 times in a loop. Each time you're creating a brand new Vertx instance with Vertx.vertx() - this doesn't seem right. You're also not closing the Vertx instance afterwards.
* You're not closing the HttpClient instance afterwards.
* This test will result in up to 1000 connections to the server each of them sending 10 Json objects. There's no guarantee in which order the server will service the connections so you should expect to the see the chunks arriving in a random order on the server. Your server verticle seems to assume it will receive json objects 0 to 9 each time. That assumption doesn't seem to be valid.

--
You received this message because you are subscribed to the Google Groups "vert.x" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
Visit this group at https://groups.google.com/group/vertx.
To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/14aa1241-f1a3-4230-9f93-8ab105b5018b%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Hendrik Haddorp]

I had also noticed the deployment issue but changing that did not cause any change. The client side does actually wait for a CompletableFuture and does not seem to run the loops in parallel but waits for them to finish. That's why the test program stops as soon as a missing chunk is detected. I had also already tried to close the HttpClient but that did also not result in any change. Given that the server side stores the received data in a request scoped object and checks the complete state once the request end is detected I don't see why this should not work.
Is there any trace to see what Vert.x or Netty is actually sending out?

You received this message because you are subscribed to a topic in the Google Groups "vert.x" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/vertx/_dQhEVWNoQI/unsubscribe.
To unsubscribe from this group and all its topics, send an email to vertx+un...@googlegroups.com.

Visit this group at https://groups.google.com/group/vertx.

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/571BAF7A.4060103%40gmail.com.

[Tim Fox]

Ok, I'll try and take a proper look tomorrow.

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/571BB533.7030505%40gmx.net.

[Peter Fischer]

@Hendrik + Tim: Thanks for looking into this!

sorry - did not get any notifications on the replies therefore my late answer.

And sorry for the quality of the quickly put together test program - the requests are send out sequentially though and everything seems to work from a communication point of view (besides the lost chunk from time to time).
Attached is a version with some "fixes" that's easier to set up (the first one only ran easily in eclipse).

Is there some other means to influence the way the requests are put together besides the obvious HttpClientOptions and the setters on the HttpClientRequest?
Any changes there did not really change the way the chunks are put together or their size (even with max chunk size set) - sometimes it's just one big request, sometimes it's a lot of small chunks, sometimes a mixture (within one test run) - and sometimes a chunk gets lost...

[Peter Fischer]

Hi Tim,

did you have a chance to look into this?
As it seems to be reproducable should I open a bug on bugzilla?

Thanks, Peter

[Peter Fischer]

did not find the correct place to report a vert.x bug in eclipse/bugzilla so I opened an "old fashioned" github issue: https://github.com/vert-x3/issues/issues/117

[Julien Viet]

that’s the correct way to report it.

On May 2, 2016, at 8:31 AM, 'Peter Fischer' via vert.x <ve...@googlegroups.com> wrote:

did not find the correct place to report a vert.x bug in eclipse/bugzilla so I opened an "old fashioned" github issue: https://github.com/vert-x3/issues/issues/117

--
You received this message because you are subscribed to the Google Groups "vert.x" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
Visit this group at https://groups.google.com/group/vertx.

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/30e93b0a-5b51-44f0-94fe-f75f0a268ffc%40googlegroups.com.