Simple POST - connection timeout exception

[clickslide]

Hi,

Here is what I'm seeing in my verbose Log:

V/ION_VERBOSE_LOGGING( 5440): (1168 ms) http://nycwaste.herokuapp.com/api/hooks: socket connected
D/ION_VERBOSE_LOGGING( 5440): (0 ms) http://nycwaste.herokuapp.com/api/hooks: preparing request
V/ION_VERBOSE_LOGGING( 5440): (1174 ms) http://nycwaste.herokuapp.com/api/hooks: 
V/ION_VERBOSE_LOGGING( 5440): POST /api/hooks HTTP/1.1
V/ION_VERBOSE_LOGGING( 5440): Host: nycwaste.herokuapp.com
V/ION_VERBOSE_LOGGING( 5440): User-Agent: Dalvik/1.6.0 (Linux; U; Android 4.4.4; Nexus 7 Build/KTU84P)
V/ION_VERBOSE_LOGGING( 5440): Accept-Encoding: gzip, deflate
V/ION_VERBOSE_LOGGING( 5440): Connection: keep-alive
V/ION_VERBOSE_LOGGING( 5440): Accept: */*
V/ION_VERBOSE_LOGGING( 5440): Cookie: sessionID=9694ca92dae0629908cc2ea815ebff9d05450ec3
V/ION_VERBOSE_LOGGING( 5440): Content-Type: application/x-www-form-urlencoded
V/ION_VERBOSE_LOGGING( 5440): Content-Length: 263
V/ION_VERBOSE_LOGGING( 5440): 
V/ION_VERBOSE_LOGGING( 5440): (1175 ms) http://nycwaste.herokuapp.com/api/hooks: request completed
I/ION_VERBOSE_LOGGING( 5440): (0 ms) http://nycwaste.herokuapp.com/api/hooks: Using loader: com.koushikdutta.ion.loader.HttpLoader@4216e280
D/ION_VERBOSE_LOGGING( 5440): (0 ms) http://nycwaste.herokuapp.com/api/hooks: Executing request.
D/ION_VERBOSE_LOGGING( 5440): (3 ms) http://nycwaste.herokuapp.com/api/hooks: Reusing keep-alive socket
V/ION_VERBOSE_LOGGING( 5440): (4 ms) http://nycwaste.herokuapp.com/api/hooks: socket connected
V/ION_VERBOSE_LOGGING( 5440): (5 ms) http://nycwaste.herokuapp.com/api/hooks: 
V/ION_VERBOSE_LOGGING( 5440): POST /api/hooks HTTP/1.1
V/ION_VERBOSE_LOGGING( 5440): Host: nycwaste.herokuapp.com
V/ION_VERBOSE_LOGGING( 5440): User-Agent: Dalvik/1.6.0 (Linux; U; Android 4.4.4; Nexus 7 Build/KTU84P)
V/ION_VERBOSE_LOGGING( 5440): Accept-Encoding: gzip, deflate
V/ION_VERBOSE_LOGGING( 5440): Connection: keep-alive
V/ION_VERBOSE_LOGGING( 5440): Accept: */*
V/ION_VERBOSE_LOGGING( 5440): Cookie: sessionID=9694ca92dae0629908cc2ea815ebff9d05450ec3
V/ION_VERBOSE_LOGGING( 5440): Content-Type: application/x-www-form-urlencoded
V/ION_VERBOSE_LOGGING( 5440): Content-Length: 514
V/ION_VERBOSE_LOGGING( 5440): 
V/ION_VERBOSE_LOGGING( 5440): (6 ms) http://nycwaste.herokuapp.com/api/hooks: request completed
E/ION_VERBOSE_LOGGING( 5440): (30002 ms) http://nycwaste.herokuapp.com/api/hooks: Connection error
E/ION_VERBOSE_LOGGING( 5440): null
E/ION_VERBOSE_LOGGING( 5440): java.util.concurrent.TimeoutException
E/ION_VERBOSE_LOGGING( 5440):   at com.koushikdutta.async.http.AsyncHttpClient$2.run(AsyncHttpClient.java:196)
E/ION_VERBOSE_LOGGING( 5440):   at com.koushikdutta.async.AsyncServer.lockAndRunQueue(AsyncServer.java:678)
E/ION_VERBOSE_LOGGING( 5440):   at com.koushikdutta.async.AsyncServer.runLoop(AsyncServer.java:695)
E/ION_VERBOSE_LOGGING( 5440):   at com.koushikdutta.async.AsyncServer.run(AsyncServer.java:603)
E/ION_VERBOSE_LOGGING( 5440):   at com.koushikdutta.async.AsyncServer.access$700(AsyncServer.java:37)
E/ION_VERBOSE_LOGGING( 5440):   at com.koushikdutta.async.AsyncServer$13.run(AsyncServer.java:552)
D/ION_VERBOSE_LOGGING( 5440): (31655 ms) http://nycwaste.herokuapp.com/api/hooks: Recycling extra socket leftover from cancelled operation
V/ION_VERBOSE_LOGGING( 5440): (3438 ms) http://nycwaste.herokuapp.com/api/hooks: socket connected

