[
https://issues.apache.org/jira/browse/HTTPASYNC-39?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13687737#comment-13687737
]
Mauro Improta commented on HTTPASYNC-39:
----------------------------------------
Here we go (I replaced the real server name with SERVER_NAME):
09:35:37,255 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl]
(ajp-SERVER_NAME-192.168.210.75-8009-73) http-outgoing-58
192.168.210.75:51001<->192.168.210.76:8080[ACTIVE][rw:r]: Event set [w]
09:35:37,256 DEBUG
[org.apache.http.contrib.logging.LoggingNHttpClientConnection] (I/O dispatcher
2) http-outgoing-58: Close connection
09:35:37,257 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl] (I/O
dispatcher 2) http-outgoing-58
192.168.210.75:51001<->192.168.210.76:8080[ACTIVE][rw:r]: Close
09:35:37,257 ERROR Elapsed time: 3 ms: java.net.SocketTimeoutException
at
org.apache.http.nio.protocol.HttpAsyncRequestExecutor.timeout(HttpAsyncRequestExecutor.java:289)
[httpcore-nio-4.2.4.jar:4.2.4]
at
org.apache.http.impl.nio.DefaultHttpClientIODispatch.onTimeout(DefaultHttpClientIODispatch.java:136)
[httpcore-nio-4.2.4.jar:4.2.4]
at
org.apache.http.impl.nio.DefaultHttpClientIODispatch.onTimeout(DefaultHttpClientIODispatch.java:50)
[httpcore-nio-4.2.4.jar:4.2.4]
at
org.apache.http.impl.nio.reactor.AbstractIODispatch.timeout(AbstractIODispatch.java:169)
[httpcore-nio-4.2.4.jar:4.2.4]
at
org.apache.http.impl.nio.reactor.BaseIOReactor.sessionTimedOut(BaseIOReactor.java:257)
[httpcore-nio-4.2.4.jar:4.2.4]
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.timeoutCheck(AbstractIOReactor.java:494)
[httpcore-nio-4.2.4.jar:4.2.4]
at
org.apache.http.impl.nio.reactor.BaseIOReactor.validate(BaseIOReactor.java:207)
[httpcore-nio-4.2.4.jar:4.2.4]
at
org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:284)
[httpcore-nio-4.2.4.jar:4.2.4]
at
org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:106)
[httpcore-nio-4.2.4.jar:4.2.4]
at
org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:613)
[httpcore-nio-4.2.4.jar:4.2.4]
at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_17]
09:35:37,498 DEBUG
[org.apache.http.contrib.logging.LoggingNHttpClientConnection] (I/O dispatcher
2) http-outgoing-58: Shutdown connection
09:35:37,499 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl] (I/O
dispatcher 2) http-outgoing-58 0.0.0.0:51001<->192.168.210.76:8080[CLOSED][]:
Shutdown
A successful request produces this output:
09:40:08,536 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl]
(ajp-SERVER_NAME-192.168.210.75-8009-78) http-outgoing-91
192.168.210.75:51036<->192.168.210.76:8080[ACTIVE][rw:r]: Event set [w]
09:40:08,536 DEBUG
[org.apache.http.contrib.logging.LoggingNHttpClientConnection] (I/O dispatcher
1) http-outgoing-91: Produce output
09:40:08,537 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl] (I/O
dispatcher 1) http-outgoing-91
192.168.210.75:51036<->192.168.210.76:8080[ACTIVE][r:w]: Event cleared [w]
09:40:08,539 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl] (I/O
dispatcher 1) http-outgoing-91
192.168.210.75:51036<->192.168.210.76:8080[ACTIVE][r:w]: Set timeout 5000
09:40:08,539 DEBUG
[org.apache.http.contrib.logging.LoggingNHttpClientConnection] (I/O dispatcher
1) http-outgoing-91: POST http://SERVER_NAME:8080/alert/alerticon/poll HTTP/1.1
09:40:08,540 DEBUG [org.apache.http.headers] (I/O dispatcher 1)
http-outgoing-91 >> POST http://SERVER_NAME:8080/alert/alerticon/poll HTTP/1.1
09:40:08,541 DEBUG [org.apache.http.headers] (I/O dispatcher 1)
http-outgoing-91 >> Content-Length: 49
09:40:08,541 DEBUG [org.apache.http.headers] (I/O dispatcher 1)
http-outgoing-91 >> Content-Type: application/x-www-form-urlencoded;
charset=UTF-8
09:40:08,541 DEBUG [org.apache.http.headers] (I/O dispatcher 1)
http-outgoing-91 >> Host: SERVER_NAME:8080
09:40:08,542 DEBUG [org.apache.http.headers] (I/O dispatcher 1)
http-outgoing-91 >> Connection: Keep-Alive
09:40:08,546 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl] (I/O
dispatcher 1) http-outgoing-91
192.168.210.75:51036<->192.168.210.76:8080[ACTIVE][rw:w]: Event set [w]
09:40:08,546 DEBUG
[org.apache.http.contrib.logging.LoggingNHttpClientConnection] (I/O dispatcher
1) http-outgoing-91: Produce output
09:40:08,547 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl] (I/O
dispatcher 1) http-outgoing-91
192.168.210.75:51036<->192.168.210.76:8080[ACTIVE][rw:w]: 234 bytes written
09:40:08,547 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
<< "POST http://SERVER_NAME:8080/alert/alerticon/poll HTTP/1.1[\r][\n]"
09:40:08,548 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
<< "Content-Length: 49[\r][\n]"
09:40:08,548 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
<< "Content-Type: application/x-www-form-urlencoded; charset=UTF-8[\r][\n]"
09:40:08,549 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
<< "Host: SERVER_NAME:8080[\r][\n]"
09:40:08,549 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
<< "Connection: Keep-Alive[\r][\n]"
09:40:08,550 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
<< "[\r][\n]"
09:40:08,550 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl] (I/O
dispatcher 1) http-outgoing-91
192.168.210.75:51036<->192.168.210.76:8080[ACTIVE][rw:w]: 49 bytes written
09:40:08,551 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
<< "_c.USER=ds_load_2&hi47n6w1=&_c.product=DEPOTSCOUT"
09:40:08,551 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl] (I/O
dispatcher 1) http-outgoing-91
192.168.210.75:51036<->192.168.210.76:8080[ACTIVE][r:w]: Event cleared [w]
09:40:08,554 DEBUG
[org.apache.http.contrib.logging.LoggingNHttpClientConnection] (I/O dispatcher
1) http-outgoing-91: Consume input
09:40:08,554 DEBUG [org.apache.http.impl.nio.reactor.IOSessionImpl] (I/O
dispatcher 1) http-outgoing-91
192.168.210.75:51036<->192.168.210.76:8080[ACTIVE][r:r]: 160 bytes read
09:40:08,555 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
>> "HTTP/1.1 200 OK[\r][\n]"
09:40:08,555 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
>> "Server: Apache-Coyote/1.1[\r][\n]"
09:40:08,556 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
>> "Content-Type: application/json;charset=UTF-8[\r][\n]"
09:40:08,556 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
>> "Content-Length: 11[\r][\n]"
09:40:08,557 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
>> "Date: Wed, 19 Jun 2013 07:40:08 GMT[\r][\n]"
09:40:08,557 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
>> "[\r][\n]"
09:40:08,557 DEBUG [org.apache.http.wire] (I/O dispatcher 1) http-outgoing-91
>> "{"count":0}"
09:40:08,558 DEBUG [org.apache.http.headers] (I/O dispatcher 1)
http-outgoing-91 << HTTP/1.1 200 OK
09:40:08,558 DEBUG [org.apache.http.headers] (I/O dispatcher 1)
http-outgoing-91 << Server: Apache-Coyote/1.1
09:40:08,558 DEBUG [org.apache.http.headers] (I/O dispatcher 1)
http-outgoing-91 << Content-Type: application/json;charset=UTF-8
09:40:08,559 DEBUG [org.apache.http.headers] (I/O dispatcher 1)
http-outgoing-91 << Content-Length: 11
09:40:08,559 DEBUG [org.apache.http.headers] (I/O dispatcher 1)
http-outgoing-91 << Date: Wed, 19 Jun 2013 07:40:08 GMT
> 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]
