[
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 >> "<?xml
> version="1.0" ... <omitted for readibility>"
> 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>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: [email protected]
For additional commands, e-mail: [email protected]
