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

[Daniel Fuchs]

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) 
>>
>>
>