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 7E20110B0B for ; Wed, 19 Jun 2013 07:45:29 +0000 (UTC) Received: (qmail 78654 invoked by uid 500); 19 Jun 2013 07:45:29 -0000 Delivered-To: apmail-hc-dev-archive@hc.apache.org Received: (qmail 78450 invoked by uid 500); 19 Jun 2013 07:45:24 -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 78288 invoked by uid 99); 19 Jun 2013 07:45:22 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 19 Jun 2013 07:45:22 +0000 Date: Wed, 19 Jun 2013 07:45:22 +0000 (UTC) From: "Mauro Improta (JIRA)" To: dev@hc.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (HTTPASYNC-39) SocketTimeoutException occurs too soon 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-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