search

ably / ably-java

Java, Android, Clojure and Scala client library SDK for Ably realtime messaging service
https://ably.com/download
Apache License 2.0
85 stars 39 forks source link

Android reconnection anomalies after exiting Airplane mode #488

Open paddybyers opened 5 years ago

paddybyers commented 5 years ago

Reported issue:

We're using version io.ably:ably-android:1.0.14

After the ably instance gets disconnected (airplane mode) we'll receive the events for reconnection. After reconnecting, none of the missed messages are delivered. We receive the reconnection events.

If we enter airplane mode again, the library does not send any connection events to the listener anymore. If we disable airplane mode, the connection listener is not called.

┆Issue is synchronized with this Jira Task by Unito

Srushtika commented 5 years ago

Log trace from the customer:

2019-06-26 11:51:40.300 18465-18486/<domain-name> D/BluetoothAdapter: onBluetoothServiceDown: android.bluetooth.IBluetooth$Stub$Proxy@658684d
2019-06-26 11:51:40.326 18465-18574/<domain-name> E/io.rollout: Push updates connection failed
    io.rollout.okhttp3.internal.http2.StreamResetException: stream was reset: CANCEL
        at io.rollout.okhttp3.internal.http2.Http2Stream$b.read(SourceFile:1436)
        at io.rollout.okhttp3.internal.http2.Http2Codec$a.read(SourceFile:210)
        at io.rollout.internal.r.indexOfElement(SourceFile:384)
        at io.rollout.internal.r.indexOfElement(SourceFile:373)
        at io.rollout.sse.okhttp3.internal.sse.ServerSentEventReader.a(SourceFile:60)
        at io.rollout.sse.okhttp3.internal.sse.RealEventSource.processResponse(SourceFile:80)
        at io.rollout.sse.okhttp3.internal.sse.RealEventSource.onResponse(SourceFile:54)
        at io.rollout.internal.d$a.execute(SourceFile:153)
        at io.rollout.okhttp3.internal.NamedRunnable.run(SourceFile:32)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
        at java.lang.Thread.run(Thread.java:764)
