[
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: [email protected]
For additional commands, e-mail: [email protected]
