You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@hc.apache.org by "Oleg Kalnichevski (JIRA)" <ji...@apache.org> on 2013/06/20 10:44:21 UTC

[jira] [Comment Edited] (HTTPASYNC-39) SocketTimeoutException occurs too soon

    [ https://issues.apache.org/jira/browse/HTTPASYNC-39?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13689017#comment-13689017 ] 

Oleg Kalnichevski edited comment on HTTPASYNC-39 at 6/20/13 8:42 AM:
---------------------------------------------------------------------

Well, see for yourself (log edited for brevity)
---
09:35:29,330 DEBUG http-outgoing-58 192.168.210.75:51001<->192.168.210.76:8080[ACTIVE][r:]: Set timeout 30000
09:35:29,331 DEBUG http-outgoing-58 192.168.210.75:51001<->192.168.210.76:8080[ACTIVE][rw:]: Event set [w]
09:35:29,333 DEBUG http-outgoing-58 192.168.210.75:51001<->192.168.210.76:8080[ACTIVE][rw:]: Set timeout 5000

...

09:35:31,562 http-outgoing-58 << HTTP/1.1 200 OK
09:35:31,562 http-outgoing-58 << Server: Apache-Coyote/1.1
09:35:31,563 http-outgoing-58 << Content-Type: application/json;charset=UTF-8
09:35:31,563 http-outgoing-58 << Content-Length: 11
09:35:31,564 http-outgoing-58 << Date: Wed, 19 Jun 2013 07:35:31 GMT

09:35:37,255 http-outgoing-58 192.168.210.75:51001<->192.168.210.76:8080[ACTIVE][rw:r]: Event set [w]
09:35:37,256 http-outgoing-58: Close connection
09:35:37,257 http-outgoing-58 192.168.210.75:51001<->192.168.210.76:8080[ACTIVE][rw:r]: Close
---

There is something in your code that changes the timeout value from 30000 to 5000 at 09:35:21,460. Then, after some activity there is an incoming response at 09:35:31,562 which should enclose 11 bytes of content. At 09:35:37,255 there was still no input and more than 5 seconds elapsed since last input event. The session is closed due to inactivity. At least in this particular case everything looks correct.

Oleg
                
      was (Author: olegk):
    Well, see for yourself (log edited for brevity)
---
09:35:21,458 http-outgoing-57 192.168.210.75:51000<->192.168.210.76:8080[ACTIVE][r:]: Set timeout 30000
09:35:21,459 http-outgoing-57 192.168.210.75:51000<->192.168.210.76:8080[ACTIVE][rw:]: Event set [w]
09:35:21,460 http-outgoing-57 192.168.210.75:51000<->192.168.210.76:8080[ACTIVE][rw:]: Set timeout 5000

...

09:35:31,562 http-outgoing-58 << HTTP/1.1 200 OK
09:35:31,562 http-outgoing-58 << Server: Apache-Coyote/1.1
09:35:31,563 http-outgoing-58 << Content-Type: application/json;charset=UTF-8
09:35:31,563 http-outgoing-58 << Content-Length: 11
09:35:31,564 http-outgoing-58 << Date: Wed, 19 Jun 2013 07:35:31 GMT

09:35:37,255 http-outgoing-58 192.168.210.75:51001<->192.168.210.76:8080[ACTIVE][rw:r]: Event set [w]
09:35:37,256 http-outgoing-58: Close connection
09:35:37,257 http-outgoing-58 192.168.210.75:51001<->192.168.210.76:8080[ACTIVE][rw:r]: Close
---

There is something in your code that changes the timeout value from 30000 to 5000 at 09:35:21,460. Then, after some activity there is an incoming response at 09:35:31,562 which should enclose 11 bytes of content. At 09:35:37,255 there was still no input and more than 5 seconds elapsed since last input event. The session is closed due to inactivity. At least in this particular case everything looks correct.

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
>         Attachments: log.txt
>
>
> 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