2019-06-26 11:51:40.327 18465-18580/<domain-name> I/System.out: (DEBUG): io.ably.lib.transport.ITransport: getConnectParams: params = [key:sC82qA.z6g7ag:m_zDbSzIoWPBSAA9, v:1.0, format:msgpack, resume:e7dJYtlFwAZD5K!VZ335Njjcua_Hiug-c34be7dJYtlFwAZD5K, connectionSerial:0, clientId:1078065, heartbeats:false, lib:android-1.0.14]
2019-06-26 11:51:40.345 18465-18740/<domain-name> I/System.out: (ERROR): io.ably.lib.transport.WebSocketTransport: Unexpected exception in WsClient
2019-06-26 11:51:40.345 18465-18740/<domain-name> I/System.out: java.net.UnknownHostException: realtime.ably.io
2019-06-26 11:51:40.346 18465-18740/<domain-name> I/System.out:     at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:208)
2019-06-26 11:51:40.346 18465-18740/<domain-name> I/System.out:     at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:436)
2019-06-26 11:51:40.346 18465-18740/<domain-name> I/System.out:     at java.net.Socket.connect(Socket.java:621)
2019-06-26 11:51:40.346 18465-18740/<domain-name> I/System.out:     at com.android.org.conscrypt.ConscryptSocketBase.connect(ConscryptSocketBase.java:152)
2019-06-26 11:51:40.346 18465-18740/<domain-name> I/System.out:     at org.java_websocket.client.WebSocketClient.run(WebSocketClient.java:166)
2019-06-26 11:51:40.346 18465-18740/<domain-name> I/System.out:     at java.lang.Thread.run(Thread.java:764)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err: java.net.UnknownHostException: Unable to resolve host "internet-up.ably-realtime.com": No address associated with hostname
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:157)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:105)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at java.net.InetAddress.getAllByName(InetAddress.java:1154)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.Dns$1.lookup(Dns.java:39)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.RouteSelector.resetNextInetSocketAddress(RouteSelector.java:175)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.RouteSelector.nextProxy(RouteSelector.java:141)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.RouteSelector.next(RouteSelector.java:83)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.StreamAllocation.findConnection(StreamAllocation.java:174)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.StreamAllocation.findHealthyConnection(StreamAllocation.java:126)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.StreamAllocation.newStream(StreamAllocation.java:95)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.HttpEngine.connect(HttpEngine.java:281)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.HttpEngine.sendRequest(HttpEngine.java:224)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.huc.HttpURLConnectionImpl.execute(HttpURLConnectionImpl.java:461)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:407)
2019-06-26 11:51:40.371 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getResponseCode(HttpURLConnectionImpl.java:538)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpCore.readResponse(HttpCore.java:385)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpCore.httpExecute(HttpCore.java:242)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpCore.httpExecute(HttpCore.java:155)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpCore.httpExecuteWithRetry(HttpCore.java:74)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpHelpers.httpExecute(HttpHelpers.java:107)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpHelpers.getUrl(HttpHelpers.java:56)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpHelpers.getUrlString(HttpHelpers.java:44)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.transport.ConnectionManager.checkConnectivity(ConnectionManager.java:1043)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.transport.ConnectionManager.checkSuspend(ConnectionManager.java:803)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.transport.ConnectionManager.handleStateChange(ConnectionManager.java:748)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.transport.ConnectionManager.access$1400(ConnectionManager.java:24)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at io.ably.lib.transport.ConnectionManager$CMThread.run(ConnectionManager.java:897)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err: Caused by: android.system.GaiException: android_getaddrinfo failed: EAI_NODATA (No address associated with hostname)
2019-06-26 11:51:40.372 18465-18580/<domain-name> W/System.err:     at libcore.io.Linux.android_getaddrinfo(Native Method)
2019-06-26 11:51:40.373 18465-18580/<domain-name> W/System.err:     at libcore.io.BlockGuardOs.android_getaddrinfo(BlockGuardOs.java:172)
2019-06-26 11:51:40.373 18465-18580/<domain-name> W/System.err:     at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:137)
2019-06-26 11:51:40.373 18465-18580/<domain-name> W/System.err:  ... 26 more
2019-06-26 11:52:08.997 18465-18486/<domain-name> D/BluetoothAdapter: onBluetoothServiceUp: android.bluetooth.IBluetooth$Stub$Proxy@57e194e
2019-06-26 11:52:10.375 18465-18580/<domain-name> I/System.out: (DEBUG): io.ably.lib.transport.ITransport: getConnectParams: params = [key:sC82qA.z6g7ag:m_zDbSzIoWPBSAA9, v:1.0, format:msgpack, resume:e7dJYtlFwAZD5K!VZ335Njjcua_Hiug-c34be7dJYtlFwAZD5K, connectionSerial:0, clientId:1078065, heartbeats:false, lib:android-1.0.14]
2019-06-26 11:52:10.385 18465-19059/<domain-name> I/System.out: (ERROR): io.ably.lib.transport.WebSocketTransport: Unexpected exception in WsClient
2019-06-26 11:52:10.385 18465-19059/<domain-name> I/System.out: java.net.UnknownHostException: realtime.ably.io
2019-06-26 11:52:10.385 18465-19059/<domain-name> I/System.out:     at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:208)
2019-06-26 11:52:10.385 18465-19059/<domain-name> I/System.out:     at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:436)
2019-06-26 11:52:10.385 18465-19059/<domain-name> I/System.out:     at java.net.Socket.connect(Socket.java:621)
2019-06-26 11:52:10.385 18465-19059/<domain-name> I/System.out:     at com.android.org.conscrypt.ConscryptSocketBase.connect(ConscryptSocketBase.java:152)
2019-06-26 11:52:10.385 18465-19059/<domain-name> I/System.out:     at org.java_websocket.client.WebSocketClient.run(WebSocketClient.java:166)
2019-06-26 11:52:10.386 18465-19059/<domain-name> I/System.out:     at java.lang.Thread.run(Thread.java:764)
2019-06-26 11:52:10.392 18465-18580/<domain-name> W/System.err: java.net.UnknownHostException: Unable to resolve host "internet-up.ably-realtime.com": No address associated with hostname
2019-06-26 11:52:10.393 18465-18580/<domain-name> W/System.err:     at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:157)
2019-06-26 11:52:10.393 18465-18580/<domain-name> W/System.err:     at java.net.Inet6AddressImpl.lookupAllHostAddr(Inet6AddressImpl.java:105)
2019-06-26 11:52:10.393 18465-18580/<domain-name> W/System.err:     at java.net.InetAddress.getAllByName(InetAddress.java:1154)
2019-06-26 11:52:10.393 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.Dns$1.lookup(Dns.java:39)
2019-06-26 11:52:10.393 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.RouteSelector.resetNextInetSocketAddress(RouteSelector.java:175)
2019-06-26 11:52:10.393 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.RouteSelector.nextProxy(RouteSelector.java:141)
2019-06-26 11:52:10.393 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.RouteSelector.next(RouteSelector.java:83)
2019-06-26 11:52:10.394 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.StreamAllocation.findConnection(StreamAllocation.java:174)
2019-06-26 11:52:10.394 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.StreamAllocation.findHealthyConnection(StreamAllocation.java:126)
2019-06-26 11:52:10.394 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.StreamAllocation.newStream(StreamAllocation.java:95)
2019-06-26 11:52:10.394 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.HttpEngine.connect(HttpEngine.java:281)
2019-06-26 11:52:10.394 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.http.HttpEngine.sendRequest(HttpEngine.java:224)
2019-06-26 11:52:10.394 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.huc.HttpURLConnectionImpl.execute(HttpURLConnectionImpl.java:461)
2019-06-26 11:52:10.394 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getResponse(HttpURLConnectionImpl.java:407)
2019-06-26 11:52:10.394 18465-18580/<domain-name> W/System.err:     at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getResponseCode(HttpURLConnectionImpl.java:538)
2019-06-26 11:52:10.395 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpCore.readResponse(HttpCore.java:385)
2019-06-26 11:52:10.395 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpCore.httpExecute(HttpCore.java:242)
2019-06-26 11:52:10.395 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpCore.httpExecute(HttpCore.java:155)
2019-06-26 11:52:10.395 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpCore.httpExecuteWithRetry(HttpCore.java:74)
2019-06-26 11:52:10.395 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpHelpers.httpExecute(HttpHelpers.java:107)
2019-06-26 11:52:10.396 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpHelpers.getUrl(HttpHelpers.java:56)
2019-06-26 11:52:10.396 18465-18580/<domain-name> W/System.err:     at io.ably.lib.http.HttpHelpers.getUrlString(HttpHelpers.java:44)
2019-06-26 11:52:10.396 18465-18580/<domain-name> W/System.err:     at io.ably.lib.transport.ConnectionManager.checkConnectivity(ConnectionManager.java:1043)
2019-06-26 11:52:10.396 18465-18580/<domain-name> W/System.err:     at io.ably.lib.transport.ConnectionManager.checkSuspend(ConnectionManager.java:803)
2019-06-26 11:52:10.397 18465-18580/<domain-name> W/System.err:     at io.ably.lib.transport.ConnectionManager.handleStateChange(ConnectionManager.java:748)
2019-06-26 11:52:10.397 18465-18580/<domain-name> W/System.err:     at io.ably.lib.transport.ConnectionManager.access$1400(ConnectionManager.java:24)
2019-06-26 11:52:10.397 18465-18580/<domain-name> W/System.err:     at io.ably.lib.transport.ConnectionManager$CMThread.run(ConnectionManager.java:897)
2019-06-26 11:52:10.397 18465-18580/<domain-name> W/System.err: Caused by: android.system.GaiException: android_getaddrinfo failed: EAI_NODATA (No address associated with hostname)
2019-06-26 11:52:10.397 18465-18580/<domain-name> W/System.err:     at libcore.io.Linux.android_getaddrinfo(Native Method)
2019-06-26 11:52:10.397 18465-18580/<domain-name> W/System.err:     at libcore.io.BlockGuardOs.android_getaddrinfo(BlockGuardOs.java:172)
2019-06-26 11:52:10.397 18465-18580/<domain-name> W/System.err:     at java.net.Inet6AddressImpl.lookupHostByName(Inet6AddressImpl.java:137)
2019-06-26 11:52:10.397 18465-18580/<domain-name> W/System.err:  ... 26 more
2019-06-26 11:52:11.051 18465-18465/<domain-name> W/Glide: Load failed for  with size [1440x1585]
    class com.bumptech.glide.load.engine.GlideException: Failed to load resource
