hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Carl D'Halluin (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HTTPCLIENT-1376) HttpClient incorrectly reuses HTTP/1.1 connection - the response body of the first request is considered as the response for the second request
Date Wed, 19 Jun 2013 19:13:20 GMT

    [ https://issues.apache.org/jira/browse/HTTPCLIENT-1376?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13688332#comment-13688332
] 

Carl D'Halluin commented on HTTPCLIENT-1376:
--------------------------------------------

This is the log for the case with authentication. The connection is reused which is incorrect.

REQUEST: GET http://127.0.0.1:8777/authenticated.html
2013/06/19 21:08:58:564 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:08:58:593 CEST [DEBUG] DefaultClientConnectionOperator - Connecting to 127.0.0.1:8777
2013/06/19 21:08:58:619 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:08:58:645 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:08:58:646 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:08:58:646 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:08:58:647 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:08:58:647 CEST [DEBUG] DefaultClientConnection - Sending request: GET /authenticated.html
HTTP/1.1
2013/06/19 21:08:58:648 CEST [DEBUG] headers - >> GET /authenticated.html HTTP/1.1
2013/06/19 21:08:58:648 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:08:58:648 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:08:58:648 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:08:58:653 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
401 Unauthorized - client is %s
2013/06/19 21:08:58:653 CEST [DEBUG] headers - << HTTP/1.1 401 Unauthorized - client
is %s
2013/06/19 21:08:58:653 CEST [DEBUG] headers - << Content-Length: 0
2013/06/19 21:08:58:653 CEST [DEBUG] headers - << WWW-Authenticate: Basic realm="Amplidata"
2013/06/19 21:08:58:658 CEST [DEBUG] DefaultHttpClient - Connection can be kept alive indefinitely
2013/06/19 21:08:58:659 CEST [DEBUG] DefaultHttpClient - Authentication required
2013/06/19 21:08:58:659 CEST [DEBUG] DefaultHttpClient - 127.0.0.1:8777 requested authentication
2013/06/19 21:08:58:660 CEST [DEBUG] TargetAuthenticationStrategy - Authentication schemes
in the order of preference: [negotiate, Kerberos, NTLM, Digest, Basic]
2013/06/19 21:08:58:660 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for negotiate
authentication scheme not available
2013/06/19 21:08:58:660 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for Kerberos
authentication scheme not available
2013/06/19 21:08:58:660 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for NTLM authentication
scheme not available
2013/06/19 21:08:58:660 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for Digest authentication
scheme not available
2013/06/19 21:08:58:667 CEST [DEBUG] DefaultHttpClient - Selected authentication options:
[BASIC]
2013/06/19 21:08:58:668 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:08:58:668 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:08:58:668 CEST [DEBUG] RequestTargetAuthentication - Target auth state: CHALLENGED
2013/06/19 21:08:58:669 CEST [DEBUG] RequestTargetAuthentication - Generating response to
an authentication challenge using basic scheme
2013/06/19 21:08:58:697 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:08:58:698 CEST [DEBUG] DefaultHttpClient - Attempt 2 to execute request
2013/06/19 21:08:58:698 CEST [DEBUG] DefaultClientConnection - Sending request: GET /authenticated.html
HTTP/1.1
2013/06/19 21:08:58:698 CEST [DEBUG] headers - >> GET /authenticated.html HTTP/1.1
2013/06/19 21:08:58:698 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:08:58:698 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:08:58:698 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:08:58:698 CEST [DEBUG] headers - >> Authorization: Basic dXNlcjpwYXNz
2013/06/19 21:08:58:701 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
200 OK - client is 127.0.0.1:51015
2013/06/19 21:08:58:701 CEST [DEBUG] headers - << HTTP/1.1 200 OK - client is 127.0.0.1:51015
2013/06/19 21:08:58:702 CEST [DEBUG] DefaultHttpClient - Authentication succeeded
2013/06/19 21:08:58:703 CEST [DEBUG] TargetAuthenticationStrategy - Caching 'basic' auth scheme
for http://127.0.0.1:8777
RESPONSE STATUS: HTTP/1.1 200 OK - client is 127.0.0.1:510152013/06/19 21:08:58:706 CEST [DEBUG]
BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@e49d67c
2013/06/19 21:08:58:706 CEST [DEBUG] BasicClientConnectionManager - Connection can be kept
alive indefinitely