This happens on nearly every request I'm sending. The code I'm using to do this looks like this:

private void sendDataToServer(JSONArray json){
        Log.i(TAG, "Sending POST request to Service.");
        Ion.with(this)
        .load("http://nycwaste.herokuapp.com/api/hooks")
        .setLogging("ION_VERBOSE_LOGGING", Log.VERBOSE)
        .setBodyParameter("payload", json.toString())
        .asString()
        .withResponse()
        .setCallback(new FutureCallback<Response<String>>() {
            @Override
            public void onCompleted(Exception e, Response<String> result) {
                sending = false;
                if(e == null) {
                    Log.i(TAG, "ION SENT MESSAGE WITH RESULT CODE: " + result.getHeaders().getResponseCode());
                }else{
                    Log.i(TAG, "ION SENT MESSAGE WITH EXCEPTION");
                    e.printStackTrace();
                }
            }
        });
    }

This method is called in a loop sending sensor data. I think it's called 3-5 times per-second. Possibly more often.

Is there anything you see that might be the problem? Perhaps there is a better way for me to get more information about the error?

Any help would be greatly appreciated.

Best, Aaron

[koush]

Well, a simple curl from the command line or trying to load it in a browser indicates the site is unresponsive... :)

It took around 45 seconds before it showed an error page:

<!DOCTYPE html>
    <html>
    <head>
      <meta name="viewport" content="width=device-width, initial-scale=1">
      <style type="text/css">
        html, body, iframe { margin: 0; padding: 0; height: 100%; }
        iframe { display: block; width: 100%; border: none; }
      </style>
    <title>Application Error</title>
    </head>
    <body>
      <iframe src="//s3.amazonaws.com/heroku_pages/error.html">
        <p>Application Error</p>
      </iframe>
    </body>
    </html>

Ion's default timeout is 30 seconds.

You can try .setTimeout(X) to change it.

[clickslide]

Actually, this API end point only accepts POST requests which would explain why it doesn't CURL or load into a browser. The server is responding fine when I use a REST client in Google Chrome.

[clickslide]

It seems that the request from Ion is closed before the server can respond. The POST is made successfully, but then Ion just cuts out without a response.

Here is the Heroku Log:

heroku[router]: at=error code=H18 desc="Request Interrupted" sock=client

Is it possible that I'm not actually calling it in an Async way such that the subsequent request forces Ion to close and start over... ?

[koush]

@clickslide I'll try it in a tight loop and see what happens. What version of ion are you running?

[clickslide]

Ion and AndroidAsync are both at 1.3.7

[koush]

Oh, it seems the operation is being cancelled for some reason:

Recycling extra socket leftover from cancelled operation

What is your "this" that you are passing into Ion? This will happen if you call cancel on the future, or if the activity/service dies.

[koush]

What is your "this" that you are passing into Ion? This will happen if you call cancel on the future, or if the activity/service dies.

