search

koush / ion

Android Asynchronous Networking and Image Loading
Other
6.29k stars 1.03k forks source link

java.util.concurrent.TimeoutException closing out socket (exception) #912

Open malik082009 opened 5 years ago

malik082009 commented 5 years ago

First of all thanks for this awesome library!!

this error happens randomly between 5 to 10 requests.

i am using implementation 'com.koushikdutta.ion:ion:2.2.1'

i tired switching versions but no luck :(

`2019-10-25 15:55:32.739 7734-7734/com.creatrixe.commo I/RequestBody:: {"items":10,"page":1,"commentable_type":"Trip","commentable_id":4}

2019-10-25 15:55:32.743 7734-7734/com.creatrixe.commo D/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/comment/show: preparing request 2019-10-25 15:55:32.743 7734-7734/com.creatrixe.commo D/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/comment/show: preparing request 2019-10-25 15:55:32.744 7734-7734/com.creatrixe.commo I/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/comment/show: Using loader: com.koushikdutta.ion.loader.HttpLoader@39d052b 2019-10-25 15:55:32.745 7734-9223/com.creatrixe.commo D/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/comment/show: Executing request. 2019-10-25 15:55:32.749 7734-9223/com.creatrixe.commo D/WebServicesIonTask: (4 ms) https://api.dev.coomotravel.com/api/v2/comment/show: Reusing keep-alive socket 2019-10-25 15:55:32.750 7734-7734/com.creatrixe.commo D/ViewRootImpl@4e4e6e0[TabActivity]: dispatchAttachedToWindow 2019-10-25 15:55:32.750 7734-9223/com.creatrixe.commo V/WebServicesIonTask: (6 ms) https://api.dev.coomotravel.com/api/v2/comment/show: socket connected 2019-10-25 15:55:32.752 7734-9223/com.creatrixe.commo V/WebServicesIonTask: (8 ms) https://api.dev.coomotravel.com/api/v2/comment/show: 

POST /api/v2/comment/show HTTP/1.1
Host: api.dev.coomotravel.com
User-Agent: Dalvik/2.1.0 (Linux; U; Android 7.0; SM-G920F Build/NRD90M)
Accept-Encoding: gzip, deflate
Connection: keep-alive
Accept: application/json
AUTHORIZATION: Bearer eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiIsImp0aSI6Ijc5MGQxOTNkYzA3MDRjM2MwMmRhYzRiZ
Cookie: laravel_session=eyJpdiI6InBBaGpMamxJcmNVampyMTNiQmpIc1E9PSIsInZhbHVlIjoiN1lhaGFWWVpXSTRXNXE
Content-Type: application/x-www-form-urlencoded; charset=utf-8
Content-Length: 54

2019-10-25 15:55:32.761 7734-9223/com.creatrixe.commo V/WebServicesIonTask: (16 ms) https://api.dev.coomotravel.com/api/v2/comment/show: request completed 2019-10-25 15:55:33.150 7734-9223/com.creatrixe.commo V/WebServicesIonTask: (405 ms) https://api.dev.coomotravel.com/api/v2/comment/show: closing out socket (exception) 2019-10-25 15:56:02.784 7734-9223/com.creatrixe.commo E/WebServicesIonTask: (30039 ms) https://api.dev.coomotravel.com/api/v2/comment/show: Connection error

2019-10-25 15:56:02.785 7734-9223/com.creatrixe.commo E/WebServicesIonTask: null

java.util.concurrent.TimeoutException
    at com.koushikdutta.async.http.AsyncHttpClient$2.run(AsyncHttpClient.java:246)
    at com.koushikdutta.async.AsyncServer.lockAndRunQueue(AsyncServer.java:740)
    at com.koushikdutta.async.AsyncServer.runLoop(AsyncServer.java:758)
    at com.koushikdutta.async.AsyncServer.run(AsyncServer.java:658)
    at com.koushikdutta.async.AsyncServer.access$800(AsyncServer.java:44)
    at com.koushikdutta.async.AsyncServer$14.run(AsyncServer.java:600)

2019-10-25 15:56:02.808 7734-7734/com.creatrixe.commo I/Comments: onTaskComplete: null `

malik082009 commented 5 years ago

@koush please look into this error, if you have some time.

malik082009 commented 5 years ago

@koush i think cookies causing this issue, which ion is adding transparently!, how can i disable this?

malik082009 commented 5 years ago

@koushi think cookies causing this issue, which ion is adding transparently!, how can i disable this?

Aah, found a way to disable cookies. Ion ion = Ion.getDefault(context); ion.getCookieMiddleware().getCookieManager().setCookiePolicy(CookiePolicy.ACCEPT_NONE); builder = ion.with(context).load(requestMethod.name(), serverUrl).setLogging(TAG, Log.VERBOSE) .setTimeout(Constants.WEBSERVICE_SOCKETTIME);

now, let see if it works or not. will close issue if it works after testing.

malik082009 commented 5 years ago

disabling accept cookies reduced the occurrence of java.util.concurrent.TimeoutException , and speeds up the API's response, but this error still occurs, i don't know why, it's very annoying. the log i got after settings cookies policy.

ion.getCookieMiddleware().getCookieManager().setCookiePolicy(CookiePolicy.ACCEPT_NONE);

`2019-11-01 11:42:09.274 12404-12404/com.creatrixe.commo D/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/comment/show: preparing request 2019-11-01 11:42:09.274 12404-12404/com.creatrixe.commo D/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/comment/show: preparing request 2019-11-01 11:42:09.274 12404-12404/com.creatrixe.commo I/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/comment/show: Using loader: com.koushikdutta.ion.loader.HttpLoader@19bd6e8 2019-11-01 11:42:09.275 12404-12603/com.creatrixe.commo D/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/comment/show: Executing request. 2019-11-01 11:42:09.277 12404-12603/com.creatrixe.commo D/WebServicesIonTask: (2 ms) https://api.dev.coomotravel.com/api/v2/comment/show: Reusing keep-alive socket 2019-11-01 11:42:09.278 12404-12603/com.creatrixe.commo V/WebServicesIonTask: (3 ms) https://api.dev.coomotravel.com/api/v2/comment/show: socket connected 2019-11-01 11:42:09.280 12404-12603/com.creatrixe.commo V/WebServicesIonTask: (5 ms) https://api.dev.coomotravel.com/api/v2/comment/show: POST /api/v2/comment/show HTTP/1.1 Host: api.dev.coomotravel.com User-Agent: Dalvik/2.1.0 (Linux; U; Android 7.0; SM-G920F Build/NRD90M) Accept-Encoding: gzip, deflate Connection: keep-alive Accept: application/json AUTHORIZATION: Bearer eyJ0eXAiOi0ODkwZGRmNWQ4ZmI3NjliZWIwMjY4NmQxMTQ5ZThjYWZjNTAw.eyJhdWQiOiI1IiwianRpIjoiODEzYjQ4OTBkZGY1ZDhmYjc2OWJlYjAyNjg2ZDExNDllOGNhZmM1MDA5NzZkNGQzZWMxNTJlMGU2Yjc2YWZkNmY2NjI5MzE2OWYwNTg4ZDIiLCJpYXQiOjE1NzI1ODkwMDgsIm5iZiI6MTU3MjU4OTAwOCwiZXhwIjoxNjA0MjExNDA4LCJzdWIiOiIzIiwic2NvcGVzIjpbXX0.g-ig5GYV5B0W9NiJp0dd45yIqKlK7qfnCATD-XL3SMMBspuAGbK3KZqfIrswIwjCHrEmAr7XHlCHwYNsdgseiRagp1_XlX-49-rH8vLI1T1vbCvxGnz7uXZeF1SWHLL69QJZzGnWEUa7zIsHNFK0uhXyK0ghJfSS_iH_rObm0iLzn6Q4K4-1fk_oXUlYGR_OGWVjBJVgvmfZRhOm58mn2Du34BZQo09YvneBduz_MU3VEMyVKAJ99xW2pe1WZxb1Vc8w5NR4Jl_FJKSwShdezFDaPXwvUbIiLNV_oPrD0e6p1cz101ct6147PBbWMaBlWs6XvsZ01Uhwr7_jpqwnCAt2eLA1DL4GzLLXyCVLAWoydAlgxCcKiUzTOI6vk3ds3Oj1WQzZb75lLEQeeRo06vo1VyloRhWD-2FrIebeO6MX9oTM8b8fU7ghvH4mQohE15LUwrlk35kkBT_7ouL9edfilcyPbAORN-GHhkaU41pBxMkpLM3tdb_MocfuwbsCn1ANkGm-EsbJzLuiM6jTmKlqC2Gc25WVTRMYKTP-giICaieMPm66zqBtkxioJXSQk08musbBCBuvsMm3H0zaF2--wkzLpM9OqeOcxFKb9EUgPzVaAfCcmskJCULEsosTgtyf-pIzHTAC475AP25KWI4t6ej2LwsPi6GY_futfXI Content-Type: application/x-www-form-urlencoded; charset=utf-8 Content-Length: 55

2019-11-01 11:42:09.287 12404-12603/com.creatrixe.commo V/WebServicesIonTask: (12 ms) https://api.dev.coomotravel.com/api/v2/comment/show: request completed 2019-11-01 11:42:09.592 12404-12603/com.creatrixe.commo V/WebServicesIonTask: (316 ms) https://api.dev.coomotravel.com/api/v2/comment/show: closing out socket (exception) 2019-11-01 11:42:29.310 12404-12603/com.creatrixe.commo E/WebServicesIonTask: (20034 ms) https://api.dev.coomotravel.com/api/v2/comment/show: Connection error 2019-11-01 11:42:29.311 12404-12603/com.creatrixe.commo E/WebServicesIonTask: null java.util.concurrent.TimeoutException at com.koushikdutta.async.http.AsyncHttpClient$2.run(AsyncHttpClient.java:246) at com.koushikdutta.async.AsyncServer.lockAndRunQueue(AsyncServer.java:740) at com.koushikdutta.async.AsyncServer.runLoop(AsyncServer.java:758) at com.koushikdutta.async.AsyncServer.run(AsyncServer.java:658) at com.koushikdutta.async.AsyncServer.access$800(AsyncServer.java:44) at com.koushikdutta.async.AsyncServer$14.run(AsyncServer.java:600) 2019-11-01 11:42:29.340 12404-12404/com.creatrixe.commo I/Comments: onTaskComplete: null`

malik082009 commented 5 years ago

@koush ???

koush commented 5 years ago

You have url or test case I can use to hit this reliably?

JovialDeveloper commented 5 years ago

You have url or test case I can use to hit this reliably?

yeah wait

JovialDeveloper commented 5 years ago

You have url or test case I can use to hit this reliably?

please check your email

malik082009 commented 5 years ago

@koush updating to latest version implementation 'com.koushikdutta.ion:ion:3.0.8' seems to resolve java.util.concurrent.TimeoutException, but i am facing new error now!

2019-11-12 14:00:19.754 18322-18322/com.creatrixe.commo D/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: preparing request 2019-11-12 14:00:19.754 18322-18322/com.creatrixe.commo D/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: preparing request 2019-11-12 14:00:19.754 18322-18322/com.creatrixe.commo I/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: Using loader: com.koushikdutta.ion.loader.HttpLoader@e243aaa 2019-11-12 14:00:19.755 18322-19479/com.creatrixe.commo D/WebServicesIonTask: (0 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: Executing request. 2019-11-12 14:00:19.758 18322-18322/com.creatrixe.commo E/RecyclerView: No adapter attached; skipping layout 2019-11-12 14:00:19.759 18322-19479/com.creatrixe.commo D/WebServicesIonTask: (4 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: Reusing keep-alive socket 2019-11-12 14:00:19.759 18322-19479/com.creatrixe.commo V/WebServicesIonTask: (4 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: socket connected 2019-11-12 14:00:19.761 18322-19479/com.creatrixe.commo V/WebServicesIonTask: (5 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: GET /api/v2/user/friend/list/66?items=10&page=1 HTTP/1.1 Host: api.dev.coomotravel.com User-Agent: Dalvik/2.1.0 (Linux; U; Android 7.0; SM-G920F Build/NRD90M) Accept-Encoding: gzip, deflate Connection: keep-alive Accept: application/json AUTHORIZATION: Bearer eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiIsImp0aSI6IjFkZDEyYTFiYjI1NTEzZDc2YTZmOWJmNDhhYzZkYm 2019-11-12 14:00:19.764 18322-19479/com.creatrixe.commo V/WebServicesIonTask: (8 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: request completed 2019-11-12 14:00:21.093 18322-19479/com.creatrixe.commo E/WebServicesIonTask: (1338 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: exception during response 2019-11-12 14:00:21.094 18322-19479/com.creatrixe.commo E/WebServicesIonTask: connection closed before headers received. com.koushikdutta.async.http.ConnectionClosedException: connection closed before headers received. at com.koushikdutta.async.http.AsyncHttpResponseImpl$2.onCompleted(AsyncHttpResponseImpl.java:54) at com.koushikdutta.async.AsyncSSLSocketWrapper$5.onCompleted(AsyncSSLSocketWrapper.java:259) at com.koushikdutta.async.AsyncNetworkSocket.reportEnd(AsyncNetworkSocket.java:241) at com.koushikdutta.async.AsyncNetworkSocket.reportEndPending(AsyncNetworkSocket.java:253) at com.koushikdutta.async.AsyncNetworkSocket.onReadable(AsyncNetworkSocket.java:170) at com.koushikdutta.async.AsyncServer.runLoop(AsyncServer.java:869) at com.koushikdutta.async.AsyncServer.run(AsyncServer.java:717) at com.koushikdutta.async.AsyncServer.access$800(AsyncServer.java:46) at com.koushikdutta.async.AsyncServer$11.run(AsyncServer.java:671) 2019-11-12 14:00:21.094 18322-19479/com.creatrixe.commo E/WebServicesIonTask: (1339 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: Connection error 2019-11-12 14:00:21.095 18322-19479/com.creatrixe.commo E/WebServicesIonTask: connection closed before headers received. com.koushikdutta.async.http.ConnectionClosedException: connection closed before headers received. at com.koushikdutta.async.http.AsyncHttpResponseImpl$2.onCompleted(AsyncHttpResponseImpl.java:54) at com.koushikdutta.async.AsyncSSLSocketWrapper$5.onCompleted(AsyncSSLSocketWrapper.java:259) at com.koushikdutta.async.AsyncNetworkSocket.reportEnd(AsyncNetworkSocket.java:241) at com.koushikdutta.async.AsyncNetworkSocket.reportEndPending(AsyncNetworkSocket.java:253) at com.koushikdutta.async.AsyncNetworkSocket.onReadable(AsyncNetworkSocket.java:170) at com.koushikdutta.async.AsyncServer.runLoop(AsyncServer.java:869) at com.koushikdutta.async.AsyncServer.run(AsyncServer.java:717) at com.koushikdutta.async.AsyncServer.access$800(AsyncServer.java:46) at com.koushikdutta.async.AsyncServer$11.run(AsyncServer.java:671) 2019-11-12 14:00:21.095 18322-19479/com.creatrixe.commo V/WebServicesIonTask: (1340 ms) https://api.dev.coomotravel.com/api/v2/user/friend/list/66?items=10&page=1: closing out socket (exception)

malik082009 commented 5 years ago

java.util.concurrent.TimeoutException has been resolved by updating to the latest version, current is: implementation 'com.koushikdutta.ion:ion:3.0.8' to resolve com.koushikdutta.async.http.ConnectionClosedException: connection closed before headers received. set header like setHeader("Connection", "close"). Finally thanks to @koush.

malik082009 commented 4 years ago

@koush, trying setHeader("Connection", "close") on the request solved the actual issue, which was java.util.concurrent.TimeoutException, but I realized that the response time is quite slow now. I tried removing setHeader("Connection", "close") and it speeds up the response time, but removing this header leads to com.koushikdutta.async.http.ConnectionClosedException. I think the keep alive socket on my server is being expired after a certain time period, I started a test case and i found that whenever i request every five seconds (not before or after five seconds). com.koushikdutta.async.http.ConnectionClosedException occurs. The header i received in successful request are follows:

HTTP/1.1 200 OK
    Date: Thu, 23 Jan 2020 07:31:24 GMT
    Server: Apache/2.4.29 (Ubuntu)
    Vary: Authorization
    Cache-Control: no-cache, private
    X-RateLimit-Limit: 60
    X-RateLimit-Remaining: 59
    Set-Cookie: laravel_session=eyJpdiI6IlExQmJ6UG9PMm1CRGJZa3FINjZRUWc9PSIsInZhbHVlIjoiTmtQTEF
    Keep-Alive: timeout=5, max=100
    Connection: Keep-Alive
    Transfer-Encoding: chunked
    Content-Type: application/json

please fix this, i am reopening this issue.