`shouldNotAddTrackableWhenRenewedTokenDoesNotHaveCapabilityForTrackableId` (`RequestingNewTokenTest`) failing with "Timed out waiting for 30000 ms"

[QuintinWillison]

I've only seen one failure so far for this test, but am creating an issue so we can track it.

Failing from our Android emulation workflow. This link will only survive as long as GitHub keeps the test run logs, so I'll also quote from the output...

At API Level 27 (https://github.com/ably/ably-asset-tracking-android/pull/843):

com.ably.tracking.publisher.RequestingNewTokenTest > shouldNotAddTrackableWhenRenewedTokenDoesNotHaveCapabilityForTrackableId[test(AVD) - 8.1.0] FAILED 
    kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 30000 ms
    at kotlinx.coroutines.TimeoutKt.TimeoutCancellationException(Timeout.kt:186)

[ddms]: Exception during activity from Selector.
[ddms]: null
java.nio.channels.CancelledKeyException
    at java.base/sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:71)
    at java.base/sun.nio.ch.SelectionKeyImpl.readyOps(SelectionKeyImpl.java:130)
    at java.base/java.nio.channels.SelectionKey.isAcceptable(SelectionKey.java:425)
    at com.android.ddmlib.internal.jdwp.JdwpProxyServer.runAsServer(JdwpProxyServer.java:281)
    at com.android.ddmlib.internal.jdwp.JdwpProxyServer.run(JdwpProxyServer.java:321)
    at java.base/java.lang.Thread.run(Thread.java:829)

[sync-by-unito[bot]]

➤ Automation for Jira commented:

The link to the corresponding Jira issue is https://ably.atlassian.net/browse/SDK-3184

[QuintinWillison]

Probably related, I've seen shouldAddTrackableWhenRenewedTokenHasCapabilityForTrackableId from this same test suite also fail:

At API Level 24:

com.ably.tracking.publisher.RequestingNewTokenTest > shouldAddTrackableWhenRenewedTokenHasCapabilityForTrackableId[test(AVD) - 7.0] FAILED 
    java.lang.AssertionError
    at org.junit.Assert.fail(Assert.java:87)
Tests on test(AVD) - 7.0 failed: There was 1 failure(s).

[QuintinWillison]

And at API Level 27 (https://github.com/ably/ably-asset-tracking-android/pull/848):

com.ably.tracking.publisher.RequestingNewTokenTest > shouldAddTrackableWhenRenewedTokenHasCapabilityForTrackableId[test(AVD) - 8.1.0] FAILED 
    java.lang.AssertionError
    at org.junit.Assert.fail(Assert.java:87)

[QuintinWillison]

Again, perhaps different but same test, at API Level 27 (https://github.com/ably/ably-asset-tracking-android/pull/850):

com.ably.tracking.publisher.RequestingNewTokenTest > shouldNotAddTrackableWhenRenewedTokenDoesNotHaveCapabilityForTrackableId[test(AVD) - 8.1.0] FAILED 
    kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 30000 ms
    at kotlinx.coroutines.TimeoutKt.TimeoutCancellationException(Timeout.kt:186)

[QuintinWillison]

At API Level 27 (https://github.com/ably/ably-asset-tracking-android/pull/855):

com.ably.tracking.publisher.RequestingNewTokenTest > shouldNotAddTrackableWhenRenewedTokenDoesNotHaveCapabilityForTrackableId[test(AVD) - 8.1.0] FAILED 
    kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 30000 ms
    at kotlinx.coroutines.TimeoutKt.TimeoutCancellationException(Timeout.kt:186)

[QuintinWillison]

At API Level 29 (https://github.com/ably/ably-asset-tracking-android/pull/856):

com.ably.tracking.publisher.RequestingNewTokenTest > shouldNotAddTrackableWhenRenewedTokenDoesNotHaveCapabilityForTrackableId[test(AVD) - 10] FAILED 
    kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 30000 ms
    at kotlinx.coroutines.TimeoutKt.TimeoutCancellationException(Timeout.kt:186)

[AndyTWF]

I had a little look at this to see if I could get a local reproduction for the 30000ms error, I did manage to do so, when my emulators' wifi was in a state of "Connected to device, but unable to provide internet".

Simply turning off the Wifi didn't do it (the test false-positive'd because the device very quickly failed to connect to Ably), I had to achieve the above state by removing all the DNS server entries from my local machine (mac) and restart android studio.

The steps:

• Run the test
• An exception is thrown, as a result of a timeout whilst connecting to Ably (almost immediately)
• Execution enters publisher.stop()
• Hangs there for 30s (appears to be at the ably.close() call in StopWorker), then test fails with exception

[AndyTWF]

Another way the test could be improved that I noticed whilst I was investigating the above: if an Exception is thrown for any other reason, the test can return a false-positive result.

A possible fix would be to catch the specific type of exception we expect for the purpose of this test, or pick some information out of the exception message to ensure that it's the correct one (in my case, with emulator Wifi just turned off, the test passed quickly because it couldn't connect to Ably).

[QuintinWillison]

As previously noted there is a possible related failure in shouldAddTrackableWhenRenewedTokenHasCapabilityForTrackableId as seen here (https://github.com/ably/ably-asset-tracking-android/pull/866):

com.ably.tracking.publisher.RequestingNewTokenTest > shouldAddTrackableWhenRenewedTokenHasCapabilityForTrackableId[test(AVD) - 5.0.2] FAILED 
    java.lang.AssertionError
    at org.junit.Assert.fail(Assert.java:87)

A bit more detail from the build report for publishing-sdk:

java.lang.AssertionError
at org.junit.Assert.fail(Assert.java:87)
at org.junit.Assert.assertTrue(Assert.java:42)
at org.junit.Assert.assertTrue(Assert.java:53)
at com.ably.tracking.publisher.RequestingNewTokenTest.shouldAddTrackableWhenRenewedTokenHasCapabilityForTrackableId(RequestingNewTokenTest.kt:47)

[QuintinWillison]

At API Level 27 (https://github.com/ably/ably-asset-tracking-android/pull/917, at https://github.com/ably/ably-asset-tracking-android/pull/917/commits/31ded369952368cfaa816f7a175002177c0d4053):

com.ably.tracking.publisher.RequestingNewTokenTest > shouldAddTrackableWhenRenewedTokenHasCapabilityForTrackableId[test(AVD) - 8.1.0] FAILED 
    android.app.RemoteServiceException: Bad notification for startForeground: java.lang.RuntimeException: invalid channel for service notification: Notification(channel=test-notification-channel pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x40 color=0x00000000 vis=PRIVATE)
    at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1768)

With a little bit more information from the build report:

android.app.RemoteServiceException: Bad notification for startForeground: java.lang.RuntimeException: invalid channel for service notification: Notification(channel=test-notification-channel pri=0 contentView=null vibrate=null sound=null defaults=0x0 flags=0x40 color=0x00000000 vis=PRIVATE)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1768)
at android.os.Handler.dispatchMessage(Handler.java:106)
at android.os.Looper.loop(Looper.java:164)
at android.app.ActivityThread.main(ActivityThread.java:6494)
at java.lang.reflect.Method.invoke(Native Method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807)

[AndyTWF]

The above issue from Quintin is something that I experienced during local testing when trying to use Android API 33 - when I googled it was something along the lines of needing to create a channel for the notification