[jira] [Issue Comment Deleted] (HTTPCLIENT-1340) Connection re-used in a inconsistent state despite 'Connection: close' after successful authentication

Arthur Pilyuk (JIRA) Sun, 05 Jan 2014 04:42:26 -0800

     [ 
https://issues.apache.org/jira/browse/HTTPCLIENT-1340?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]


Arthur Pilyuk updated HTTPCLIENT-1340:
--------------------------------------

    Comment: was deleted

(was: Hi, guys!
I have same issue on httpclient:4.2.6.

*What I send:*
[[{"operation":"createComponent","parameters":{"projectName":"Default","componentName":"CompName
 
0","groupId":"groupdId","artifactId":"artifactId","repositoryType":"ECAM","componentType":"repository","url":"repository","artifactVersion":"url"},
 "requestId":"0.3667526548400687"}],{}]

*What I get:*
14:07:42,659 DEBUG BasicClientConnectionManager:159 - Get connection for route 
{}->http://localhost:443
14:07:42,662 DEBUG DefaultClientConnectionOperator:177 - Connecting to 
localhost:443
14:07:42,666 DEBUG RequestAddCookies:132 - CookieSpec selected: ignoreCookies
14:07:42,669 DEBUG RequestAuthCache:78 - Auth cache not set in the context
14:07:42,670 DEBUG RequestTargetAuthentication:78 - Target auth state: 
UNCHALLENGED
14:07:42,671 DEBUG RequestProxyAuthentication:87 - Proxy auth state: 
UNCHALLENGED
14:07:42,672 DEBUG DefaultHttpClient:713 - Attempt 1 to execute request
14:07:42,672 DEBUG DefaultClientConnection:269 - Sending request: POST /url 
HTTP/1.1
14:07:42,673 DEBUG wire:63 - >> "POST /url HTTP/1.1[\r][\n]"
14:07:42,673 DEBUG wire:63 - >> "Accept: */*[\r][\n]"
14:07:42,674 DEBUG wire:63 - >> "Cookie: 
COMMANDER_SESSION_ID=s3dqutba9jpkkc6mv8ml42h9u6[\r][\n]"
14:07:42,675 DEBUG wire:63 - >> "Content-Length: 284[\r][\n]"
14:07:42,675 DEBUG wire:63 - >> "Content-Type: application/octet-stream; 
charset=ISO-8859-1[\r][\n]"
14:07:42,677 DEBUG wire:63 - >> "Host: localhost:443[\r][\n]"
14:07:42,678 DEBUG wire:63 - >> "Connection: Keep-Alive[\r][\n]"
14:07:42,679 DEBUG wire:63 - >> "User-Agent: Apache-HttpClient/4.2.6 (java 
1.5)[\r][\n]"
14:07:42,681 DEBUG wire:63 - >> "Accept-Encoding: gzip,deflate[\r][\n]"
14:07:42,682 DEBUG wire:63 - >> "[\r][\n]"
14:07:42,683 DEBUG headers:273 - >> POST /url HTTP/1.1
14:07:42,685 DEBUG headers:276 - >> Accept: */*
14:07:42,686 DEBUG headers:276 - >> Cookie: 
COMMANDER_SESSION_ID=s3dqutba9jpkkc6mv8ml42h9u6
14:07:42,687 DEBUG headers:276 - >> Content-Length: 284
14:07:42,688 DEBUG headers:276 - >> Content-Type: application/octet-stream; 
charset=ISO-8859-1
14:07:42,689 DEBUG headers:276 - >> Host: localhost:443
14:07:42,690 DEBUG headers:276 - >> Connection: Keep-Alive
14:07:42,690 DEBUG headers:276 - >> User-Agent: Apache-HttpClient/4.2.6 (java 
1.5)
14:07:42,691 DEBUG headers:276 - >> Accept-Encoding: gzip,deflate
14:07:42,692 DEBUG wire:77 - >> 
"[[{"operation":"createComponent","parameters":{"projectName":"Default","componentName":"CompName
 
0","groupId":"groupdId","artifactId":"artifactId","repositoryType":"ECAM","componentType":"repository","url":"repository","artifactVersion":"url"},
 "requestId":"0.30660520270012304"}],{}]"
{color:red}14:07:42,694 DEBUG wire:63 - << 
"[0x19]??8j????X?[0xb]B[0x4]????|?C?,?@YB\[0x2][\r][\n]"
14:07:42,695 DEBUG DefaultHttpResponseParser:107 - Garbage in response: 
¥8jõXBÀÍ|C,@YB\
14:07:42,696 DEBUG wire:63 - << 
"?_[0xf]??o?u?o[0x14][0x16]???lO?i??d??;?a[0x1e]w??[\r][\n]"
14:07:42,698 DEBUG DefaultHttpResponseParser:107 - Garbage in response: 
¾_ã¹ouÔoülOi¿dò;°aw¼ý
14:07:42,702 DEBUG wire:63 - << 
"s?Y?/[0x14]u"?`QN?l?:?8I???eR[0x1b][0x10]A~W[0x1c]?jS?9[0x16][0xf]t?(u.????[\r][\n]"
14:07:42,703 DEBUG DefaultHttpResponseParser:107 - Garbage in response: 
sY¶/u"«`QNçlí:ã8IæÄeRA~WÝjSè9tà(u.¥¼
{color}
14:07:42,704 DEBUG DefaultClientConnection:169 - Connection 
0.0.0.0:61789<->127.0.0.1:443 closed
14:07:42,705 DEBUG DefaultClientConnection:154 - Connection 
0.0.0.0:61789<->127.0.0.1:443 shut down
14:07:42,706 DEBUG BasicClientConnectionManager:201 - Releasing connection 
org.apache.http.impl.conn.ManagedClientConnectionImpl@236e4a57

*P.S. I am able to execute properly some other requests, like "create 
application"*
[[{"operation":"createApplication","parameters":{"projectName":"Default","applicationName":"AppName
 0"}, "requestId":"0.3164679326105345"}],{}] 
etc.

*I think that problem is here:*
14:07:42,694 DEBUG wire:63 - << 
"[0x19]??8j????X?[0xb]B[0x4]????|?C?,?@YB\[0x2][\r][\n]"
14:07:42,695 DEBUG DefaultHttpResponseParser:107 - Garbage in response: 
¥8jõXBÀÍ|C,@YB\
14:07:42,696 DEBUG wire:63 - << 
"?_[0xf]??o?u?o[0x14][0x16]???lO?i??d??;?a[0x1e]w??[\r][\n]"
14:07:42,698 DEBUG DefaultHttpResponseParser:107 - Garbage in response: 
¾_ã¹ouÔoülOi¿dò;°aw¼ý
14:07:42,702 DEBUG wire:63 - << 
"s?Y?/[0x14]u"?`QN?l?:?8I???eR[0x1b][0x10]A~W[0x1c]?jS?9[0x16][0xf]t?(u.????[\r][\n]"
14:07:42,703 DEBUG DefaultHttpResponseParser:107 - Garbage in response: 
sY¶/u"«`QNçlí:ã8IæÄeRA~WÝjSè9tà(u.¥¼
*But I don`t know how to identify reason of such behaviour.*)

> Connection re-used in a inconsistent state despite 'Connection: close' after 
> successful authentication 
> -------------------------------------------------------------------------------------------------------
>
>                 Key: HTTPCLIENT-1340
>                 URL: https://issues.apache.org/jira/browse/HTTPCLIENT-1340
>             Project: HttpComponents HttpClient
>          Issue Type: Bug
>    Affects Versions: 4.2.4, 4.3 Beta1
>            Reporter: Igor Fedorenko
>            Priority: Critical
>             Fix For: 4.2.5
>
>         Attachments: HTTPCLIENT1340.java, hc4.log
>
>
> The problem was originally observed when using maven 3.0.5 and newer with 
> maven repositories served by nginx that has username/password authentication 
> and connection keep-alive enabled. 
> I was able to reproduce the problem using standalone test application that 
> executes the same HttpGet request in a loop. Below is wire log of the last 
> two iterations that lead to "ProtocolException: The server failed to respond 
> with a valid HTTP response". From the log the client apparently stopped 
> processing of the response with Connection:close heaader and then reused the 
> connection for the next request.
> {noformat}
> 2013/04/12 11:48:02:745 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Stale connection check
> 2013/04/12 11:48:02:746 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Attempt 1 to execute request
> 2013/04/12 11:48:02:747 EDT [DEBUG] wire - >> "GET 
> /content/groups/sonatype-grid/.meta/prefixes.txt HTTP/1.1[\r][\n]"
> 2013/04/12 11:48:02:747 EDT [DEBUG] wire - >> "Host: 
> repository.sonatype.org[\r][\n]"
> 2013/04/12 11:48:02:747 EDT [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
> 2013/04/12 11:48:02:747 EDT [DEBUG] wire - >> "[\r][\n]"
> 2013/04/12 11:48:02:782 EDT [DEBUG] wire - << "HTTP/1.1 401 
> Unauthorized[\r][\n]"
> 2013/04/12 11:48:02:782 EDT [DEBUG] wire - << "Server: nginx/0.8.54[\r][\n]"
> 2013/04/12 11:48:02:782 EDT [DEBUG] wire - << "Date: Fri, 12 Apr 2013 
> 15:48:02 GMT[\r][\n]"
> 2013/04/12 11:48:02:782 EDT [DEBUG] wire - << "Connection: keep-alive[\r][\n]"
> 2013/04/12 11:48:02:782 EDT [DEBUG] wire - << "Keep-Alive: timeout=5[\r][\n]"
> 2013/04/12 11:48:02:783 EDT [DEBUG] wire - << "Set-Cookie: 
> rememberMe=deleteMe; Path=/; Max-Age=0; Expires=Thu, 11-Apr-2013 15:48:02 
> GMT[\r][\n]"
> 2013/04/12 11:48:02:783 EDT [DEBUG] wire - << "WWW-Authenticate: BASIC 
> realm="Sonatype Nexus Repository Manager"[\r][\n]"
> 2013/04/12 11:48:02:783 EDT [DEBUG] wire - << "Content-Length: 0[\r][\n]"
> 2013/04/12 11:48:02:783 EDT [DEBUG] wire - << "[\r][\n]"
> 2013/04/12 11:48:02:783 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Connection can be kept alive for 5000 MILLISECONDS
> 2013/04/12 11:48:02:783 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Authentication required
> 2013/04/12 11:48:02:783 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> repository.sonatype.org:443 requested authentication
> 2013/04/12 11:48:02:795 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Selected authentication options: [BASIC]
> 2013/04/12 11:48:02:796 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Attempt 2 to execute request
> 2013/04/12 11:48:02:796 EDT [DEBUG] wire - >> "GET 
> /content/groups/sonatype-grid/.meta/prefixes.txt HTTP/1.1[\r][\n]"
> 2013/04/12 11:48:02:796 EDT [DEBUG] wire - >> "Host: 
> repository.sonatype.org[\r][\n]"
> 2013/04/12 11:48:02:796 EDT [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
> 2013/04/12 11:48:02:796 EDT [DEBUG] wire - >> "Authorization: Basic XXX 
> [\r][\n]"
> 2013/04/12 11:48:02:796 EDT [DEBUG] wire - >> "[\r][\n]"
> 2013/04/12 11:48:02:840 EDT [DEBUG] wire - << "HTTP/1.1 200 OK[\r][\n]"
> 2013/04/12 11:48:02:840 EDT [DEBUG] wire - << "Server: nginx/0.8.54[\r][\n]"
> 2013/04/12 11:48:02:840 EDT [DEBUG] wire - << "Date: Fri, 12 Apr 2013 
> 15:48:02 GMT[\r][\n]"
> 2013/04/12 11:48:02:840 EDT [DEBUG] wire - << "Content-Type: 
> text/plain[\r][\n]"
> 2013/04/12 11:48:02:840 EDT [DEBUG] wire - << "Connection: keep-alive[\r][\n]"
> 2013/04/12 11:48:02:840 EDT [DEBUG] wire - << "Keep-Alive: timeout=5[\r][\n]"
> 2013/04/12 11:48:02:840 EDT [DEBUG] wire - << "Set-Cookie: 
> rememberMe=deleteMe; Path=/; Max-Age=0; Expires=Thu, 11-Apr-2013 15:48:02 
> GMT[\r][\n]"
> 2013/04/12 11:48:02:840 EDT [DEBUG] wire - << "Last-Modified: Fri, 12 Apr 
> 2013 08:22:54 GMT[\r][\n]"
> 2013/04/12 11:48:02:840 EDT [DEBUG] wire - << "ETag: 
> "{SHA1{3cf8e81cedbd285b8c745289d7184315762ca578}}"[\r][\n]"
> 2013/04/12 11:48:02:841 EDT [DEBUG] wire - << "Vary: Accept-Charset, 
> Accept-Encoding, Accept-Language, Accept[\r][\n]"
> 2013/04/12 11:48:02:841 EDT [DEBUG] wire - << "X-Content-Type-Options: 
> nosniff[\r][\n]"
> 2013/04/12 11:48:02:841 EDT [DEBUG] wire - << "Content-Length: 100[\r][\n]"
> 2013/04/12 11:48:02:841 EDT [DEBUG] wire - << "[\r][\n]"
> 2013/04/12 11:48:02:841 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Connection can be kept alive for 5000 MILLISECONDS
> 2013/04/12 11:48:02:841 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Authentication succeeded
> 2013/04/12 11:48:02:841 EDT [DEBUG] wire - << "@ unsupported[\n]"
> 2013/04/12 11:48:02:841 EDT [DEBUG] wire - << "# Prefix file generated by 
> Sonatype Nexus[\n]"
> 2013/04/12 11:48:02:841 EDT [DEBUG] wire - << "# Do not edit, changes will be 
> overwritten![\n]"
> 2013/04/12 11:48:02:841 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Stale connection check
> 2013/04/12 11:48:02:843 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Attempt 1 to execute request
> 2013/04/12 11:48:02:843 EDT [DEBUG] wire - >> "GET 
> /content/groups/sonatype-grid/.meta/prefixes.txt HTTP/1.1[\r][\n]"
> 2013/04/12 11:48:02:843 EDT [DEBUG] wire - >> "Host: 
> repository.sonatype.org[\r][\n]"
> 2013/04/12 11:48:02:843 EDT [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
> 2013/04/12 11:48:02:843 EDT [DEBUG] wire - >> "[\r][\n]"
> 2013/04/12 11:48:02:878 EDT [DEBUG] wire - << "HTTP/1.1 401 
> Unauthorized[\r][\n]"
> 2013/04/12 11:48:02:878 EDT [DEBUG] wire - << "Server: nginx/0.8.54[\r][\n]"
> 2013/04/12 11:48:02:878 EDT [DEBUG] wire - << "Date: Fri, 12 Apr 2013 
> 15:48:02 GMT[\r][\n]"
> 2013/04/12 11:48:02:878 EDT [DEBUG] wire - << "Connection: keep-alive[\r][\n]"
> 2013/04/12 11:48:02:878 EDT [DEBUG] wire - << "Keep-Alive: timeout=5[\r][\n]"
> 2013/04/12 11:48:02:878 EDT [DEBUG] wire - << "Set-Cookie: 
> rememberMe=deleteMe; Path=/; Max-Age=0; Expires=Thu, 11-Apr-2013 15:48:02 
> GMT[\r][\n]"
> 2013/04/12 11:48:02:878 EDT [DEBUG] wire - << "WWW-Authenticate: BASIC 
> realm="Sonatype Nexus Repository Manager"[\r][\n]"
> 2013/04/12 11:48:02:878 EDT [DEBUG] wire - << "Content-Length: 0[\r][\n]"
> 2013/04/12 11:48:02:878 EDT [DEBUG] wire - << "[\r][\n]"
> 2013/04/12 11:48:02:879 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Connection can be kept alive for 5000 MILLISECONDS
> 2013/04/12 11:48:02:879 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Authentication required
> 2013/04/12 11:48:02:879 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> repository.sonatype.org:443 requested authentication
> 2013/04/12 11:48:02:879 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Selected authentication options: [BASIC]
> 2013/04/12 11:48:02:879 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Attempt 2 to execute request
> 2013/04/12 11:48:02:879 EDT [DEBUG] wire - >> "GET 
> /content/groups/sonatype-grid/.meta/prefixes.txt HTTP/1.1[\r][\n]"
> 2013/04/12 11:48:02:879 EDT [DEBUG] wire - >> "Host: 
> repository.sonatype.org[\r][\n]"
> 2013/04/12 11:48:02:879 EDT [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
> 2013/04/12 11:48:02:879 EDT [DEBUG] wire - >> "Authorization: Basic XXX 
> [\r][\n]"
> 2013/04/12 11:48:02:879 EDT [DEBUG] wire - >> "[\r][\n]"
> 2013/04/12 11:48:02:924 EDT [DEBUG] wire - << "HTTP/1.1 200 OK[\r][\n]"
> 2013/04/12 11:48:02:924 EDT [DEBUG] wire - << "Server: nginx/0.8.54[\r][\n]"
> 2013/04/12 11:48:02:924 EDT [DEBUG] wire - << "Date: Fri, 12 Apr 2013 
> 15:48:02 GMT[\r][\n]"
> 2013/04/12 11:48:02:924 EDT [DEBUG] wire - << "Content-Type: 
> text/plain[\r][\n]"
> 2013/04/12 11:48:02:925 EDT [DEBUG] wire - << "Connection: close[\r][\n]"
> 2013/04/12 11:48:02:925 EDT [DEBUG] wire - << "Set-Cookie: 
> rememberMe=deleteMe; Path=/; Max-Age=0; Expires=Thu, 11-Apr-2013 15:48:02 
> GMT[\r][\n]"
> 2013/04/12 11:48:02:925 EDT [DEBUG] wire - << "Last-Modified: Fri, 12 Apr 
> 2013 08:22:54 GMT[\r][\n]"
> 2013/04/12 11:48:02:925 EDT [DEBUG] wire - << "ETag: 
> "{SHA1{3cf8e81cedbd285b8c745289d7184315762ca578}}"[\r][\n]"
> 2013/04/12 11:48:02:925 EDT [DEBUG] wire - << "Vary: Accept-Charset, 
> Accept-Encoding, Accept-Language, Accept[\r][\n]"
> 2013/04/12 11:48:02:925 EDT [DEBUG] wire - << "X-Content-Type-Options: 
> nosniff[\r][\n]"
> 2013/04/12 11:48:02:925 EDT [DEBUG] wire - << "Content-Length: 100[\r][\n]"
> 2013/04/12 11:48:02:925 EDT [DEBUG] wire - << "[\r][\n]"
> 2013/04/12 11:48:02:925 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Authentication succeeded
> 2013/04/12 11:48:02:925 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Stale connection check
> 2013/04/12 11:48:02:926 EDT [DEBUG] DownloadMain$DefaultHttpClientImpl - 
> Attempt 1 to execute request
> 2013/04/12 11:48:02:926 EDT [DEBUG] wire - >> "GET 
> /content/groups/sonatype-grid/.meta/prefixes.txt HTTP/1.1[\r][\n]"
> 2013/04/12 11:48:02:926 EDT [DEBUG] wire - >> "Host: 
> repository.sonatype.org[\r][\n]"
> 2013/04/12 11:48:02:926 EDT [DEBUG] wire - >> "Connection: Keep-Alive[\r][\n]"
> 2013/04/12 11:48:02:926 EDT [DEBUG] wire - >> "[\r][\n]"
> 2013/04/12 11:48:02:926 EDT [DEBUG] wire - << "@ unsupported[\r][\n]"
> 2013/04/12 11:48:02:926 EDT [DEBUG] wire - << "# Prefix file generated by 
> Sonatype Nexus[\r][\n]"
> 2013/04/12 11:48:02:926 EDT [DEBUG] wire - << "# Do not edit, changes will be 
> overwritten![\r][\n]"
> 50 4975
> Exception in thread "main" org.apache.http.client.ClientProtocolException
>       at 
> org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:909)
>       at 
> org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
>       at 
> org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
>       at download.httpclient.ssl.DownloadMain.run(DownloadMain.java:80)
>       at download.httpclient.ssl.DownloadMain.main(DownloadMain.java:31)
> Caused by: org.apache.http.ProtocolException: The server failed to respond 
> with a valid HTTP response
>       at 
> org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:103)
>       at 
> org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:62)
>       at 
> org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:254)
>       at 
> org.apache.http.impl.AbstractHttpClientConnection.receiveResponseHeader(AbstractHttpClientConnection.java:289)
>       at 
> org.apache.http.impl.conn.DefaultClientConnection.receiveResponseHeader(DefaultClientConnection.java:252)
>       at 
> org.apache.http.impl.conn.ManagedClientConnectionImpl.receiveResponseHeader(ManagedClientConnectionImpl.java:191)
>       at 
> org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:300)
>       at 
> org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:127)
>       at 
> org.apache.http.impl.client.DefaultRequestDirector.tryExecute(DefaultRequestDirector.java:716)
>       at 
> org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:521)
>       at 
> org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
>       ... 4 more
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.1.5#6160)

---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]

[jira] [Issue Comment Deleted] (HTTPCLIENT-1340) Connection re-used in a inconsistent state despite 'Connection: close' after successful authentication

Reply via email to