diff --git a/app/build.gradle.kts b/app/build.gradle.kts index 3ac0ba5..fef7b54 100644 --- a/app/build.gradle.kts +++ b/app/build.gradle.kts @@ -40,8 +40,16 @@ android { // the paragraph above, so the code keeps climbing and the NAME is what // closes the 0.10 -> 0.12 gap. They are allowed to differ: the code is // ordering, the name is what a person reads. - versionCode = 21 - versionName = "0.19" + // The NAME is what the website and the app show a person, and it now + // matches the code rather than trailing it: somebody comparing the + // download page against their own app should not have to know that one + // number is ordering and the other is a label. + // + // The code goes to 22 because 21 is published and a code is never + // reused. So they line up as closely as they can from here: name 0.21, + // code 22, and each release from now moves both. + versionCode = 22 + versionName = "0.21" testInstrumentationRunner = "androidx.test.runner.AndroidJUnitRunner" } diff --git a/app/src/main/kotlin/io/flamenet/messenger/app/MessengerService.kt b/app/src/main/kotlin/io/flamenet/messenger/app/MessengerService.kt index 4b1225c..3953e13 100644 --- a/app/src/main/kotlin/io/flamenet/messenger/app/MessengerService.kt +++ b/app/src/main/kotlin/io/flamenet/messenger/app/MessengerService.kt @@ -253,9 +253,28 @@ class MessengerService : Service() { // Ask, take what is there, go again. A request a second for the // length of a call, and no worst case. val onACall = CallManager.aCallIsUp() - val touched = - runCatching { s.receive(if (onACall) 0 else WAIT_SECONDS) } - .getOrDefault(emptySet()) + val outcome = runCatching { s.receive(if (onACall) 0 else WAIT_SECONDS) } + val touched = outcome.getOrDefault(emptySet()) + // How long a cycle took, every cycle. + // + // The relay can measure how long a phone takes to collect what is + // waiting for it, and for one Android emulator that was 112 seconds + // on average against 5 for an iPhone. Nothing here could say why: + // a cycle that takes ninety seconds of starved CPU and a loop that + // is not running at all look identical from the outside, and the + // only Android device to hand was an emulator producing thirty + // second UI frames, which cannot tell them apart either. + // + // So: say it. One line per cycle, with what it cost and what came + // back, so the next run on a real handset answers the question + // instead of raising it again. + val took = System.currentTimeMillis() - started + android.util.Log.i( + "fnmsg-poll", + "cycle ${took}ms held=${if (onACall) 0 else WAIT_SECONDS}s " + + "call=$onACall touched=${touched.size} " + + (outcome.exceptionOrNull()?.let { "failed=${it::class.simpleName}" } ?: "ok"), + ) if (touched.isNotEmpty()) notifyMessages(touched.size) // Reply reminders fire from THIS loop, after `receive()`, and the // order matters: an inbound message clears the reminder inside diff --git a/app/src/main/kotlin/io/flamenet/messenger/app/MessengerViewModel.kt b/app/src/main/kotlin/io/flamenet/messenger/app/MessengerViewModel.kt index 3e3d8fa..62c86cf 100644 --- a/app/src/main/kotlin/io/flamenet/messenger/app/MessengerViewModel.kt +++ b/app/src/main/kotlin/io/flamenet/messenger/app/MessengerViewModel.kt @@ -3773,9 +3773,44 @@ class MessengerViewModel( // A story arriving must appear without the user pulling // to refresh; it is filed by `receive()` and read back // here. + // A call cannot wait on a twenty-second hold. + // + // THIS is the loop that runs while somebody is looking + // at the app, and placing a call is exactly that. The + // activity stops `MessengerService` on the way in -- + // "exactly one poller at a time" -- so the service's + // own fast poll, which was fixed first, is not running + // when it matters. The hold was fixed in the loop that + // was switched off and left in the one that was on. + // + // Measured on the relay: Android took 112 seconds on + // average to collect what was waiting for it, against 5 + // for an iPhone, and an answer sat on the relay while + // this end was inside its twenty-second hold. + val onACall = CallManager.aCallIsUp() + val pollStarted = System.currentTimeMillis() val received = withContext(Dispatchers.IO) { - val got = runCatching { current.receive(POLL_WAIT_SECONDS) } + val got = + runCatching { + current.receive(if (onACall) 0 else POLL_WAIT_SECONDS) + } + // The loop that actually runs while somebody is + // looking at the app, which is when calls are + // placed. The service has a line like this and + // the service is STOPPED here by design, so for + // two rounds the traces came back empty and the + // silence was read as "the loop is not running" + // rather than "the loop has no voice". + android.util.Log.i( + "fnmsg-poll", + "vm cycle ${System.currentTimeMillis() - pollStarted}ms " + + "held=${if (onACall) 0 else POLL_WAIT_SECONDS}s " + + "call=$onACall " + + (got.exceptionOrNull() + ?.let { "failed=${it::class.simpleName}: ${it.message}" } + ?: "got=${got.getOrNull()?.size ?: 0}"), + ) // Cached plaintext for anything nothing refers // to any more, an expired message's photo, a // story past its lifetime. diff --git a/app/src/test/kotlin/io/flamenet/messenger/app/NoSignalIsEatenByTheServiceTest.kt b/app/src/test/kotlin/io/flamenet/messenger/app/NoSignalIsEatenByTheServiceTest.kt index 7afd4b0..450ac3d 100644 --- a/app/src/test/kotlin/io/flamenet/messenger/app/NoSignalIsEatenByTheServiceTest.kt +++ b/app/src/test/kotlin/io/flamenet/messenger/app/NoSignalIsEatenByTheServiceTest.kt @@ -198,3 +198,57 @@ class ClosingTheAppEndsTheCallTest { assertTrue(fn.contains("if (!CallManager.aCallIsUp()) return")) } } + +/** + * The poll loop says what each cycle cost. + * + * The relay can measure how long a phone takes to collect what is waiting for + * it: 112 seconds on average for one Android emulator against 5 for an + * iPhone. Nothing on this side could say why, because a cycle that takes + * ninety seconds of starved CPU and a loop that is not running at all look + * identical from outside the process. + * + * A number nobody can see is a number nobody can act on, which is how most of + * a week went. + */ +class ThePollLoopSaysWhatItCostTest { + private fun source(path: String): String { + val file = File("src/main/kotlin/io/flamenet/messenger/app/$path") + assertTrue("missing $path", file.exists()) + return file.readText() + } + + private val service get() = source("MessengerService.kt") + + @Test + fun `every cycle logs its duration`() { + assertTrue( + "no cycle timing at all", + service.contains("val took = System.currentTimeMillis() - started"), + ) + assertTrue(service.contains("\"fnmsg-poll\"")) + } + + /** + * The three things that separate the explanations: how long it took, how + * long it was allowed to hold, and whether it came back at all. + */ + @Test + fun `the line carries enough to tell the causes apart`() { + val line = service.substringAfter("\"fnmsg-poll\"").take(400) + assertTrue("duration missing", line.contains("cycle \${took}ms")) + assertTrue("hold missing", line.contains("held=")) + assertTrue("call state missing", line.contains("call=\$onACall")) + assertTrue("failure missing", line.contains("exceptionOrNull()")) + } + + /** A throwing poll must still be counted, not swallowed into a silent retry. */ + @Test + fun `a failed cycle is still reported`() { + assertTrue( + "the failure has to survive into the log line", + service.contains("val outcome = runCatching { s.receive("), + ) + assertTrue(service.contains("outcome.getOrDefault(emptySet())")) + } +} diff --git a/client/src/main/kotlin/io/flamenet/client/RelayClient.kt b/client/src/main/kotlin/io/flamenet/client/RelayClient.kt index 3bb3989..4891262 100644 --- a/client/src/main/kotlin/io/flamenet/client/RelayClient.kt +++ b/client/src/main/kotlin/io/flamenet/client/RelayClient.kt @@ -38,6 +38,21 @@ class RelayClient( http .newBuilder() .callTimeout(MAX_WAIT_SECONDS + 20L, TimeUnit.SECONDS) + // AND the read timeout, which is the one that was killing it. + // + // `callTimeout` bounds the whole call; `readTimeout` bounds the + // wait between bytes, and OkHttp defaults it to TEN SECONDS. A held + // poll asks the relay to say nothing for up to twenty, so every + // single one died at ten with a SocketTimeoutException, long before + // the generous call timeout above could matter. + // + // Nothing said so. The failure was swallowed into a retry, the loop + // looked like it was working, and the effect showed up only on the + // relay: this device took an average of 112 seconds to collect what + // was waiting for it against 5 for an iPhone, because a message + // written into a connection this end had already abandoned waited + // for the next poll instead. + .readTimeout(MAX_WAIT_SECONDS + 20L, TimeUnit.SECONDS) .build() } diff --git a/client/src/test/kotlin/io/flamenet/client/AHeldPollOutlivesItsHoldTest.kt b/client/src/test/kotlin/io/flamenet/client/AHeldPollOutlivesItsHoldTest.kt new file mode 100644 index 0000000..26e3856 --- /dev/null +++ b/client/src/test/kotlin/io/flamenet/client/AHeldPollOutlivesItsHoldTest.kt @@ -0,0 +1,55 @@ +package io.flamenet.client + +import java.io.File +import kotlin.test.Test +import kotlin.test.assertTrue + +/** + * A poll that asks the relay to hold must survive the hold. + * + * `heldHttp` raised `callTimeout` and left `readTimeout` at OkHttp's default + * of TEN SECONDS. A held poll asks the relay to stay silent for up to twenty, + * so every one died at ten with a SocketTimeoutException, and the generous + * call timeout above it never got a chance to matter. + * + * Measured on a real device before the fix, once the loop was made to say what + * it was doing: + * + * vm cycle 10125ms held=20s call=false failed=SocketTimeoutException + * vm cycle 10009ms held=20s call=false failed=SocketTimeoutException + * vm cycle 10012ms held=20s call=false failed=SocketTimeoutException + * + * Every single poll failing, silently, because the failure was swallowed into + * a retry and the loop looked busy. It showed up only as a number on the + * relay: 112 seconds to collect what was waiting, against 5 for an iPhone. + */ +class AHeldPollOutlivesItsHoldTest { + private val relay = + File("src/main/kotlin/io/flamenet/client/RelayClient.kt").readText() + + @Test + fun `the held client raises the read timeout, not only the call timeout`() { + val block = relay.substringAfter("private val heldHttp").substringBefore("}") + assertTrue( + block.contains(".readTimeout(MAX_WAIT_SECONDS + 20L, TimeUnit.SECONDS)"), + "readTimeout left at OkHttp's 10s default kills every held poll", + ) + assertTrue( + block.contains(".callTimeout(MAX_WAIT_SECONDS + 20L, TimeUnit.SECONDS)"), + "the call timeout has to clear the hold too", + ) + } + + /** + * Both bounds must exceed the longest hold the client will ask for, or the + * transport contradicts the protocol. + */ + @Test + fun `both timeouts clear the longest hold the client asks for`() { + assertTrue(relay.contains("const val MAX_WAIT_SECONDS = 20")) + assertTrue( + relay.contains("waitSeconds.coerceIn(0, MAX_WAIT_SECONDS)"), + "the hold is clamped to the same constant the timeouts are built from", + ) + } +}