Android System.out: (ERROR): io.ably.lib.transport.WebSocketTransport: No activity for 25000ms, closing connection

[abhimanyuraj]

No description provided.

[SimonWoolf]

Another customer reported this
their (mildly redacted) code: https://gist.github.com/SimonWoolf/0d98988cd9395d6ef5fbaf4b971d31ae
(mildly redacted) verbose logs: https://gist.github.com/SimonWoolf/bf7024814540d8c19b2590cfcec56650

The lib sends a CLOSE and receives a CLOSED, but the websocket seems to stay open until the 25s activity timeout; which is odd, as realtime definitely disconnects websockets after it sends a CLOSED.

(VERBOSE): io.ably.lib.transport.ConnectionManager: onMessage( {"action":8,"flags":0,"count":0,"timestamp":0}
(VERBOSE): io.ably.lib.transport.ConnectionManager: setState(): setting closed
(VERBOSE): io.ably.lib.transport.ConnectionManager: notifyState(): notifying disconnected; id = null
(VERBOSE): io.ably.lib.transport.WebSocketTransport: checkActivity: ok
(ERROR): io.ably.lib.transport.WebSocketTransport: No activity for 25000ms, closing connection

(also odd that the connection state would return to disconnected after going into closed).

That's on 0.8.11, but customer gave a similar log for 1.0.

[emilm]

Yes it will remain open forever. And the WebSocketTransport will report no activity etc forever. Seems like that thread maintaining activity just keeps on living.

[paddybyers]

I've added 6899a02 which eliminates the commonly-seen error message "No activity for 25000ms, closing connection", where the timer was left running even after the WsClient was closed.

I've also added 934b562 which has some tests to verify that the connectionmanager thread is exiting cleanly in various situations.

@emilm I tried to reproduce what you're doing in your code but I've not been able to reproduce the situation in which the connectionmanager fails to exit. Are you able to provide any additional information which would help me reproduce it? Or a code sample?

Thanks

[emilm]

Hello! All I did was:

`
public void open() {

ExecutorService executor = Executors.newSingleThreadExecutor();
executor.submit(() -> {
    try {

        logger.info("Logging in with customer ID {}.", user.getCustomerId());

        logger.info("Connecting to ably.");
        ClientOptions options = new ClientOptions();
        options.logLevel = Log.NONE;
        options.authUrl = String.format("https://xxxxxx/" + this.user.getCustomerId());

        this.ably = new AblyRealtime(options);
        this.ably.connection.on(this::onConnectionStateChanged);

        this.ably.connection.connect();

    } catch (AblyException ex) {
        logger.error("Failed to connect to ably for customer ID '{}'.", user.getCustomerId(), ex);
    }
});

}`

...

`private void onConnectionStateChanged(ConnectionStateListener.ConnectionStateChange state) {

logger.info("Connection state changed to '{}' from '{}'. Reason: '{}'.", state.current, state.previous, state.reason);


switch (state.current) {
    case connected:
        this.isConnected = true;
        break;

    default:
        this.isConnected = false;
        break;
}

if (this.isConnected()) {
    ably.channels.clear();
    logger.info("Subscribing to channel {}.", user.getCustomerId());
    this.sendChannel = ably.channels.get(String.format("control:%s", user.getCustomerId()));
    this.receiveChannel = ably.channels.get(String.format("listen:%s", user.getCustomerId()));


    try {
        this.receiveChannel.subscribe(this::onChannelReceiveMessage);
    } catch (AblyException e) {
        e.printStackTrace();
    }
}

}`

...

`public void close() {
if (this.ably == null)
return;

this.ably.close();

}`

In short: open() -> connect -> onConnected -> get 2 channels, subscribe to 1 of them -> close()

[paddybyers]

and what context is close() called from? Is it a callback from the library, or the main thread, or a thread that your app created?

Also, is this on Android or JRE, and which version?

[emilm]

JRE 1.8 It's opened and closed on the main thread. But the executor inside open() is actually connecting I suppose. So that's a different thread in on itself. But the main thread closes. But that might change.

[paddybyers]

I tried to replicate that (ie open in a new thread, close in the main thread) in this test: https://github.com/ably/ably-java/blob/master/lib/src/test/java/io/ably/lib/test/realtime/ConnectionManagerTest.java#L294

but in this case the thread exits without any problem :(

[paddybyers]

BTW have you retried with this change: 6899a02 ?

Before that fix, the dangling Timer thread could prevent the VM from exiting.

[emilm]

I haven't tried any of it so far. Is there a dev channel on bintray? Or do I have to compile and test myself?

[paddybyers]

I haven't tried any of it so far. Is there a dev channel on bintray? Or do I have to compile and test myself?

No, I haven't made a release with that fix yet. If you checkout the source you can build a fat jar with:

./gradlew java:fullJar

I will do a new release probably on Wednesday this week but it would be great if you are able to check it before then.

[emilm]

Yes! That worked! Thank you!

[paddybyers]

OK, great. I'm travelling tomorrow but I'll do a new release as soon as I get back.

[emilm]

Are you back yet? I hope you can push out a new release soon, thanks!

[mattheworiordan]

Hi @emilm. I'll check in with @paddybyers in the morning to see if we can get this pushed out. Sorry for the delay.

[emilm]

Hello again... I hope this can be done today so I don't have to add a fat jar to the GIT source tree. :)

[mattheworiordan]

Been promised it will happen today! @paddybyers is unfortunately flat out on something else, but this is next in his list

[mattheworiordan]

Hi @emilm. Apologies for the delay, we're just swamped with things right now and our previous maintainer is not around, so only @paddybyers is really able to do this. We'll get this done as soon as he gets a chance to breath.

[emilm]

I caved in and used the JAR file I compiled myself. But it would be nice to get it in this week or something!

[emilm]

Would STILL be nice with using bintray instead of a local jar though ;)

[mattheworiordan]

@emilm this came up in our stand up yesterday, I am really sorry, we've just been flat out. @tcard is now looking into this as a result. I promise we'll do everything we can to get a release out very soon.

[paddybyers]

This is released in 1.0.1 (https://bintray.com/ably-io/ably/ably-java/1.0.1, https://bintray.com/ably-io/ably/ably-android/1.0.1)