On Thu, 2016-10-27 at 11:55 +0200, Marc Sluiter wrote: > On 26 October 2016 at 22:28:28, Oleg Kalnichevski ([email protected]) wrote: > On Wed, 2016-10-26 at 13:01 +0200, Marc Sluiter wrote: > > Hi all, > > > > during testing a Restlet based web app with JMeter I came across a strange > > issue, which I stripped down to an issue with the Apache HttpClient: > > > > when a request gets a 204 (success no content) response, the NEXT request > > fails with a "org.apache.http.NoHttpResponseException: The target server > > failed to respond” exception (see stacktrace below), but only if the > > request follows immediately (like 200ms) after the 1st request. With some > > time (e.g. 2s) between the requests the 2nd request succeeds. > > > > The only interesting fact I found so far is, that Restlet adds a > > “Content-Length: 0” header to the 204 response. There seems to be some > > disussion if that is allowed or not. While I agree that the header does > > make much sense for a 204, it seems not to be strictly forbidden. > > > > Find example code at https://github.com/slintes/httpclienttest with 3 > > components: > > > > - the Restlet server with 2 endpoints, “test” which returns a 200 with > > response body, and “empty” which returns a 204 without body (but > > automatically added Content-Length header) > > - an Apache HttpClient based test client, which request “test”, “empty”, > > “test”, “test”: the 3rd request fails, unless you increase the sleep in > > line 35. The 4th request is always successful. > > - for comparison a Vertx HttpClient based test client, which does the same > > and always succeeds. > > > > Is this a bug? And if not, why not? > > > > Complete stacktrace of the failing request: > > > > org.apache.http.NoHttpResponseException: The target server failed to > > respond > > at > > org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:143) > > > > at > > org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57) > > > > at > > org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:261) > > > > at > > org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:165) > > > > at > > org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:167) > > > > at > > org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:272) > > > > at > > org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:124) > > > > at > > org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:271) > > > > at > > org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184) > > at > > org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) > > at > > org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184) > > > > at > > org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:71) > > > > at > > org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:220) > > > > at > > org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:164) > > > > at > > org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:139) > > > > > > Kind Regards, > > > > Marc Sluiter > > Marc > > As far as I can tell HttpClient does everything correctly. It treats 204 > as a message without a response body and correctly keeps the connection > alive. However on the subsequent request the server drops the > connection, which looks like a server side problem to me. > > See the wire log. > > Just because VertX sweeps the problem under the carpet and quietly > retries the request does not meant the problem does not exit. > > Oleg > > --- > [DEBUG] RequestAddCookies - CookieSpec selected: default > [DEBUG] RequestAuthCache - Auth cache not set in the context > [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: > {}->http://localhost:9090][total kept alive: 0; route allocated: 0 of 2; > total allocated: 0 of 20] > [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: > 0][route: {}->http://localhost:9090][total kept alive: 0; route allocated: 1 > of 2; total allocated: 1 of 20] > [DEBUG] MainClientExec - Opening connection {}->http://localhost:9090 > [DEBUG] DefaultHttpClientConnectionOperator - Connecting to > localhost/127.0.0.1:9090 > [DEBUG] DefaultHttpClientConnectionOperator - Connection established > 127.0.0.1:42579<->127.0.0.1:9090 > [DEBUG] MainClientExec - Executing request GET /test HTTP/1.1 > [DEBUG] MainClientExec - Target auth state: UNCHALLENGED > [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED > [DEBUG] headers - http-outgoing-0 >> GET /test HTTP/1.1 > [DEBUG] headers - http-outgoing-0 >> Host: localhost:9090 > [DEBUG] headers - http-outgoing-0 >> Connection: Keep-Alive > [DEBUG] headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.2 > (Java/1.8.0_60) > [DEBUG] headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate > [DEBUG] wire - http-outgoing-0 >> "GET /test HTTP/1.1[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "Host: localhost:9090[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.2 > (Java/1.8.0_60)[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "HTTP/1.1 200 OK[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "Server: Restlet-Framework/2.3.5[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "Date: Wed, 26 Oct 2016 20:16:20 > GMT[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "Content-type: text/plain; > charset=UTF-8[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "Content-length: 4[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "test" > [DEBUG] headers - http-outgoing-0 << HTTP/1.1 200 OK > [DEBUG] headers - http-outgoing-0 << Server: Restlet-Framework/2.3.5 > [DEBUG] headers - http-outgoing-0 << Date: Wed, 26 Oct 2016 20:16:20 GMT > [DEBUG] headers - http-outgoing-0 << Content-type: text/plain; charset=UTF-8 > [DEBUG] headers - http-outgoing-0 << Content-length: 4 > [DEBUG] MainClientExec - Connection can be kept alive indefinitely > [DEBUG] PoolingHttpClientConnectionManager - Connection [id: 0][route: > {}->http://localhost:9090] can be kept alive indefinitely > [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: > 0][route: {}->http://localhost:9090][total kept alive: 1; route allocated: 1 > of 2; total allocated: 1 of 20] > test: status 200, body ignore > [DEBUG] RequestAddCookies - CookieSpec selected: default > [DEBUG] RequestAuthCache - Auth cache not set in the context > [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: > {}->http://localhost:9090][total kept alive: 1; route allocated: 1 of 2; > total allocated: 1 of 20] > [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: > 0][route: {}->http://localhost:9090][total kept alive: 0; route allocated: 1 > of 2; total allocated: 1 of 20] > [DEBUG] MainClientExec - Executing request GET /empty HTTP/1.1 > [DEBUG] MainClientExec - Target auth state: UNCHALLENGED > [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED > [DEBUG] headers - http-outgoing-0 >> GET /empty HTTP/1.1 > [DEBUG] headers - http-outgoing-0 >> Host: localhost:9090 > [DEBUG] headers - http-outgoing-0 >> Connection: Keep-Alive > [DEBUG] headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.2 > (Java/1.8.0_60) > [DEBUG] headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate > [DEBUG] wire - http-outgoing-0 >> "GET /empty HTTP/1.1[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "Host: localhost:9090[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.2 > (Java/1.8.0_60)[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "HTTP/1.1 204 No Content[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "Server: Restlet-Framework/2.3.5[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "Date: Wed, 26 Oct 2016 20:16:20 > GMT[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "Content-length: 0[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "[\r][\n]" > [DEBUG] headers - http-outgoing-0 << HTTP/1.1 204 No Content > [DEBUG] headers - http-outgoing-0 << Server: Restlet-Framework/2.3.5 > [DEBUG] headers - http-outgoing-0 << Date: Wed, 26 Oct 2016 20:16:20 GMT > [DEBUG] headers - http-outgoing-0 << Content-length: 0 > [DEBUG] MainClientExec - Connection can be kept alive indefinitely > [DEBUG] PoolingHttpClientConnectionManager - Connection [id: 0][route: > {}->http://localhost:9090] can be kept alive indefinitely > [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: > 0][route: {}->http://localhost:9090][total kept alive: 1; route allocated: 1 > of 2; total allocated: 1 of 20] > Executing request GET http://localhost:9090/empty HTTP/1.1 > empty: status 204, body ignore > [DEBUG] RequestAddCookies - CookieSpec selected: default > [DEBUG] RequestAuthCache - Auth cache not set in the context > [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: > {}->http://localhost:9090][total kept alive: 1; route allocated: 1 of 2; > total allocated: 1 of 20] > [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: > 0][route: {}->http://localhost:9090][total kept alive: 0; route allocated: 1 > of 2; total allocated: 1 of 20] > [DEBUG] MainClientExec - Executing request GET /test HTTP/1.1 > [DEBUG] MainClientExec - Target auth state: UNCHALLENGED > [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED > [DEBUG] headers - http-outgoing-0 >> GET /test HTTP/1.1 > [DEBUG] headers - http-outgoing-0 >> Host: localhost:9090 > [DEBUG] headers - http-outgoing-0 >> Connection: Keep-Alive > [DEBUG] headers - http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.2 > (Java/1.8.0_60) > [DEBUG] headers - http-outgoing-0 >> Accept-Encoding: gzip,deflate > [DEBUG] wire - http-outgoing-0 >> "GET /test HTTP/1.1[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "Host: localhost:9090[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.2 > (Java/1.8.0_60)[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]" > [DEBUG] wire - http-outgoing-0 >> "[\r][\n]" > [DEBUG] wire - http-outgoing-0 << "end of stream" > [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-0: Close > connection > [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-0: Shutdown > connection > [DEBUG] MainClientExec - Connection discarded > Executing request GET http://localhost:9090/test HTTP/1.1 > [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: > 0][route: {}->http://localhost:9090][total kept alive: 0; route allocated: 0 > of 2; total allocated: 0 of 20] > org.apache.http.NoHttpResponseException: The target server failed to respond > at > org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:143) > > at > org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:57) > > at > org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259) > > at > org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163) > > at > org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:167) > > at > org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273) > > at > org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125) > > at > org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:271) > > at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184) > > at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) > > at > org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184) > > at > org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:71) > > at > org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:220) > > at > org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:164) > > at > org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:139) > > at net.slintes.restlet.TestClient.doGet(TestClient.java:65) > at net.slintes.restlet.TestClient.lambda$run$1(TestClient.java:33) > at java.util.Arrays$ArrayList.forEach(Arrays.java:3880) > at net.slintes.restlet.TestClient.run(TestClient.java:32) > at net.slintes.restlet.TestClient.main(TestClient.java:23) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) > > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) > > at java.lang.reflect.Method.invoke(Method.java:497) > at com.intellij.rt.execution.application.AppMain.main(AppMain.java:147) > Executing request GET http://localhost:9090/test HTTP/1.1 > [DEBUG] RequestAddCookies - CookieSpec selected: default > [DEBUG] RequestAuthCache - Auth cache not set in the context > [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: > {}->http://localhost:9090][total kept alive: 0; route allocated: 0 of 2; > total allocated: 0 of 20] > [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: > 1][route: {}->http://localhost:9090][total kept alive: 0; route allocated: 1 > of 2; total allocated: 1 of 20] > [DEBUG] MainClientExec - Opening connection {}->http://localhost:9090 > [DEBUG] DefaultHttpClientConnectionOperator - Connecting to > localhost/127.0.0.1:9090 > [DEBUG] DefaultHttpClientConnectionOperator - Connection established > 127.0.0.1:42580<->127.0.0.1:9090 > [DEBUG] MainClientExec - Executing request GET /test HTTP/1.1 > [DEBUG] MainClientExec - Target auth state: UNCHALLENGED > [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED > [DEBUG] headers - http-outgoing-1 >> GET /test HTTP/1.1 > [DEBUG] headers - http-outgoing-1 >> Host: localhost:9090 > [DEBUG] headers - http-outgoing-1 >> Connection: Keep-Alive > [DEBUG] headers - http-outgoing-1 >> User-Agent: Apache-HttpClient/4.5.2 > (Java/1.8.0_60) > [DEBUG] headers - http-outgoing-1 >> Accept-Encoding: gzip,deflate > [DEBUG] wire - http-outgoing-1 >> "GET /test HTTP/1.1[\r][\n]" > [DEBUG] wire - http-outgoing-1 >> "Host: localhost:9090[\r][\n]" > [DEBUG] wire - http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]" > [DEBUG] wire - http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.5.2 > (Java/1.8.0_60)[\r][\n]" > [DEBUG] wire - http-outgoing-1 >> "Accept-Encoding: gzip,deflate[\r][\n]" > [DEBUG] wire - http-outgoing-1 >> "[\r][\n]" > [DEBUG] wire - http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]" > [DEBUG] wire - http-outgoing-1 << "Server: Restlet-Framework/2.3.5[\r][\n]" > [DEBUG] wire - http-outgoing-1 << "Date: Wed, 26 Oct 2016 20:16:21 > GMT[\r][\n]" > [DEBUG] wire - http-outgoing-1 << "Content-type: text/plain; > charset=UTF-8[\r][\n]" > [DEBUG] wire - http-outgoing-1 << "Content-length: 4[\r][\n]" > [DEBUG] wire - http-outgoing-1 << "[\r][\n]" > [DEBUG] wire - http-outgoing-1 << "test" > [DEBUG] headers - http-outgoing-1 << HTTP/1.1 200 OK > [DEBUG] headers - http-outgoing-1 << Server: Restlet-Framework/2.3.5 > [DEBUG] headers - http-outgoing-1 << Date: Wed, 26 Oct 2016 20:16:21 GMT > [DEBUG] headers - http-outgoing-1 << Content-type: text/plain; charset=UTF-8 > [DEBUG] headers - http-outgoing-1 << Content-length: 4 > [DEBUG] MainClientExec - Connection can be kept alive indefinitely > [DEBUG] PoolingHttpClientConnectionManager - Connection [id: 1][route: > {}->http://localhost:9090] can be kept alive indefinitely > [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: > 1][route: {}->http://localhost:9090][total kept alive: 1; route allocated: 1 > of 2; total allocated: 1 of 20] > test: status 200, body ignore > > > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > > > Hello Greg, > > thanks for having a look. But I’m not sure if I agree.
You are very welcome to disagree with me, with Greg, or both. > I enabled some more logging, and saw that indeed Restlet closes the > connection, but at the end of a request, and not when the new request comes > in. As far as I know closing a connection is not strictly forbidden? > This is how classic (blocking) i/o works. It can detect that the input stream has been closed by the remote endpoint only when blocked in a read operation. In this particular case it can happen only after submitting a subsequent request and attempting to receive a response. While what Restlet does is not illegal, it can really cause problems on the client end. If the server intends to terminate the connection immediately after sending an HTTP/1.1 response it _really_ ought to send 'Connection: close' in it. > Oct 27, 2016 10:08:42 AM org.restlet.engine.log.LogFilter afterHandle > INFO: 2016-10-27 10:08:42 127.0.0.1 - - 9090 > GET /app/empty - 204 0 0 6 > http://localhost:9090 Apache-HttpClient/4.5.2 (Java/1.8.0_66) - > Oct 27, 2016 10:08:42 AM sun.net.httpserver.ServerImpl logReply > FINE: GET /app/empty HTTP/1.1 [204 No Content] () > Oct 27, 2016 10:08:42 AM sun.net.httpserver.HttpConnection close > FINEST: Closing connection: java.nio.channels.SocketChannel[connected > local=/127.0.0.1:9090 remote=/127.0.0.1:64814] > > I’m wondering why this is a problem when the next request follows quickly, > but not when there is some time between requests…? Is it a kind of race > condition? > No, it is not. After a certain period of inactivity on a blocking connection HttpClient validates its state by executing the so called staleness check prior to re-using it. The check is relatively expensive. That is why as of version 4.4 HttpClient does not execute it for each and every request. > The Vertx client does not retry, it detects that the connection / channel is > closed and reopens it: > Which is essentially the same to me. Oleg --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