[clickslide]

It's a service...

public class MyService extends BackgroundService implements IBeaconConsumer, RangeNotifier, IBeaconDataNotifier

[koush]

IntentService or just Service?

[clickslide]

running

adb -d logcat

Seems to show the service running. Also, inspecting my Heroku logs, it seems some of the requests are getting to the server but many are getting this error.

[clickslide]

public abstract class BackgroundService extends Service

[koush]

Alright will write up a test case with this and see if I can reproduce it.

You on wifi or 3g when this happens?

[clickslide]

Wifi

[clickslide]

thanks for looking into it!

[fatihpense]

It can be related: https://github.com/koush/AndroidAsync/issues/132

[clickslide]

Thanks for the response @fatihpense, but I'm not seeing the connection. My requests are being sent from a request happing in a Service that is running in the background. Furthermore, this timeout exception happens quite quickly after the app starts. I'm parsing data from an iBeacon every 100ms and POSTing it to a server. The app is usually running in the foreground and it is immediately after a fresh install. It appears that the linked issue relates more to a closed socket after the device has been sleeping. The device I'm working with is wide awake and connected to the web :) Please let me know if I'm missing something.

[koush]

Sorry, just now returning to this issue. Checking now.

Are any of the requests completing successfully, and just some timing out? Or is everything failing?

[koush]

Can you provide me some sample data that I can post to the server in rapid succession?

[clickslide]

Not every request fails. Some make it through successfully. However, many of them fail.

Here is the sample data. I have many beacons in my home so there is a lot of data that streams constantly into the App.

{ uuid: '2f234454cf6d4a0fadf2f4911ba9ffa6',
  major: 1,
  minor: 1,
  measuredPower: -59,
  rssi: -78,
  accuracy: 3.3212335430520668,
  proximity: 'near' }
{ uuid: 'beceeb9d65104c7eaedf08eb5575e0ae',
  major: 1,
  minor: 2,
  measuredPower: -66,
  rssi: -67,
  accuracy: 1.0581003218778426,
  proximity: 'near' }
{ uuid: '2f234454cf6d4a0fadf2f4911ba9ffa6',
  major: 1,
  minor: 1,
  measuredPower: -59,
  rssi: -71,
  accuracy: 2.134232534620913,
  proximity: 'near' }

Every time the app discovers beacon data, it sends a POST request. I will be working more on it this week so I will have time to do a few tweaks.

I think this data POSTs ever 100ms or perhaps every 50ms. I don't know the exact timing. But it's a lot.

[clickslide]

Is it possible that this would be caused by a weak WiFi connection? I haven't tested in other locations, but perhaps the amount of data streaming from the app through my router along with all the other devices I have connected is creating a bottleneck in my WiFi connection. In such a case, the router might start closing connections. When I get a bit of time I will test this theory at a Starbucks.

[clickslide]

Still getting loads of these errors. I'm now GETing data from a simple URL and it my logs are filled with this error. I'm sending about 2-4 requests a second.

09-24 18:09:13.712  21201-21300/com.variable.demo.api D/MyLogs﹕ (0 ms) https://datadipity.com/clickslide/fleetplusdata.json?PHPSESSID=gae519f8k5humje0jqb195nob6&update&postparam[payload]=humidity;2D95AFA56444;4.02: Executing request.
09-24 18:09:14.322  21201-21300/com.variable.demo.api E/MyLogs﹕ (30006 ms) https://datadipity.com/clickslide/fleetplusdata.json?PHPSESSID=gae519f8k5humje0jqb195nob6&update&postparam[payload]=light;2D95AFA56444;253.46: Connection error
09-24 18:09:14.322  21201-21300/com.variable.demo.api E/MyLogs﹕ null
    java.util.concurrent.TimeoutException
            at com.koushikdutta.async.http.AsyncHttpClient$2.run(AsyncHttpClient.java:240)
            at com.koushikdutta.async.AsyncServer.lockAndRunQueue(AsyncServer.java:683)
            at com.koushikdutta.async.AsyncServer.runLoop(AsyncServer.java:700)
            at com.koushikdutta.async.AsyncServer.run(AsyncServer.java:608)
            at com.koushikdutta.async.AsyncServer.access$700(AsyncServer.java:37)
            at com.koushikdutta.async.AsyncServer$13.run(AsyncServer.java:557)

