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. 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?
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?
The Vertx client does not retry, it detects that the connection / channel is
closed and reopens it:
Oct 27, 2016 11:20:16 AM io.netty.handler.logging.LoggingHandler channelInactive
FINE: [id: 0xdec8eb4a, L:/127.0.0.1:53053 ! R:localhost/127.0.0.1:9090] INACTIVE
Oct 27, 2016 11:20:16 AM io.netty.handler.logging.LoggingHandler
channelUnregistered
FINE: [id: 0xdec8eb4a, L:/127.0.0.1:53053 ! R:localhost/127.0.0.1:9090]
UNREGISTERED
Oct 27, 2016 11:20:17 AM io.netty.handler.logging.LoggingHandler
channelRegistered
FINE: [id: 0x04c17460] REGISTERED
Oct 27, 2016 11:20:17 AM io.netty.handler.logging.LoggingHandler connect
FINE: [id: 0x04c17460] CONNECT: localhost/127.0.0.1:9090
Marc
