hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Mauro Improta (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (HTTPASYNC-39) SocketTimeoutException occurs too soon
Date Wed, 19 Jun 2013 07:45:22 GMT

    [ 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: dev-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org


Mime
View raw message