[scmcfetridge]

I am having a very similar problem, my request is timing out and receiving the same error. Simple GET and POST, both have the same problem. Other API calls in the app are behaving perfectly well, but these calls are always failing. I wanted to post since it doesn't seem like an isolated incident. Please let me know if there is a fix for this!

[moynard]

i have the same problem like @scmcfetridge , with simple GET,POST,PUT call a request from a url and retrieve timeout and Im working with ios with Afnetworking and works perfect. and i have 3 projects with this library

[hgross4]

I'm using version 2.latest of Ion (2.+ as gradle dependency), and getting this on every few (maybe 1 in 10 or 20 on average?) Get requests to populate an image in an ImageView (code is below the log below). The URL is secure, https.

java.util.concurrent.TimeoutException at com.koushikdutta.async.http.AsyncHttpClient$2.run(AsyncHttpClient.java:247) at com.koushikdutta.async.AsyncServer.lockAndRunQueue(AsyncServer.java:708) at com.koushikdutta.async.AsyncServer.runLoop(AsyncServer.java:725) at com.koushikdutta.async.AsyncServer.run(AsyncServer.java:626) at com.koushikdutta.async.AsyncServer.access$700(AsyncServer.java:41) at com.koushikdutta.async.AsyncServer$13.run(AsyncServer.java:568)

