Return-Path: X-Original-To: apmail-hc-dev-archive@www.apache.org Delivered-To: apmail-hc-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id BCD90101E3 for ; Mon, 6 Jan 2014 21:07:50 +0000 (UTC) Received: (qmail 50691 invoked by uid 500); 6 Jan 2014 21:07:50 -0000 Delivered-To: apmail-hc-dev-archive@hc.apache.org Received: (qmail 50655 invoked by uid 500); 6 Jan 2014 21:07:50 -0000 Mailing-List: contact dev-help@hc.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: "HttpComponents Project" Delivered-To: mailing list dev@hc.apache.org Received: (qmail 50647 invoked by uid 99); 6 Jan 2014 21:07:50 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 06 Jan 2014 21:07:50 +0000 Date: Mon, 6 Jan 2014 21:07:50 +0000 (UTC) From: "Johannes Kienzle (JIRA)" To: dev@hc.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (HTTPASYNC-63) ConnectionShutdownException when getting out-of-sequence 401 MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HTTPASYNC-63?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13863414#comment-13863414 ] Johannes Kienzle commented on HTTPASYNC-63: ------------------------------------------- Tested with the original issue posted above and confirmed that it works now. Thanks! > ConnectionShutdownException when getting out-of-sequence 401 > ------------------------------------------------------------ > > Key: HTTPASYNC-63 > URL: https://issues.apache.org/jira/browse/HTTPASYNC-63 > Project: HttpComponents HttpAsyncClient > Issue Type: Bug > Affects Versions: 4.0 Final > Environment: Server: IIS 7.5 > Client: Ubuntu 12.04 with HttpAsyncClient 4.0 Final, HttpClient 4.3.1 > Reporter: Johannes Kienzle > Fix For: 4.0.1 > > > When sending large requests to IIS 7.5 with NTLM authentication, an out-of-sequence 401 response causes HttpAsyncClient to close the connection (even though it's reusable) and eventually throw a ConnectionShutdownException. > See the below log for details. > POST https://mc-ex4-1-sfm.s2x.uncrap.local/EWS/exchange.asmx HTTP/1.1 > 2014/01/03 15:02:52:684 PST [DEBUG] MainClientExec - [exchange: 1] start execution > 2014/01/03 15:02:52:688 PST [DEBUG] RequestAddCookies - CookieSpec selected: best-match > 2014/01/03 15:02:52:697 PST [DEBUG] RequestAuthCache - Auth cache not set in the context > 2014/01/03 15:02:52:698 PST [DEBUG] InternalHttpAsyncClient - [exchange: 1] Request connection for {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443 > 2014/01/03 15:02:52:699 PST [DEBUG] PoolingNHttpClientConnectionMa > nager - Connection request: [route: {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20] > 2014/01/03 15:02:52:720 PST [DEBUG] PoolingNHttpClientConnectionManager - Connection leased: [id: http-outgoing-0][route: {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20] > 2014/01/03 15:02:52:726 PST [DEBUG] InternalHttpAsyncClient - [exchange: 1] Connection allocated: http-outgoing-0 [ACTIVE] > 2014/01/03 15:02:52:726 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][r:]: Set attribute http.nio.exchange-handler > 2014/01/03 15:02:52:726 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][rw:]: Event set [w] > 2014/01/03 15:02:52:726 PST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE]: Connected > 2014/01/03 15:02:52:727 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][rw:]: Set attribute http.nio.http-exchange-state > 2014/01/03 15:02:52:727 PST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] Request ready > 2014/01/03 15:02:52:727 PST [DEBUG] MainClientExec - Start connection routing > 2014/01/03 15:02:52:735 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 Upgrade session 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][rw:][ACTIVE][rw][NEED_UNWRAP][0][0][206][0] > 2014/01/03 15:02:52:735 PST [DEBUG] MainClientExec - Connection route established > 2014/01/03 15:02:52:735 PST [DEBUG] MainClientExec - [exchange: 1] Attempt 1 to execute request > 2014/01/03 15:02:52:735 PST [DEBUG] MainClientExec - Target auth state: UNCHALLENGED > 2014/01/03 15:02:52:736 PST [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED > 2014/01/03 15:02:52:736 PST [DEBUG] headers - http-outgoing-0 >> POST /EWS/exchange.asmx HTTP/1.1 > 2014/01/03 15:02:52:736 PST [DEBUG] headers - http-outgoing-0 >> Content-type: text/xml; charset=utf-8 > 2014/01/03 15:02:52:736 PST [DEBUG] headers - http-outgoing-0 >> Keep-Alive: 300 > 2014/01/03 15:02:52:736 PST [DEBUG] headers - http-outgoing-0 >> User-Agent: ExchangeServicesClient/0.0.0.0 > 2014/01/03 15:02:52:736 PST [DEBUG] headers - http-outgoing-0 >> Accept: text/xml > 2014/01/03 15:02:52:736 PST [DEBUG] headers - http-outgoing-0 >> Content-Length: 41113 > 2014/01/03 15:02:52:736 PST [DEBUG] headers - http-outgoing-0 >> Host: mc-ex4-1-sfm.s2x.uncrap.local > 2014/01/03 15:02:52:736 PST [DEBUG] headers - http-outgoing-0 >> Connection: Keep-Alive > 2014/01/03 15:02:52:738 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][rw:][ACTIVE][rw][NEED_UNWRAP][0][0][206][0]: Event set [w] > 2014/01/03 15:02:52:752 PST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] Output ready > 2014/01/03 15:02:52:753 PST [DEBUG] MainClientExec - [exchange: 1] produce content > 2014/01/03 15:02:52:753 PST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] [content length: 41113; pos: 4096; completed: false] > 2014/01/03 15:02:52:756 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][rw:w][ACTIVE][rw][NOT_HANDSHAKING][0][0][4373][0]: 4334 bytes written > 2014/01/03 15:02:52:756 PST [DEBUG] wire - http-outgoing-0 >> "POST /EWS/exchange.asmx HTTP/1.1[\r][\n]" > 2014/01/03 15:02:52:756 PST [DEBUG] wire - http-outgoing-0 >> "Content-type: text/xml; charset=utf-8[\r][\n]" > 2014/01/03 15:02:52:756 PST [DEBUG] wire - http-outgoing-0 >> "Keep-Alive: 300[\r][\n]" > 2014/01/03 15:02:52:756 PST [DEBUG] wire - http-outgoing-0 >> "User-Agent: ExchangeServicesClient/0.0.0.0[\r][\n]" > 2014/01/03 15:02:52:756 PST [DEBUG] wire - http-outgoing-0 >> "Accept: text/xml[\r][\n]" > 2014/01/03 15:02:52:757 PST [DEBUG] wire - http-outgoing-0 >> "Content-Length: 41113[\r][\n]" > 2014/01/03 15:02:52:757 PST [DEBUG] wire - http-outgoing-0 >> "Host: mc-ex4-1-sfm.s2x.uncrap.local[\r][\n]" > 2014/01/03 15:02:52:757 PST [DEBUG] wire - http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]" > 2014/01/03 15:02:52:757 PST [DEBUG] wire - http-outgoing-0 >> "[\r][\n]" > 2014/01/03 15:02:52:758 PST [DEBUG] wire - http-outgoing-0 >> "" > 2014/01/03 15:02:52:766 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][rw:rw][ACTIVE][rw][NOT_HANDSHAKING][0][0][0][0]: 369 bytes read > 2014/01/03 15:02:52:767 PST [DEBUG] wire - http-outgoing-0 << "HTTP/1.1 401 Unauthorized[\r][\n]" > 2014/01/03 15:02:52:767 PST [DEBUG] wire - http-outgoing-0 << "Server: Microsoft-IIS/7.5[\r][\n]" > 2014/01/03 15:02:52:767 PST [DEBUG] wire - http-outgoing-0 << "Set-Cookie: exchangecookie=75fd3fbf79da43df8252fdd2d65e6cd4; expires=Sat, 03-Jan-2015 23:02:38 GMT; path=/; HttpOnly[\r][\n]" > 2014/01/03 15:02:52:767 PST [DEBUG] wire - http-outgoing-0 << "WWW-Authenticate: Negotiate[\r][\n]" > 2014/01/03 15:02:52:767 PST [DEBUG] wire - http-outgoing-0 << "WWW-Authenticate: NTLM[\r][\n]" > 2014/01/03 15:02:52:767 PST [DEBUG] wire - http-outgoing-0 << "WWW-Authenticate: Basic realm="mc-ex4-1-sfm.s2x.uncrap.local"[\r][\n]" > 2014/01/03 15:02:52:767 PST [DEBUG] wire - http-outgoing-0 << "X-Powered-By: ASP.NET[\r][\n]" > 2014/01/03 15:02:52:767 PST [DEBUG] wire - http-outgoing-0 << "Date: Fri, 03 Jan 2014 23:02:38 GMT[\r][\n]" > 2014/01/03 15:02:52:767 PST [DEBUG] wire - http-outgoing-0 << "Content-Length: 0[\r][\n]" > 2014/01/03 15:02:52:767 PST [DEBUG] wire - http-outgoing-0 << "[\r][\n]" > 2014/01/03 15:02:52:773 PST [DEBUG] headers - http-outgoing-0 << HTTP/1.1 401 Unauthorized > 2014/01/03 15:02:52:774 PST [DEBUG] headers - http-outgoing-0 << Server: Microsoft-IIS/7.5 > 2014/01/03 15:02:52:774 PST [DEBUG] headers - http-outgoing-0 << Set-Cookie: exchangecookie=75fd3fbf79da43df8252fdd2d65e6cd4; expires=Sat, 03-Jan-2015 23:02:38 GMT; path=/; HttpOnly > 2014/01/03 15:02:52:774 PST [DEBUG] headers - http-outgoing-0 << WWW-Authenticate: Negotiate > 2014/01/03 15:02:52:774 PST [DEBUG] headers - http-outgoing-0 << WWW-Authenticate: NTLM > 2014/01/03 15:02:52:774 PST [DEBUG] headers - http-outgoing-0 << WWW-Authenticate: Basic realm="mc-ex4-1-sfm.s2x.uncrap.local" > 2014/01/03 15:02:52:774 PST [DEBUG] headers - http-outgoing-0 << X-Powered-By: ASP.NET > 2014/01/03 15:02:52:774 PST [DEBUG] headers - http-outgoing-0 << Date: Fri, 03 Jan 2014 23:02:38 GMT > 2014/01/03 15:02:52:774 PST [DEBUG] headers - http-outgoing-0 << Content-Length: 0 > 2014/01/03 15:02:52:774 PST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] Response received > 2014/01/03 15:02:52:774 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][r:rw][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]: Event cleared [w] > 2014/01/03 15:02:52:774 PST [DEBUG] MainClientExec - [exchange: 1] Response received HTTP/1.1 401 Unauthorized > 2014/01/03 15:02:52:786 PST [DEBUG] ResponseProcessCookies - Cookie accepted: "[version: 0][name: exchangecookie][value: 75fd3fbf79da43df8252fdd2d65e6cd4][domain: mc-ex4-1-sfm.s2x.uncrap.local][path: /][expiry: Sat Jan 03 15:02:38 PST 2015]". > 2014/01/03 15:02:52:786 PST [DEBUG] MainClientExec - Authentication required > 2014/01/03 15:02:52:786 PST [DEBUG] MainClientExec - mc-ex4-1-sfm.s2x.uncrap.local:443 requested authentication > 2014/01/03 15:02:52:787 PST [DEBUG] TargetAuthenticationStrategy - Authentication schemes in the order of preference: [Basic, Digest] > 2014/01/03 15:02:52:792 PST [DEBUG] TargetAuthenticationStrategy - Challenge for Digest authentication scheme not available > 2014/01/03 15:02:52:792 PST [DEBUG] MainClientExec - Selected authentication options: [BASIC] > 2014/01/03 15:02:52:792 PST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [ACTIVE] Input ready > 2014/01/03 15:02:52:792 PST [DEBUG] MainClientExec - [exchange: 1] Consume content > 2014/01/03 15:02:52:793 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][r:rw][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]: 0 bytes read > 2014/01/03 15:02:52:793 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][r:rw][ACTIVE][r][NOT_HANDSHAKING][0][0][0][0]: Close > 2014/01/03 15:02:52:794 PST [DEBUG] MainClientExec - [exchange: 1] Connection can be kept alive indefinitely > 2014/01/03 15:02:52:794 PST [DEBUG] InternalHttpAsyncClient - [exchange: 1] releasing connection > 2014/01/03 15:02:52:794 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][rw:rw][CLOSING][r][NEED_WRAP][0][0][0][0]: Remove attribute http.nio.exchange-handler > 2014/01/03 15:02:52:794 PST [DEBUG] PoolingNHttpClientConnectionManager - Connection released: [id: http-outgoing-0][route: {s}->https://mc-ex4-1-sfm.s2x.uncrap.local:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20] > 2014/01/03 15:02:52:795 PST [DEBUG] ManagedNHttpClientConnectionImpl - http-outgoing-0 10.0.115.48:10423<->10.224.203.221:443[ACTIVE][rw:rw][CLOSING][r][NEED_WRAP][0][0][0][0]: Shutdown > 2014/01/03 15:02:52:795 PST [DEBUG] HttpAsyncRequestExecutor - null org.apache.http.impl.conn.ConnectionShutdownException > at org.apache.http.impl.nio.conn.CPoolProxy.invoke(CPoolProxy.java:133) > at com.sun.proxy.$Proxy7.requestOutput(Unknown Source) > at org.apache.http.impl.nio.client.DefaultClientExchangeHandlerImpl.responseCompleted(DefaultClientExchangeHandlerImpl.java:180) > at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.processResponse(HttpAsyncRequestExecutor.java:349) > at org.apache.http.nio.protocol.HttpAsyncRequestExecutor.inputReady(HttpAsyncRequestExecutor.java:236) > at org.apache.http.impl.nio.client.LoggingAsyncRequestExecutor.inputReady(LoggingAsyncRequestExecutor.java:87) > at org.apache.http.impl.nio.DefaultNHttpClientConnection.consumeInput(DefaultNHttpClientConnection.java:267) > at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:73) > at org.apache.http.impl.nio.client.InternalIODispatch.onInputReady(InternalIODispatch.java:37) > at org.apache.http.impl.nio.reactor.AbstractIODispatch.inputReady(AbstractIODispatch.java:120) > at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:159) > at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:338) > at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:316) > at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:277) > at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:105) > at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:584) > at java.lang.Thread.run(Thread.java:722) > 2014/01/03 15:02:52:796 PST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-0 [CLOSED]: Disconnected -- 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