2019-06-26 11:52:40.403 18465-18580/<domain-name> I/System.out: (DEBUG): io.ably.lib.transport.ITransport: getConnectParams: params = [key:sC82qA.z6g7ag:m_zDbSzIoWPBSAA9, v:1.0, format:msgpack, resume:e7dJYtlFwAZD5K!VZ335Njjcua_Hiug-c34be7dJYtlFwAZD5K, connectionSerial:0, clientId:1078065, heartbeats:false, lib:android-1.0.14]
2019-06-26 11:52:58.407 18465-18489/<domain-name> D/BluetoothAdapter: onBluetoothServiceDown: android.bluetooth.IBluetooth$Stub$Proxy@57e194e
2019-06-26 11:53:56.473 18465-18487/<domain-name> D/BluetoothAdapter: onBluetoothServiceUp: android.bluetooth.IBluetooth$Stub$Proxy@6c6b00a
2019-06-26 11:53:58.576 18465-18465/<domain-name> W/Glide: Load failed for  with size [1440x1585]
    class com.bumptech.glide.load.engine.GlideException: Failed to load resource
2019-06-26 11:55:16.536 18465-18487/<domain-name> D/BluetoothAdapter: onBluetoothServiceDown: android.bluetooth.IBluetooth$Stub$Proxy@6c6b00a
2019-06-26 11:55:31.516 18465-18487/<domain-name> D/BluetoothAdapter: onBluetoothServiceUp: android.bluetooth.IBluetooth$Stub$Proxy@df8307b
amihaiemil commented 5 years ago