Ion.with(pictureToRate) .placeholder(0) .load(firstPhoto.get("original_image_url").getAsString()) .setCallback(new FutureCallback()

[PavelDolbik]

I'm using version 2.latest of Ion (2.+ as gradle dependency), and getting this error too when I trying used device that have version android >= 19

[koush]

I believe this was fixed yesterday, I'll push a release shortly.

[markeins]

Hi, I'm using version 2.0.8 and facing the same problem with the socket connection. The only weird thing is that when I'm executing the POST request based on a user action (click), it ALWAYS WORKS; but, when I have it executed as a post-delayed action with 20 secs timer, if user does not select the action, then MOST of the times, IT FAILS, only several times it worked automatically...

Here is the logcat:

03-30 22:22:31.152 5432-6356/COM.MY.APP D/COM.MY.APP﹕ (0 ms) http://localhost:8080/server/api/device/sendRequest: preparing request 03-30 22:22:31.172 5432-5432/COM.MY.APP I/COM.MY.APP﹕ (0 ms) http://localhost:8080/server/api/device/sendRequest: Using loader: com.koushikdutta.ion.loader.HttpLoader@41b370f0 03-30 22:22:31.172 5432-6341/COM.MY.APP D/COM.MY.APP﹕ (0 ms) http://localhost:8080/server/api/device/sendRequest: Executing request. 03-30 22:22:31.182 5432-6341/COM.MY.APP D/COM.MY.APP﹕ (2 ms) http://localhost:8080/server/api/device/sendRequest: Reusing keep-alive socket 03-30 22:22:31.182 5432-6341/COM.MY.APP V/COM.MY.APP﹕ (2 ms) http://localhost:8080/server/api/device/sendRequest: socket connected 03-30 22:22:31.182 5432-6341/COM.MY.APP V/COM.MY.APP﹕ (10 ms) http://localhost:8080/server/api/device/sendRequest: POST /server/api/device/sendRequest HTTP/1.1 Host: localhost:8080 User-Agent: Dalvik/1.6.0 (Linux; U; Android 4.4.2; LG-V400 Build/KOT49I.A1403851534) Accept-Encoding: gzip, deflate Connection: keep-alive Accept: / Content-Type: application/json Content-Length: 150 03-30 22:22:31.192 5432-6341/COM.MY.APP V/COM.MY.APP﹕ (12 ms) http://localhost:8080/server/api/device/sendRequest: request completed 03-30 22:22:31.202 5432-6341/COM.MY.APP V/COM.MY.APP﹕ (28 ms) http://localhost:8080/server/api/device/sendRequest: closing out socket (exception) 03-30 22:22:37.192 5432-6341/COM.MY.APP E/COM.MY.APP﹕ (6020 ms) http://localhost:8080/server/api/device/sendRequest: Connection error 03-30 22:22:37.212 5432-6341/COM.MY.APP E/COM.MY.APP﹕ null java.util.concurrent.TimeoutException at com.koushikdutta.async.http.AsyncHttpClient$2.run(AsyncHttpClient.java:247) at com.koushikdutta.async.AsyncServer.lockAndRunQueue(AsyncServer.java:708) at com.koushikdutta.async.AsyncServer.runLoop(AsyncServer.java:725) at com.koushikdutta.async.AsyncServer.run(AsyncServer.java:626) at com.koushikdutta.async.AsyncServer.access$700(AsyncServer.java:41) at com.koushikdutta.async.AsyncServer$13.run(AsyncServer.java:568) 03-30 22:22:37.262 5432-5432/COM.MY.APP E/COM.MY.APP/DashboardActivity.java:465﹕ main java.util.concurrent.ExecutionException: java.util.concurrent.TimeoutException at com.koushikdutta.async.future.SimpleFuture.getResultOrThrow(SimpleFuture.java:71) at com.koushikdutta.async.future.SimpleFuture.get(SimpleFuture.java:66) at rx.internal.operators.OnSubscribeToObservableFuture$ToObservableFuture.call(OnSubscribeToObservableFuture.java:73) at rx.internal.operators.OnSubscribeToObservableFuture$ToObservableFuture.call(OnSubscribeToObservableFuture.java:42) at rx.Observable.unsafeSubscribe(Observable.java:7495) at rx.internal.operators.OperatorSubscribeOn$1$1.call(OperatorSubscribeOn.java:62) at rx.internal.schedulers.ScheduledAction.run(ScheduledAction.java:55) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422) at java.util.concurrent.FutureTask.run(FutureTask.java:237) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:152) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:265) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587) at java.lang.Thread.run(Thread.java:841) Caused by: java.util.concurrent.TimeoutException at com.koushikdutta.async.http.AsyncHttpClient$2.run(AsyncHttpClient.java:247) at com.koushikdutta.async.AsyncServer.lockAndRunQueue(AsyncServer.java:708) at com.koushikdutta.async.AsyncServer.runLoop(AsyncServer.java:725) at com.koushikdutta.async.AsyncServer.run(AsyncServer.java:626) at com.koushikdutta.async.AsyncServer.access$700(AsyncServer.java:41) at com.koushikdutta.async.AsyncServer$13.run(AsyncServer.java:568)

[NiklasMerz]

I have the same problem with the latest ION Version only for PUT requests. Get perfectly works.

public void upvoteDoc(View view) {

        String url = doc.apiURL + doc.getName() + "?apiKey=" + apiKey;
        Ion.with(getBaseContext()).load("PUT", url)
                .setTimeout(6000) 
                .setLogging("NPA_ION", Log.DEBUG)
                .setBodyParameter("Points", "1").asString()
                .setCallback(new FutureCallback<String>() {

                    @Override
                    public void onCompleted(Exception arg0, String arg1) {
                        // TODO Auto-generated method stub

                    }

                });
    }

[WasimMemon]

Have any progress on this ? because i am facing this issue in latest version also.

please can you provide some exception handler so we can display proper message to user.

Thanks for library...

[maarcosd]

Has anyone found a solution for this?

Having same issue only for PUT requests.

[BapaiahMandava]

hi,

what does setTimeout(-1) do? And even the public void onCompleted(Exception ex, WebSocket webSocket) method is being calling the webscoket every minute?

Pls throw some light why is this behaviour.

[shokri-navid]

i have same problem.... is there any solution?