hc-httpclient-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Oleg Kalnichevski <ol...@apache.org>
Subject Re: next request after a 204 response fails
Date Thu, 27 Oct 2016 11:44:41 GMT
On Thu, 2016-10-27 at 11:55 +0200, Marc Sluiter wrote:
> On 26 October 2016 at 22:28:28, Oleg Kalnichevski (olegk@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-unsubscribe@hc.apache.org  
> For additional commands, e-mail: httpclient-users-help@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.

> 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: httpclient-users-unsubscribe@hc.apache.org
For additional commands, e-mail: httpclient-users-help@hc.apache.org


Mime
View raw message