New HttpClient PUT request fails oddly - is it size is it number of invocations!

Tue Jun 26 14:41:49 UTC 2018

Hi Daniel,

You are right- I just added:

diff -r 955a66f0f04a test/jdk/java/net/httpclient/PUTRequestSizeTest.java

--- a/test/jdk/java/net/httpclient/PUTRequestSizeTest.java      Tue Jun 
26 18:33:18 2018 +0530
+++ b/test/jdk/java/net/httpclient/PUTRequestSizeTest.java      Tue Jun 
26 20:05:20 2018 +0530
@@ -92,6 +92,7 @@
          public void handle(final HttpExchange httpExchange) throws 
IOException {
              final URI requestURI = httpExchange.getRequestURI();
              System.out.println("Handling " + 
httpExchange.getRequestMethod() + " request " + requestURI);
+ httpExchange.getRequestBody().readAllBytes();
httpExchange.sendResponseHeaders(200, -1);
          }
      }

(and no more Thread.sleep())

and it started passing.

So is this a case of the server implementation misbehaving? I haven't 
checked what the expectations are from a spec point of view for handling 
such requests on the server. Or is it a combination of a misbehaving 
server plus the HttpClient implementation having some issue? I think the 
fact that it fails after what appear to be a couple of successful 
invocations and the odd nature of the exception message, makes it hard 
to narrow this down from a client usage point of view.Thank you 
narrowing this down quickly and for the -ea hints.

-Jaikiran

On 26/06/18 8:02 PM, Daniel Fuchs wrote:
> Hi Jaikiran,
>
> I believe you need to drain the request body in the server
> before sending the response.
>
> If you pass -ea -esa options to jtreg, you should see the
> following assertion printed by the server:
>
> java.lang.AssertionError: State is not RESPONSE (REQUEST)
>     at 
> jdk.httpserver/sun.net.httpserver.ServerImpl.responseCompleted(ServerImpl.java:814)
>     at 
> jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.handleEvent(ServerImpl.java:297)
>     at 
> jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:356)
>     at java.base/java.lang.Thread.run(Thread.java:834)
>
> I added this line in the server handler (before calling sendResponse()):
>
>    httpExchange.getRequestBody().readAllBytes();
>
> and with that the assertion disappears and the test passes for me.
>
> Could you try adding this line to your test, and run it again
> in your environment to confirm whether that might be the actual
> issue ? (I'm obviously running on a different machine than you, so
> if it's really a race condition I am concerned that I might not
> be seeing it)
>
> best regards,
>
> -- daniel
>
> On 26/06/2018 14:52, Jaikiran Pai wrote:
>> So it looks like there some race condition somewhere in the 
>> HttpClient implementation. I just addeda smalldelay between the PUT 
>> requests, in the test that I sent in the patch and it's now started 
>> passing:
>>
>> diff -r 955a66f0f04a 
>> test/jdk/java/net/httpclient/PUTRequestSizeTest.java
>> --- a/test/jdk/java/net/httpclient/PUTRequestSizeTest.java    Tue Jun 
>> 26 18:33:18 2018 +0530
>> +++ b/test/jdk/java/net/httpclient/PUTRequestSizeTest.java    Tue Jun 
>> 26 19:19:54 2018 +0530
>> @@ -59,6 +59,9 @@
>>               for (int i = 0; i < 10; i++) {
>>                   System.out.println("Sending PUT request " + (i +1));
>>                   issuePUT(httpClient, requestURL);
>> +                // TODO: This shouldn't be needed but is here to 
>> demonstrate a race
>> +                // condition somewhere in the HttpClient implementation
>> +                Thread.sleep(500);
>>               }
>>           } finally {
>>               server.stop(0);
>>
>>
>>
>> -Jaikiran
>> On 26/06/18 7:12 PM, Jaikiran Pai wrote:
>>> In my random experimentation with the new HttpClient API usage, I 
>>> have ended up running into an odd and hard to decipher exception 
>>> when dealing with PUT requests. I am noticing that if I issue 
>>> multiple PUT requests using the same HttpClient instance, the first 
>>> 2 invocations succeed while the 3rd one fails with an exception[1]. 
>>> Initially when I ran into this, I saw this happening depending on 
>>> the size of the data being uploaded via PUT request. As soon as it 
>>> hit 16385 bytes (16 KB + 1), it would end up throwing the odd 
>>> exception. However, when I decided to narrow it down to a testcase, 
>>> I was able to reproduce this without the size of the data playing a 
>>> role. And weirdly, it now keeps failing for the third invocation.
>>>
>>> I have now isolated this into a jtreg testcase and created a patch 
>>> against the latest upstream jdk to reproduce this issue. I've 
>>> attached the patch in this mail. In the test, I create a local 
>>> server and keep sending PUT requests to the server using the same 
>>> instance of HttpClient. As soon as it hits the 3rd invocation, I end 
>>> up seeing the exception[1].
>>>
>>> It's really odd, since, initially I thought it could be a size based 
>>> issue, which would have been more understandable. However with the 
>>> way it's failing now in this jtreg test, I am starting to wonder if 
>>> I have got some basics wrong.
>>>
>>>
>>> [1]
>>>
>>> java.io.IOException: HTTP/1.1 header parser received no bytes
>>>     at 
>>> java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:546) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:113) 
>>>
>>>     at PUTRequestSizeTest.issuePUT(PUTRequestSizeTest.java:76)
>>>     at PUTRequestSizeTest.main(PUTRequestSizeTest.java:61)
>>>     at 
>>> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native 
>>> Method)
>>>     at 
>>> java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) 
>>>
>>>     at 
>>> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 
>>>
>>>     at java.base/java.lang.reflect.Method.invoke(Method.java:566)
>>>     at 
>>> com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:115) 
>>>
>>>     at java.base/java.lang.Thread.run(Thread.java:834)
>>> Caused by: java.io.IOException: HTTP/1.1 header parser received no 
>>> bytes
>>>     at 
>>> java.net.http/jdk.internal.net.http.common.Utils.wrapWithExtraDetail(Utils.java:293) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.onReadError(Http1Response.java:646) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.Http1AsyncReceiver.checkForErrors(Http1AsyncReceiver.java:297) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:263) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198) 
>>>
>>>     at 
>>> java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) 
>>>
>>>     at 
>>> java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) 
>>>
>>>     ... 1 more
>>> Caused by: java.io.EOFException: EOF reached while reading
>>>     at 
>>> java.net.http/jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber.onComplete(Http1AsyncReceiver.java:587) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadSubscription.signalCompletion(SocketTube.java:629) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:830) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:175) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.handleSubscribeEvent(SocketTube.java:687) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.AsyncTriggerEvent.handle(AsyncTriggerEvent.java:54) 
>>>
>>>     at 
>>> java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:796) 
>>>
>>>
>>
>

