Every held poll on Android was failing at ten seconds

`heldHttp` raised `callTimeout` to the hold plus twenty and left `readTimeout`
at OkHttp's default of TEN SECONDS. A held poll asks the relay to say nothing
for up to twenty. So every one died at ten with a SocketTimeoutException, and
the generous call timeout above it never got the chance to matter.

Nothing said so. The failure was swallowed into a retry, the loop looked busy,
and the only trace was a number on the relay: this device took an average of
112 seconds to collect what was waiting for it, against 5 for an iPhone. A
message written into a connection this end had already abandoned waited for
the next poll instead of arriving.

That is why calling an iPhone took forever, why "connecting..." never
resolved, and why the call then ended: the answer was on the relay the whole
time and the dial guard gave up at forty-five seconds waiting for a fetch that
could not succeed.

Measured on the device, before and after, once the loop was made to say what
it was doing:

    vm cycle 10125ms held=20s call=false failed=SocketTimeoutException
    vm cycle 20304ms held=20s call=false got=0

TWO POLLS, AND I FIXED THE ONE THAT WAS SWITCHED OFF

`MessengerService` and the view model both poll, and the activity stops the
service on the way in -- "exactly one poller at a time". Placing a call is
exactly when the app is on screen, so the service is stopped and the view
model is the poller. The twenty-second hold during a call was fixed in the
service first. The loop that was running kept it.

Both ask for no hold during a call now.

AND THE LOOP CAN SAY WHAT IT COST

One line per cycle: how long it took, how long it was allowed to hold, whether
a call was up, and what came back or what failed. Two rounds were spent
reading an empty trace as "the loop is not running" when it was "the loop has
no voice", and the bug above was invisible for as long as it was because a
failing poll and a quiet one look identical from outside the process.

1619 tests.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

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
+        // The NAME is what the website and the app show a person, and it now
-        versionName = "0.19"
+        // 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"
     }
 

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 =
+            val outcome = runCatching { s.receive(if (onACall) 0 else WAIT_SECONDS) }
-                runCatching { s.receive(if (onACall) 0 else WAIT_SECONDS) }
+            val touched = outcome.getOrDefault(emptySet())
-                    .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

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.

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())"))
+    }
+}

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()
     }
 

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",
+        )
+    }
+}