[
https://issues.apache.org/jira/browse/HTTPASYNC-39?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Oleg Kalnichevski resolved HTTPASYNC-39.
----------------------------------------
Resolution: Cannot Reproduce
Clinton,
I cannot see how this could be happening just by looking at the source code.
lastAccessTime should be set to the current time by the constructor and then
updated with every read or write operation. Access to the variable is always
synchronized. I need more contextual details to be able to figure out what
might be going wrong. Could you please run your application with the following
logging settings and attach the resultant log to this issue?
---
-Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.SimpleLog
-Dorg.apache.commons.logging.simplelog.showdatetime=true
-Dorg.apache.commons.logging.simplelog.log.org.apache.http.impl.nio.reactor=DEBUG
-Dorg.apache.commons.logging.simplelog.log.org.apache.http.nio.protocol=DEBUG
---
You should be able to correlate i/o events by using session id such as
'http-outgoing-1'
---
2013/04/22 13:56:32:269 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:]: Set attribute
http.nio.exchange-handler
2013/04/22 13:56:32:272 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][rw:]: Event set [w]
2013/04/22 13:56:32:272 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE]: Connected
2013/04/22 13:56:32:273 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][rw:]: Set attribute
http.nio.http-exchange-state
2013/04/22 13:56:32:273 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] Request ready
2013/04/22 13:56:32:274 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][rw:]: Set timeout 1
2013/04/22 13:56:32:286 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][rw:]: Event set [w]
2013/04/22 13:56:32:287 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][rw:w]: 120 bytes written
2013/04/22 13:56:32:287 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:w]: Event cleared [w]
2013/04/22 13:56:32:287 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] Request ready
2013/04/22 13:56:32:615 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 1462 bytes read
2013/04/22 13:56:32:630 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE(903)] Response received
2013/04/22 13:56:32:637 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE(903)] Input ready
2013/04/22 13:56:32:637 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:32:638 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:32:638 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] [chunk-coded; completed: false]
2013/04/22 13:56:32:655 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] Input ready
2013/04/22 13:56:32:656 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 1448 bytes read
2013/04/22 13:56:32:658 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 2825 bytes read
2013/04/22 13:56:32:663 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:32:663 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:32:663 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] [chunk-coded; completed: false]
2013/04/22 13:56:32:738 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] Input ready
2013/04/22 13:56:32:740 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 2896 bytes read
2013/04/22 13:56:32:744 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 2903 bytes read
2013/04/22 13:56:32:745 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:32:745 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:32:748 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:32:748 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:32:748 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] [chunk-coded; completed: false]
2013/04/22 13:56:32:779 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] Input ready
2013/04/22 13:56:32:780 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 1428 bytes read
2013/04/22 13:56:32:780 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:32:780 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] [chunk-coded; completed: false]
2013/04/22 13:56:32:863 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] Input ready
2013/04/22 13:56:32:864 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 2876 bytes read
2013/04/22 13:56:32:864 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 2856 bytes read
2013/04/22 13:56:32:865 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 1408 bytes read
2013/04/22 13:56:32:865 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
...
2013/04/22 13:56:33:241 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 1428 bytes read
2013/04/22 13:56:33:242 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:33:243 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:33:244 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: 0 bytes read
2013/04/22 13:56:33:245 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] [chunk-coded; completed: false]
2013/04/22 13:56:33:246 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[ACTIVE] Timeout
2013/04/22 13:56:33:247 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[ACTIVE][r:r]: Shutdown
2013/04/22 13:56:33:249 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[CLOSED][]: Shutdown
2013/04/22 13:56:33:249 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[CLOSED][]: Shutdown
2013/04/22 13:56:33:250 CEST [DEBUG] IOSessionImpl - http-outgoing-1
192.168.1.121:41595<->87.248.122.122:80[CLOSED][]: Shutdown
2013/04/22 13:56:33:251 CEST [DEBUG] HttpAsyncRequestExecutor - http-outgoing-1
[CLOSED]: Disconnected
Exception in thread "main" java.util.concurrent.ExecutionException:
java.net.SocketTimeoutException
at org.apache.http.concurrent.BasicFuture.getResult(BasicFuture.java:66)
at org.apache.http.concurrent.BasicFuture.get(BasicFuture.java:75)
at Testing.main(Testing.java:19)
Caused by: java.net.SocketTimeoutException
at
org.apache.http.nio.protocol.HttpAsyncRequestExecutor.timeout(HttpAsyncRequestExecutor.java:279)
at
org.apache.http.impl.nio.client.LoggingAsyncRequestExecutor.timeout(LoggingAsyncRequestExecutor.java:128)
at
org.apache.http.impl.nio.DefaultHttpClientIODispatch.onTimeout(DefaultHttpClientIODispatch.java:136)
at
org.apache.http.impl.nio.DefaultHttpClientIODispatch.onTimeout(DefaultHttpClientIODispatch.java:50)
at
org.apache.http.impl.nio.reactor.AbstractIODispatch.timeout(AbstractIODispatch.java:169)
at
org.apache.http.impl.nio.reactor.BaseIOReactor.sessionTimedOut(BaseIOReactor.java:257)
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.timeoutCheck(AbstractIOReactor.java:494)
at
org.apache.http.impl.nio.reactor.BaseIOReactor.validate(BaseIOReactor.java:207)
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:284)
at
org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:106)
at
org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:604)
---
Oleg
> SocketTimeoutException occurs too soon
> --------------------------------------
>
> Key: HTTPASYNC-39
> URL: https://issues.apache.org/jira/browse/HTTPASYNC-39
> Project: HttpComponents HttpAsyncClient
> Issue Type: Bug
> Affects Versions: 4.0-beta3
> Reporter: Clinton Nielsen
>
> In a highly concurrent environment, where SocketTimeout is set to 30,000
> milliseconds, we are often seeing a timeoutexception after only 0 or 1 or 2
> milliseconds has actually passed.
> I get the impression that in the AbstractIOReactor timeoutCheck function,
> session.getLastAccessTime is being called on the session before the
> lastAccessTime is set on the session for the current session (ie. the
> lastAccessTime being retrieved is the time that was set on the session object
> for the previous http session)
--
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: [email protected]
For additional commands, e-mail: [email protected]
