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] [Comment Edited] (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:19: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 edited comment on HTTPCLIENT-1376 at 6/19/13 7:18 PM:
---------------------------------------------------------------------

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

2013/06/19 21:17:57:845 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:17:57:873 CEST [DEBUG] DefaultClientConnectionOperator - Connecting to 127.0.0.1:8777
2013/06/19 21:17:57:900 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:17:57:925 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:17:57:925 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:17:57:926 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:17:57:926 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:17:57:926 CEST [DEBUG] DefaultClientConnection - Sending request: GET /authenticated.html
HTTP/1.1
2013/06/19 21:17:57:927 CEST [DEBUG] wire - >> "GET /authenticated.html HTTP/1.1[\r][\n]"
2013/06/19 21:17:57:928 CEST [DEBUG] wire - >> "Host: 127.0.0.1:8777[\r][\n]"
2013/06/19 21:17:57:928 CEST [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
2013/06/19 21:17:57:929 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.2.4
(java 1.5)[\r][\n]"
2013/06/19 21:17:57:929 CEST [DEBUG] wire - >> "[\r][\n]"
2013/06/19 21:17:57:929 CEST [DEBUG] headers - >> GET /authenticated.html HTTP/1.1
2013/06/19 21:17:57:929 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:17:57:929 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:17:57:929 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:17:57:930 CEST [DEBUG] wire - << "HTTP/1.1 401 Unauthorized - client is
%s[\r][\n]"
2013/06/19 21:17:57:933 CEST [DEBUG] wire - << "Content-Length: 0[\r][\n]"
2013/06/19 21:17:57:933 CEST [DEBUG] wire - << "WWW-Authenticate: Basic realm="Amplidata"[\r][\n]"
2013/06/19 21:17:57:933 CEST [DEBUG] wire - << "[\r][\n]"
2013/06/19 21:17:57:934 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
401 Unauthorized - client is %s
2013/06/19 21:17:57:934 CEST [DEBUG] headers - << HTTP/1.1 401 Unauthorized - client
is %s
2013/06/19 21:17:57:934 CEST [DEBUG] headers - << Content-Length: 0
2013/06/19 21:17:57:934 CEST [DEBUG] headers - << WWW-Authenticate: Basic realm="Amplidata"
2013/06/19 21:17:57:939 CEST [DEBUG] DefaultHttpClient - Connection can be kept alive indefinitely
2013/06/19 21:17:57:940 CEST [DEBUG] DefaultHttpClient - Authentication required
2013/06/19 21:17:57:940 CEST [DEBUG] DefaultHttpClient - 127.0.0.1:8777 requested authentication
2013/06/19 21:17:57:940 CEST [DEBUG] TargetAuthenticationStrategy - Authentication schemes
in the order of preference: [negotiate, Kerberos, NTLM, Digest, Basic]
2013/06/19 21:17:57:941 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for negotiate
authentication scheme not available
2013/06/19 21:17:57:941 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for Kerberos
authentication scheme not available
2013/06/19 21:17:57:941 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for NTLM authentication
scheme not available
2013/06/19 21:17:57:941 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for Digest authentication
scheme not available
2013/06/19 21:17:57:946 CEST [DEBUG] DefaultHttpClient - Selected authentication options:
[BASIC]
2013/06/19 21:17:57:947 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:17:57:947 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:17:57:948 CEST [DEBUG] RequestTargetAuthentication - Target auth state: CHALLENGED
2013/06/19 21:17:57:948 CEST [DEBUG] RequestTargetAuthentication - Generating response to
an authentication challenge using basic scheme
2013/06/19 21:17:57:973 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:17:57:974 CEST [DEBUG] DefaultHttpClient - Attempt 2 to execute request
2013/06/19 21:17:57:974 CEST [DEBUG] DefaultClientConnection - Sending request: GET /authenticated.html
HTTP/1.1
2013/06/19 21:17:57:974 CEST [DEBUG] wire - >> "GET /authenticated.html HTTP/1.1[\r][\n]"
2013/06/19 21:17:57:974 CEST [DEBUG] wire - >> "Host: 127.0.0.1:8777[\r][\n]"
2013/06/19 21:17:57:974 CEST [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
2013/06/19 21:17:57:974 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.2.4
(java 1.5)[\r][\n]"
2013/06/19 21:17:57:974 CEST [DEBUG] wire - >> "Authorization: Basic dXNlcjpwYXNz[\r][\n]"
2013/06/19 21:17:57:974 CEST [DEBUG] wire - >> "[\r][\n]"
2013/06/19 21:17:57:975 CEST [DEBUG] headers - >> GET /authenticated.html HTTP/1.1
2013/06/19 21:17:57:975 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:17:57:975 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:17:57:975 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:17:57:975 CEST [DEBUG] headers - >> Authorization: Basic dXNlcjpwYXNz
2013/06/19 21:17:57:975 CEST [DEBUG] wire - << "HTTP/1.1 200 OK - client is 127.0.0.1:51050[\r][\n]"
2013/06/19 21:17:57:976 CEST [DEBUG] wire - << "[\r][\n]"
2013/06/19 21:17:57:976 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
200 OK - client is 127.0.0.1:51050
2013/06/19 21:17:57:976 CEST [DEBUG] headers - << HTTP/1.1 200 OK - client is 127.0.0.1:51050
2013/06/19 21:17:57:976 CEST [DEBUG] DefaultHttpClient - Authentication succeeded
2013/06/19 21:17:57:977 CEST [DEBUG] TargetAuthenticationStrategy - Caching 'basic' auth scheme
for http://127.0.0.1:8777
2013/06/19 21:17:57:981 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@2d8941f7
2013/06/19 21:17:57:981 CEST [DEBUG] BasicClientConnectionManager - Connection can be kept
alive indefinitely
2013/06/19 21:17:57:981 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:17:57:981 CEST [DEBUG] DefaultHttpClient - Stale connection check
2013/06/19 21:17:57:981 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:17:57:982 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:17:57:982 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:17:57:982 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:17:57:982 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:17:57:982 CEST [DEBUG] DefaultClientConnection - Sending request: GET /authenticated.html
HTTP/1.1
2013/06/19 21:17:57:982 CEST [DEBUG] wire - >> "GET /authenticated.html HTTP/1.1[\r][\n]"
2013/06/19 21:17:57:982 CEST [DEBUG] wire - >> "Host: 127.0.0.1:8777[\r][\n]"
2013/06/19 21:17:57:982 CEST [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
2013/06/19 21:17:57:983 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.2.4
(java 1.5)[\r][\n]"
2013/06/19 21:17:57:983 CEST [DEBUG] wire - >> "[\r][\n]"
2013/06/19 21:17:57:983 CEST [DEBUG] headers - >> GET /authenticated.html HTTP/1.1
2013/06/19 21:17:57:983 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:17:57:983 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:17:57:983 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:17:57:984 CEST [DEBUG] wire - << "HTTP/1.1 400 This is a request body
- client is 127.0.0.1:51050[\r][\n]"
2013/06/19 21:17:57:984 CEST [DEBUG] wire - << "[\r][\n]"
2013/06/19 21:17:57:984 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
400 This is a request body - client is 127.0.0.1:51050
2013/06/19 21:17:57:984 CEST [DEBUG] headers - << HTTP/1.1 400 This is a request body
- client is 127.0.0.1:51050
2013/06/19 21:17:57:984 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@e49d67c
2013/06/19 21:17:57:985 CEST [DEBUG] DefaultClientConnection - Connection 0.0.0.0:51050<->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)


2013/06/19 21:18:48:287 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:18:48:316 CEST [DEBUG] DefaultClientConnectionOperator - Connecting to 127.0.0.1:8777
2013/06/19 21:18:48:345 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:18:48:370 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:18:48:371 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:18:48:382 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:18:48:382 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:18:48:383 CEST [DEBUG] DefaultClientConnection - Sending request: GET /non-authenticated.html
HTTP/1.1
2013/06/19 21:18:48:384 CEST [DEBUG] wire - >> "GET /non-authenticated.html HTTP/1.1[\r][\n]"
2013/06/19 21:18:48:386 CEST [DEBUG] wire - >> "Host: 127.0.0.1:8777[\r][\n]"
2013/06/19 21:18:48:386 CEST [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
2013/06/19 21:18:48:386 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.2.4
(java 1.5)[\r][\n]"
2013/06/19 21:18:48:386 CEST [DEBUG] wire - >> "[\r][\n]"
2013/06/19 21:18:48:386 CEST [DEBUG] headers - >> GET /non-authenticated.html HTTP/1.1
2013/06/19 21:18:48:387 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:18:48:387 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:18:48:387 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:18:48:388 CEST [DEBUG] wire - << "HTTP/1.1 200 OK - client is 127.0.0.1:51059[\r][\n]"
2013/06/19 21:18:48:391 CEST [DEBUG] wire - << "[\r][\n]"
2013/06/19 21:18:48:391 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
200 OK - client is 127.0.0.1:51059
2013/06/19 21:18:48:391 CEST [DEBUG] headers - << HTTP/1.1 200 OK - client is 127.0.0.1:51059
2013/06/19 21:18:48:396 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@7cb25b9d
2013/06/19 21:18:48:397 CEST [DEBUG] DefaultClientConnection - Connection 0.0.0.0:51059<->127.0.0.1:8777
shut down
2013/06/19 21:18:48:398 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:18:48:398 CEST [DEBUG] DefaultClientConnectionOperator - Connecting to 127.0.0.1:8777
2013/06/19 21:18:48:399 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:18:48:399 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:18:48:399 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:18:48:400 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:18:48:400 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:18:48:400 CEST [DEBUG] DefaultClientConnection - Sending request: GET /non-authenticated.html
HTTP/1.1
2013/06/19 21:18:48:400 CEST [DEBUG] wire - >> "GET /non-authenticated.html HTTP/1.1[\r][\n]"
2013/06/19 21:18:48:400 CEST [DEBUG] wire - >> "Host: 127.0.0.1:8777[\r][\n]"
2013/06/19 21:18:48:400 CEST [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
2013/06/19 21:18:48:401 CEST [DEBUG] wire - >> "User-Agent: Apache-HttpClient/4.2.4
(java 1.5)[\r][\n]"
2013/06/19 21:18:48:402 CEST [DEBUG] wire - >> "[\r][\n]"
2013/06/19 21:18:48:402 CEST [DEBUG] headers - >> GET /non-authenticated.html HTTP/1.1
2013/06/19 21:18:48:402 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:18:48:402 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:18:48:402 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:18:48:402 CEST [DEBUG] wire - << "HTTP/1.1 200 OK - client is 127.0.0.1:51060[\r][\n]"
2013/06/19 21:18:48:403 CEST [DEBUG] wire - << "[\r][\n]"
2013/06/19 21:18:48:403 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
200 OK - client is 127.0.0.1:51060
2013/06/19 21:18:48:403 CEST [DEBUG] headers - << HTTP/1.1 200 OK - client is 127.0.0.1:51060
2013/06/19 21:18:48:403 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@424ecfdd
2013/06/19 21:18:48:403 CEST [DEBUG] DefaultClientConnection - Connection 0.0.0.0:51060<->127.0.0.1:8777
shut down

                
      was (Author: carldhalluin):
    This is the log for the case with authentication. The connection is reused which is incorrect.

2013/06/19 21:16:47:744 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:16:47:773 CEST [DEBUG] DefaultClientConnectionOperator - Connecting to 127.0.0.1:8777
2013/06/19 21:16:47:798 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:16:47:813 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:16:47:813 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:16:47:814 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:16:47:814 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:16:47:814 CEST [DEBUG] DefaultClientConnection - Sending request: GET /authenticated.html
HTTP/1.1
2013/06/19 21:16:47:816 CEST [DEBUG] headers - >> GET /authenticated.html HTTP/1.1
2013/06/19 21:16:47:816 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:16:47:816 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:16:47:816 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:16:47:820 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
401 Unauthorized - client is %s
2013/06/19 21:16:47:820 CEST [DEBUG] headers - << HTTP/1.1 401 Unauthorized - client
is %s
2013/06/19 21:16:47:820 CEST [DEBUG] headers - << Content-Length: 0
2013/06/19 21:16:47:821 CEST [DEBUG] headers - << WWW-Authenticate: Basic realm="Amplidata"
2013/06/19 21:16:47:825 CEST [DEBUG] DefaultHttpClient - Connection can be kept alive indefinitely
2013/06/19 21:16:47:825 CEST [DEBUG] DefaultHttpClient - Authentication required
2013/06/19 21:16:47:826 CEST [DEBUG] DefaultHttpClient - 127.0.0.1:8777 requested authentication
2013/06/19 21:16:47:826 CEST [DEBUG] TargetAuthenticationStrategy - Authentication schemes
in the order of preference: [negotiate, Kerberos, NTLM, Digest, Basic]
2013/06/19 21:16:47:826 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for negotiate
authentication scheme not available
2013/06/19 21:16:47:827 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for Kerberos
authentication scheme not available
2013/06/19 21:16:47:827 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for NTLM authentication
scheme not available
2013/06/19 21:16:47:827 CEST [DEBUG] TargetAuthenticationStrategy - Challenge for Digest authentication
scheme not available
2013/06/19 21:16:47:832 CEST [DEBUG] DefaultHttpClient - Selected authentication options:
[BASIC]
2013/06/19 21:16:47:833 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:16:47:833 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:16:47:833 CEST [DEBUG] RequestTargetAuthentication - Target auth state: CHALLENGED
2013/06/19 21:16:47:833 CEST [DEBUG] RequestTargetAuthentication - Generating response to
an authentication challenge using basic scheme
2013/06/19 21:16:47:858 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:16:47:859 CEST [DEBUG] DefaultHttpClient - Attempt 2 to execute request
2013/06/19 21:16:47:859 CEST [DEBUG] DefaultClientConnection - Sending request: GET /authenticated.html
HTTP/1.1
2013/06/19 21:16:47:859 CEST [DEBUG] headers - >> GET /authenticated.html HTTP/1.1
2013/06/19 21:16:47:859 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:16:47:860 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:16:47:860 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:16:47:860 CEST [DEBUG] headers - >> Authorization: Basic dXNlcjpwYXNz
2013/06/19 21:16:47:867 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
200 OK - client is 127.0.0.1:51043
2013/06/19 21:16:47:867 CEST [DEBUG] headers - << HTTP/1.1 200 OK - client is 127.0.0.1:51043
2013/06/19 21:16:47:868 CEST [DEBUG] DefaultHttpClient - Authentication succeeded
2013/06/19 21:16:47:869 CEST [DEBUG] TargetAuthenticationStrategy - Caching 'basic' auth scheme
for http://127.0.0.1:8777
2013/06/19 21:16:47:872 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@50618d26
2013/06/19 21:16:47:872 CEST [DEBUG] BasicClientConnectionManager - Connection can be kept
alive indefinitely
2013/06/19 21:16:47:873 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:16:47:873 CEST [DEBUG] DefaultHttpClient - Stale connection check
2013/06/19 21:16:47:873 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:16:47:874 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:16:47:874 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:16:47:874 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:16:47:874 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:16:47:874 CEST [DEBUG] DefaultClientConnection - Sending request: GET /authenticated.html
HTTP/1.1
2013/06/19 21:16:47:875 CEST [DEBUG] headers - >> GET /authenticated.html HTTP/1.1
2013/06/19 21:16:47:875 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:16:47:875 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:16:47:875 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:16:47:875 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
400 This is a request body - client is 127.0.0.1:51043
2013/06/19 21:16:47:876 CEST [DEBUG] headers - << HTTP/1.1 400 This is a request body
- client is 127.0.0.1:51043
2013/06/19 21:16:47:876 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@3479e304
2013/06/19 21:16:47:877 CEST [DEBUG] DefaultClientConnection - Connection 0.0.0.0:51043<->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)


2013/06/19 21:16:11:851 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:16:11:879 CEST [DEBUG] DefaultClientConnectionOperator - Connecting to 127.0.0.1:8777
2013/06/19 21:16:11:905 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:16:11:922 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:16:11:922 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:16:11:923 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:16:11:924 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:16:11:924 CEST [DEBUG] DefaultClientConnection - Sending request: GET /non-authenticated.html
HTTP/1.1
2013/06/19 21:16:11:926 CEST [DEBUG] headers - >> GET /non-authenticated.html HTTP/1.1
2013/06/19 21:16:11:926 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:16:11:926 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:16:11:926 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:16:11:939 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
200 OK - client is 127.0.0.1:51034
2013/06/19 21:16:11:939 CEST [DEBUG] headers - << HTTP/1.1 200 OK - client is 127.0.0.1:51034
2013/06/19 21:16:11:945 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@625dcec6
2013/06/19 21:16:11:946 CEST [DEBUG] DefaultClientConnection - Connection 0.0.0.0:51034<->127.0.0.1:8777
shut down
2013/06/19 21:16:11:947 CEST [DEBUG] BasicClientConnectionManager - Get connection for route
{}->http://127.0.0.1:8777
2013/06/19 21:16:11:947 CEST [DEBUG] DefaultClientConnectionOperator - Connecting to 127.0.0.1:8777
2013/06/19 21:16:11:948 CEST [DEBUG] RequestAddCookies - CookieSpec selected: best-match
2013/06/19 21:16:11:948 CEST [DEBUG] RequestAuthCache - Auth cache not set in the context
2013/06/19 21:16:11:948 CEST [DEBUG] RequestTargetAuthentication - Target auth state: UNCHALLENGED
2013/06/19 21:16:11:948 CEST [DEBUG] RequestProxyAuthentication - Proxy auth state: UNCHALLENGED
2013/06/19 21:16:11:948 CEST [DEBUG] DefaultHttpClient - Attempt 1 to execute request
2013/06/19 21:16:11:948 CEST [DEBUG] DefaultClientConnection - Sending request: GET /non-authenticated.html
HTTP/1.1
2013/06/19 21:16:11:948 CEST [DEBUG] headers - >> GET /non-authenticated.html HTTP/1.1
2013/06/19 21:16:11:948 CEST [DEBUG] headers - >> Host: 127.0.0.1:8777
2013/06/19 21:16:11:949 CEST [DEBUG] headers - >> Connection: Keep-Alive
2013/06/19 21:16:11:949 CEST [DEBUG] headers - >> User-Agent: Apache-HttpClient/4.2.4
(java 1.5)
2013/06/19 21:16:11:949 CEST [DEBUG] DefaultClientConnection - Receiving response: HTTP/1.1
200 OK - client is 127.0.0.1:51035
2013/06/19 21:16:11:949 CEST [DEBUG] headers - << HTTP/1.1 200 OK - client is 127.0.0.1:51035
2013/06/19 21:16:11:949 CEST [DEBUG] BasicClientConnectionManager - Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@219ce060
2013/06/19 21:16:11:949 CEST [DEBUG] DefaultClientConnection - Connection 0.0.0.0:51035<->127.0.0.1:8777
shut down

                  
> 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