@paddybyers Is there some way we can simulate Airplane mode in a testcase? :D

paddybyers commented 5 years ago

Is there some way we can simulate Airplane mode in a testcase?

I did find something at one time that does enable you to do this. It was a project by Netflix or one of the other big tech companies. It's an APK that comes signed with the AOSP platform key that exposes an AIDL API that allows you to do various things from test cases such as enable/disable Wifi etc. I've looked and can't find it straight away.

paddybyers commented 5 years ago

in the meantime, we need at least to try to reproduce this manually, and investigate.

paddybyers commented 5 years ago

It's this: https://github.com/linkedin/test-butler. Definitely worth a look.

One question is whether or not we can have it work with Travis. Perhaps that's an argument for setting up something using an emulator that we control somewhere (maybe triggered as a Github action?).

amihaiemil commented 4 years ago

@paddybyers I read the docs of Test Butler. It only seems useful in testing actual Android apps and for UI testing.

So I don't see its use in this repo, which is just a library.

Do you think it would make sense to use it in writing tests for push-example-android? I guess we could continue developing it to cover all the library's functionalities.

mattheworiordan commented 4 years ago

If we need more sophisticated real-device testing, I believe we should look at integrating something like https://firebase.google.com/docs/test-lab or https://www.bitrise.io/ , even if we only spin up specific tests in those environments where a real-ish device is needed

amihaiemil commented 4 years ago

@paddybyers I've managed to download the google-services.json and run the push-example app. However, the Ably instance doesn't seem to be able to connect at all:

Screenshot 2019-11-20 at 10 55 28

I also see the following log in the console:

(ERROR): io.ably.lib.transport.WebSocketTransport: Unexpected exception attempting connection; wsUri = wss://null-realtime.ably.io:443/
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out: io.ably.lib.types.AblyException: io.ably.lib.types.AblyException: java.lang.Exception: Auth.requestToken(): options must include valid authentication parameters
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out:     at io.ably.lib.rest.Auth.requestToken(Auth.java:591)
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out:     at io.ably.lib.rest.Auth.assertValidToken(Auth.java:963)
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out:     at io.ably.lib.rest.Auth.assertValidToken(Auth.java:947)
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out:     at io.ably.lib.rest.Auth.getAuthParams(Auth.java:812)
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out:     at io.ably.lib.transport.WebSocketTransport.connect(WebSocketTransport.java:66)
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out:     at io.ably.lib.transport.ConnectionManager.connectImpl(ConnectionManager.java:1009)
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out:     at io.ably.lib.transport.ConnectionManager.handleStateRequest(ConnectionManager.java:688)
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out:     at io.ably.lib.transport.ConnectionManager.access$1000(ConnectionManager.java:26)
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out:     at io.ably.lib.transport.ConnectionManager$CMThread.run(ConnectionManager.java:879)
2019-11-20 10:54:33.754 28103-28173/io.ably.example.androidpushexample I/System.out: Caused by: io.ably.lib.types.AblyException: java.lang.Exception: Auth.requestToken(): options must include valid authentication parameters
2019-11-20 10:54:33.755 28103-28173/io.ably.example.androidpushexample I/System.out:     at io.ably.lib.rest.Auth.requestToken(Auth.java:679)

This happens with both the initial ably sdk dependency (1.1.3) and with the latest one (1.1.6).

I think we're wasting our time with this ticket, to be honest. If there's a reconnection anomaly, we should check the existing tests for the scenario. Whether the connection drops because of Airplane mode or some other reason should be irrelevant.

Furthermore, the client's Android developers should be able to give us more information like logs and so on. Can we ask someone for more information and actually whether this problem occured again? After all, it's an old ticket.