RESPONSE BODY - SKIPPED

REQUEST: GET http://127.0.0.1:8777/authenticated.html
2013/06/19 21:08:58:708 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
RESPONSE STATUS: HTTP/1.1 400 This is a request body - client is 127.0.0.1:51015
--> BUG! Response status 400
RESPONSE BODY - SKIPPED
2013/06/19 21:08:58:708 CEST [DEBUG] DefaultHttpClient - Stale connection check
2013/06/19 21:08:58:709 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:08:58:709 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:08:58:709 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:08:58:709 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:08:58:709 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:08:58:709 CEST [DEBUG] DefaultClientConnection - Sending request: GET /authenticated.html
HTTP/1.1
2013/06/19 21:08:58:709 CEST [DEBUG] headers - >> GET /authenticated.html HTTP/1.1
2013/06/19 21:08:58:710 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:08:58:710 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:08:58:710 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:08:58:710 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
400 This is a request body - client is 127.0.0.1:51015
2013/06/19 21:08:58:710 CEST [DEBUG] headers - << HTTP/1.1 400 This is a request body
- client is 127.0.0.1:51015
2013/06/19 21:08:58:711 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@11a06e38
2013/06/19 21:08:58:712 CEST [DEBUG] DefaultClientConnection - Connection 0.0.0.0:51015<->127.0.0.1:8777
shut down




This is the case without authentication. The connection is not reused which is correct (see
the 'connection shut down' line)


REQUEST: GET http://127.0.0.1:8777/non-authenticated.html
2013/06/19 21:11:27:973 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:11:28:001 CEST [DEBUG] DefaultClientConnectionOperator - Connecting to 127.0.0.1:8777
2013/06/19 21:11:28:028 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:11:28:043 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:11:28:043 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:11:28:044 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:11:28:044 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:11:28:044 CEST [DEBUG] DefaultClientConnection - Sending request: GET /non-authenticated.html
HTTP/1.1
2013/06/19 21:11:28:046 CEST [DEBUG] headers - >> GET /non-authenticated.html HTTP/1.1
2013/06/19 21:11:28:046 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:11:28:046 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:11:28:046 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:11:28:050 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
200 OK - client is 127.0.0.1:51025
2013/06/19 21:11:28:050 CEST [DEBUG] headers - << HTTP/1.1 200 OK - client is 127.0.0.1:51025
RESPONSE STATUS: HTTP/1.1 200 OK - client is 127.0.0.1:51025
2013/06/19 21:11:28:055 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@779b04e2
2013/06/19 21:11:28:056 CEST [DEBUG] DefaultClientConnection - Connection 0.0.0.0:51025<->127.0.0.1:8777
shut down
2013/06/19 21:11:28:056 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:11:28:057 CEST [DEBUG] DefaultClientConnectionOperator - Connecting to 127.0.0.1:8777
2013/06/19 21:11:28:066 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:11:28:066 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:11:28:066 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:11:28:066 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:11:28:066 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:11:28:066 CEST [DEBUG] DefaultClientConnection - Sending request: GET /non-authenticated.html
HTTP/1.1
2013/06/19 21:11:28:066 CEST [DEBUG] headers - >> GET /non-authenticated.html HTTP/1.1
2013/06/19 21:11:28:067 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:11:28:067 CEST [DEBUG] headers - >> Connection: Keep-Alive
RESPONSE BODY - SKIPPED

REQUEST: GET http://127.0.0.1:8777/non-authenticated.html
2013/06/19 21:11:28:067 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:11:28:103 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
200 OK - client is 127.0.0.1:51026
2013/06/19 21:11:28:103 CEST [DEBUG] headers - << HTTP/1.1 200 OK - client is 127.0.0.1:51026
RESPONSE STATUS: HTTP/1.1 200 OK - client is 127.0.0.1:51026
2013/06/19 21:11:28:103 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@7cb25b9d
2013/06/19 21:11:28:104 CEST [DEBUG] DefaultClientConnection - Connection 0.0.0.0:51026<->127.0.0.1:8777
shut down
RESPONSE BODY - SKIPPED
                
