hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Arthur Pilyuk (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HTTPCLIENT-1340) Connection re-used in a inconsistent state despite 'Connection: close' after successful authentication
Date Sun, 05 Jan 2014 12:03:50 GMT

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

Arthur Pilyuk commented on HTTPCLIENT-1340:
-------------------------------------------

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

What I send:
BODY [[{"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:
- Get connection for route {}->http://localhost:443
- Connecting to localhost:443
- CookieSpec selected: ignoreCookies
- Auth cache not set in the context
- Target auth state: UNCHALLENGED
- Proxy auth state: UNCHALLENGED
- Attempt 1 to execute request
- Sending request: POST /url HTTP/1.1
- >> "POST /url HTTP/1.1[\r][\n]"
- >> "Accept: */*[\r][\n]"
- >> "Cookie: COMMANDER_SESSION_ID=s3dqutba9jpkkc6mv8ml42h9u6[\r][\n]"
- >> "Content-Length: 283[\r][\n]"
- >> "Content-Type: application/octet-stream; charset=ISO-8859-1[\r][\n]"
- >> "Host: localhost:443[\r][\n]"
- >> "Connection: Keep-Alive[\r][\n]"
- >> "User-Agent: Apache-HttpClient/4.2.6 (java 1.5)[\r][\n]"
- >> "Accept-Encoding: gzip,deflate[\r][\n]"
- >> "[\r][\n]"
- >> POST /url HTTP/1.1
- >> Accept: */*
- >> Cookie: COMMANDER_SESSION_ID=s3dqutba9jpkkc6mv8ml42h9u6
- >> Content-Length: 283
- >> Content-Type: application/octet-stream; charset=ISO-8859-1
- >> Host: localhost:443
- >> Connection: Keep-Alive
- >> User-Agent: Apache-HttpClient/4.2.6 (java 1.5)
- >> Accept-Encoding: gzip,deflate
- >> "[[{"operation":"createComponent","parameters":{"projectName":"Default","componentName":"CompName
0","groupId":"groupdId","artifactId":"artifactId","repositoryType":"ECAM","componentType":"repository","url":"repository","artifactVersion":"url"},
"requestId":"0.3667526548400687"}],{}]"
- << "f??4[0xc]??????Ay9U?Q???c???????????U?[0x1b]????'????w[0x1d]?[\r]?:?8I???eR[0x1b][0x10]A~W[0x1c]?jS?9[0x16][0xf]tU???1???????)F$E??p??el*?V?[\r][\n]"
í:ã8IæŸÄeRA~WÝjSè9tU‚‹À1®ÇÌ͚Ø)F$E²ûp¬Èel*ÇV²
- Connection 0.0.0.0:61376<->127.0.0.1:443 closed
- Connection 0.0.0.0:61376<->127.0.0.1:443 shut down
- Releasing connection org.apache.http.impl.conn.ManagedClientConnectionImpl@36f7b10b

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:
- << "f??4[0xc]??????Ay9U?Q???c???????????U?[0x1b]????'????w[0x1d]?[\r]?:?8I???eR[0x1b][0x10]A~W[0x1c]?jS?9[0x16][0xf]tU???1???????)F$E??p??el*?V?[\r][\n]"
í:ã8IæŸÄeRA~WÝjSè9tU‚‹À1®ÇÌ͚Ø)F$E²ûp¬Èel*ÇV²
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: dev-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org


Mime
View raw message