On 27 October 2016 at 13:54:25, Oleg Kalnichevski (ol...@apache.org) wrote: On Thu, 2016-10-27 at 11:55 +0200, Marc Sluiter wrote: > On 26 October 2016 at 22:28:28, Oleg Kalnichevski (ol...@apache.org) 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: httpclient-users-unsubscr...@hc.apache.org > For additional commands, e-mail: httpclient-users-h...@hc.apache.org > > > 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. Oh sorry Oleg! No idea how that typo could happen :/ > 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. ok, thanks for clarifying this. 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. I read a bit more about http connections in the meanwhile and agree: it’s at least not nice what Restlet does. > 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. ok > 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: httpclient-users-unsubscr...@hc.apache.org For additional commands, e-mail: httpclient-users-h...@hc.apache.org I just found a workaround: it’s possible to make Restlet use Jetty as http server. At least in my test project everything works when doing that. I will suggest to do that in our real application too. I will also report this issue to the Restlet team. Thanks for taking time and clarifying things! :) Regards, Marc