> HttpClient incorrectly reuses HTTP/1.1 connection - the response body of the first request
is considered as the response for the second request
> -----------------------------------------------------------------------------------------------------------------------------------------------
>
>                 Key: HTTPCLIENT-1376
>                 URL: https://issues.apache.org/jira/browse/HTTPCLIENT-1376
>             Project: HttpComponents HttpClient
>          Issue Type: Bug
>    Affects Versions: 4.2.4
>            Reporter: Carl D'Halluin
>
> In the following scenario, the HttpClient incorrectly reuses the HTTP/1.1 stream, and
actually considers the response body of the first request, to be the HTTP response to a second
request.
> Details:
> 1. Client does a simple HTTP/1.1 GET request
> 2. Server responds with a 401 and a WWW-Authenticate header
> 3. Client repeats the GET request but now with an Authorization header
> 4. Server responds with a HTTP/1.1 200 OK but there is no content length. The server
sends a response body
> 5. HttpClient ignores the response body by closing the entity content InputStream (or
call EntityUtils.consume)
> 6. Client sends a new HTTP/1.1 GET request (totally unrelated to the previous one)
> 7. Client erroneously considers the response body received in step 5 as the response
to step 6
> I tracked the bug down in the HttpClient library: Step 2 marks the HTTP connection as
reusable. Step 4 should explicitly mark the connection as non-reusable since the only thing
the client can do to such an ugly reponse (no content-length) is read until EOF. However,
that does not happen in step 4. Hence in step 5 the code sees that the connection is reusable,
and doesnt bother consuming the response content at all. The body is reused in step 7
> Here we see 4 times 2 subsequent request
> - first 2 are no authentication no streaming: HttpClient correctly does not reuse connection
(see port number)
> - next 2 are no authentication with streaming: HttpClient correctly does not reuse connection
> - next 2 are with authentication with streaming: HttpClient correctly does not reuse
connection
> - final 2 are with authentication no streaming: Bug - HttpClient tries to reuse connection
given error. Closing the HttpResponse InputStream does not correctly close the underlying
Socket
> {code}
> REQUEST: GET http://127.0.0.1:8777/non-authenticated.html
> RESPONSE STATUS: HTTP/1.1 200 OK - client is 127.0.0.1:49603
> RESPONSE BODY - SKIPPED
> REQUEST: GET http://127.0.0.1:8777/non-authenticated.html
> RESPONSE STATUS: HTTP/1.1 200 OK - client is 127.0.0.1:49604
> RESPONSE BODY - SKIPPED
> =======================
> REQUEST: GET http://127.0.0.1:8777/non-authenticated.html
> RESPONSE STATUS: HTTP/1.1 200 OK - client is 127.0.0.1:49605
> RESPONSE BODY:   HTTP/1.1 400 This is a request body - client is 127.0.0.1:49605
> RESPONSE BODY:   
> REQUEST: GET http://127.0.0.1:8777/non-authenticated.html
> RESPONSE STATUS: HTTP/1.1 200 OK - client is 127.0.0.1:49606
> RESPONSE BODY:   HTTP/1.1 400 This is a request body - client is 127.0.0.1:49606
> RESPONSE BODY:   
> =======================
> REQUEST: GET http://127.0.0.1:8777/authenticated.html
> RESPONSE STATUS: HTTP/1.1 200 OK - client is 127.0.0.1:49607
> RESPONSE BODY:   HTTP/1.1 400 This is a request body - client is 127.0.0.1:49607
> RESPONSE BODY:   
> REQUEST: GET http://127.0.0.1:8777/authenticated.html
> RESPONSE STATUS: HTTP/1.1 200 OK - client is 127.0.0.1:49608
> RESPONSE BODY:   HTTP/1.1 400 This is a request body - client is 127.0.0.1:49608
> RESPONSE BODY:   
> =======================
> REQUEST: GET http://127.0.0.1:8777/authenticated.html
> RESPONSE STATUS: HTTP/1.1 200 OK - client is 127.0.0.1:49609
> RESPONSE BODY - SKIPPED
> REQUEST: GET http://127.0.0.1:8777/authenticated.html
> RESPONSE STATUS: HTTP/1.1 400 This is a request body - client is 127.0.0.1:49609
> --> BUG! Response status 400
> RESPONSE BODY - SKIPPED
> {code}

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org


Mime
View raw message