fix(fallback): say whether the primary stalled or failed

Sources/DoNotTypeCore/FallbackTranscriber.swift

@@ -30,7 +30,7 @@ public struct FallbackTranscriber: Sendable {
     public struct Attribution: Sendable, Equatable {
         public var provider: String
         public var model: String
-        /// True when the primary stalled and the secondary answered first.
+        /// True when the primary stalled or failed and the secondary answered first.
         public var wasFallback: Bool
 
         public init(provider: String, model: String, wasFallback: Bool) {
@@ -117,17 +117,32 @@ public struct FallbackTranscriber: Sendable {
                 // The hedge. Sleeping inside the group rather than scheduling separately means
                 // cancellation of the winner's siblings also cancels a hedge that never fired,
                 // so a fast primary costs nothing at all — not even a pending timer.
-                await Self.waitToHedge(for: hedgeAfter, orUntil: primaryFailed)
+                let trigger = await Self.waitToHedge(for: hedgeAfter, orUntil: primaryFailed)
                 try Task.checkCancellation()
                 // Logged at info: this is the app spending a second request on the user's behalf,
                 // and a fallback that fires on every dictation is a misconfigured `hedgeAfter`
                 // rather than a working feature. It should be visible without turning anything on.
-                Self.log.info(
-                    "primary stalled; starting the fallback",
-                    [
-                        "primary": primary.provider.name, "fallback": secondary.provider.name,
-                        "after": "\(hedgeAfter)",
-                    ])
+                //
+                // Which of the two started it is the difference between "the primary is slow" and
+                // "the primary is broken", and those want opposite responses from whoever reads
+                // the log. Only the stall waited, so only the stall reports a delay.
+                switch trigger {
+                case .delayElapsed:
+                    Self.log.info(
+                        "primary stalled; starting the fallback",
+                        [
+                            "primary": primary.provider.name,
+                            "fallback": secondary.provider.name,
+                            "afterMs": String(Self.milliseconds(hedgeAfter)),
+                        ])
+                case .primaryFailed:
+                    Self.log.info(
+                        "primary failed; starting the fallback",
+                        [
+                            "primary": primary.provider.name,
+                            "fallback": secondary.provider.name,
+                        ])
+                }
                 return Outcome(
                     result: try await secondary.transcribeLong(
                         audio: audio, context: context, styled: styled,
@@ -166,6 +181,12 @@ public struct FallbackTranscriber: Sendable {
         }
     }
 
+    /// What stopped the hedge waiting, which is what the log line reports.
+    private enum HedgeTrigger {
+        case delayElapsed
+        case primaryFailed
+    }
+
     /// Waits out the hedge delay, or gives up on it the moment the primary fails.
     ///
     /// Racing the two legs inside a child group is what keeps both cancellable: `Task.sleep`
@@ -174,18 +195,30 @@ public struct FallbackTranscriber: Sendable {
     /// on the common path, where the primary answers and no failure is ever reported.
     private static func waitToHedge(
         for delay: Duration, orUntil primaryFailed: AsyncStream<Void>
-    ) async {
-        await withTaskGroup(of: Void.self) { group in
-            group.addTask { try? await Task.sleep(for: delay) }
+    ) async -> HedgeTrigger {
+        await withTaskGroup(of: HedgeTrigger.self) { group in
+            group.addTask {
+                try? await Task.sleep(for: delay)
+                return .delayElapsed
+            }
             group.addTask {
                 var failures = primaryFailed.makeAsyncIterator()
                 _ = await failures.next()
+                return .primaryFailed
             }
-            _ = await group.next()
+            let trigger = await group.next() ?? .delayElapsed
             group.cancelAll()
+            return trigger
         }
     }
 
+    /// Whole milliseconds, so the delay reads as the same number the other ports log rather than
+    /// as a `Duration` description no other platform produces.
+    private static func milliseconds(_ duration: Duration) -> Int64 {
+        let parts = duration.components
+        return parts.seconds * 1000 + parts.attoseconds / 1_000_000_000_000_000
+    }
+
     private func attribution(
         _ service: TranscriptionService, wasFallback: Bool
     ) -> Attribution {

Tests/DoNotTypeCoreTests/FallbackTranscriberTests.swift

@@ -21,6 +21,31 @@ private struct SlowProvider: TranscriptionProvider {
 
 final class FallbackTranscriberTests: XCTestCase {
     private let audio = AudioFile(data: Data("wav".utf8), mimeType: "audio/wav")
+    private var sink: MemoryLogSink!
+
+    /// The two spellings the hedge can log, repeated verbatim in each platform's test suite
+    /// rather than shared from one file, per `docs/PARITY.md`.
+    private enum HedgeLog {
+        static let stalled = "primary stalled; starting the fallback"
+        static let failed = "primary failed; starting the fallback"
+    }
+
+    override func setUp() {
+        super.setUp()
+        sink = MemoryLogSink()
+        LogRouter.shared.install(sinks: [sink], level: .trace)
+        LogRouter.shared.clearBuffer()
+    }
+
+    override func tearDown() {
+        LogRouter.shared.install(sinks: [], level: .off)
+        super.tearDown()
+    }
+
+    /// The line that announced the handover, which is the first thing the category logs.
+    private var handoverLine: LogEvent? {
+        sink.events.first { $0.category == "fallback" }
+    }
 
     private func service(
         _ name: String, delay: Duration, text: String, failure: (any Error)? = nil
@@ -112,6 +137,42 @@ final class FallbackTranscriberTests: XCTestCase {
         }
     }
 
+    /// A stall and a failure are different problems, so the log has to name which one happened.
+    ///
+    /// "The primary is slow" and "the primary is broken" want opposite responses from whoever
+    /// reads the log, and for as long as both said "stalled" the log pointed at the wrong one.
+    func testAStalledPrimaryIsLoggedAsAStall() async throws {
+        let hedger = FallbackTranscriber(
+            primary: service("primary", delay: .seconds(30), text: "primary"),
+            secondary: service("secondary", delay: .milliseconds(10), text: "secondary"),
+            hedgeAfter: .milliseconds(20))
+
+        _ = try await hedger.transcribe(audio: audio, context: nil)
+
+        XCTAssertEqual(handoverLine?.message, HedgeLog.stalled)
+        XCTAssertEqual(handoverLine?.fields["primary"], "primary")
+        XCTAssertEqual(handoverLine?.fields["fallback"], "secondary")
+        XCTAssertEqual(handoverLine?.fields["afterMs"], "20")
+    }
+
+    /// The delay is deliberately absent: nothing waited it out, so reporting it would describe a
+    /// wait that never happened. That is exactly what the old single message did.
+    func testAFailedPrimaryIsLoggedAsAFailureAndReportsNoDelay() async throws {
+        let hedger = FallbackTranscriber(
+            primary: service(
+                "primary", delay: .milliseconds(5), text: "",
+                failure: ProviderError.http(status: 400, body: "location not supported")),
+            secondary: service("secondary", delay: .milliseconds(10), text: "secondary"),
+            hedgeAfter: .seconds(8))
+
+        _ = try await hedger.transcribe(audio: audio, context: nil)
+
+        XCTAssertEqual(handoverLine?.message, HedgeLog.failed)
+        XCTAssertEqual(handoverLine?.fields["primary"], "primary")
+        XCTAssertEqual(handoverLine?.fields["fallback"], "secondary")
+        XCTAssertNil(handoverLine?.fields["afterMs"], "nothing waited, so there is no delay")
+    }
+
     /// No secondary configured is the default, and must behave exactly as before this type existed.
     func testWithoutASecondaryItIsATransparentPassThrough() async throws {
         let hedger = FallbackTranscriber(

android/app/src/main/kotlin/app/donottype/core/FallbackTranscriber.kt

@@ -78,18 +78,28 @@ class FallbackTranscriber(
         }
         val second = async {
             // Wait out the hedge delay, but cut it short if the primary has already failed —
-            // there is then nothing left to wait for.
-            withTimeoutOrNull(hedgeAfterMillis) { primaryError.await() }
+            // there is then nothing left to wait for. Null means the delay won.
+            val failure = withTimeoutOrNull(hedgeAfterMillis) { primaryError.await() }
             // Logged at info: this is the app spending a second request on the user's behalf, and
             // a fallback that fires on every dictation is a misconfigured delay rather than a
             // working feature. It should be visible without turning anything on.
-            log.info(
-                mapOf(
-                    "primary" to primaryName,
-                    "fallback" to secondaryName,
-                    "afterMs" to hedgeAfterMillis.toString(),
-                ),
-            ) { "primary stalled; starting the fallback" }
+            //
+            // Which of the two started it is the difference between "the primary is slow" and
+            // "the primary is broken", and those want opposite responses from whoever reads the
+            // log. Only the stall waited, so only the stall reports a delay.
+            if (failure == null) {
+                log.info(
+                    mapOf(
+                        "primary" to primaryName,
+                        "fallback" to secondaryName,
+                        "afterMs" to hedgeAfterMillis.toString(),
+                    ),
+                ) { "primary stalled; starting the fallback" }
+            } else {
+                log.info(
+                    mapOf("primary" to primaryName, "fallback" to secondaryName),
+                ) { "primary failed; starting the fallback" }
+            }
             try {
                 Outcome(fallback.transcribe(), Attribution(secondaryName, secondaryModel, true))
             } catch (cancellation: CancellationException) {

android/app/src/test/kotlin/app/donottype/core/FallbackTranscriberTest.kt

@@ -2,9 +2,12 @@ package app.donottype.core
 
 import kotlinx.coroutines.delay
 import kotlinx.coroutines.runBlocking
+import org.junit.After
 import org.junit.Assert.assertEquals
 import org.junit.Assert.assertFalse
+import org.junit.Assert.assertNull
 import org.junit.Assert.assertTrue
+import org.junit.Before
 import org.junit.Test
 import kotlin.system.measureTimeMillis
 
@@ -21,6 +24,32 @@ import kotlin.system.measureTimeMillis
  */
 class FallbackTranscriberTest {
 
+    private companion object {
+        /**
+         * The two spellings the hedge can log, repeated verbatim in each platform's test suite
+         * rather than shared from one file, per `docs/PARITY.md`.
+         */
+        const val STALLED_MESSAGE = "primary stalled; starting the fallback"
+        const val FAILED_MESSAGE = "primary failed; starting the fallback"
+    }
+
+    private lateinit var sink: MemoryLogSink
+
+    @Before
+    fun setUp() {
+        sink = MemoryLogSink()
+        LogRouter.install(listOf(sink), LogLevel.TRACE)
+    }
+
+    @After
+    fun tearDown() {
+        LogRouter.install(emptyList(), LogLevel.OFF)
+    }
+
+    /** The line that announced the handover, the first thing the category logs. */
+    private val handoverLine: LogEvent?
+        get() = sink.events.firstOrNull { it.category == "fallback" }
+
     private fun backend(delayMillis: Long, text: String, failure: Throwable? = null) =
         FallbackTranscriber.Transcriber {
             delay(delayMillis)
@@ -42,6 +71,44 @@ class FallbackTranscriberTest {
         assertEquals("primary", outcome.attribution.provider)
     }
 
+    /**
+     * A stall and a failure are different problems, so the log has to name which one happened.
+     *
+     * "The primary is slow" and "the primary is broken" want opposite responses from whoever
+     * reads the log, and for as long as both said "stalled" the log pointed at the wrong one.
+     */
+    @Test
+    fun `a stalled primary is logged as a stall`() = runBlocking {
+        FallbackTranscriber(
+            primary = backend(30_000, "primary"),
+            secondary = backend(10, "secondary"),
+            hedgeAfterMillis = 20,
+        ).transcribe("primary", "p-model", "secondary", "s-model")
+
+        assertEquals(STALLED_MESSAGE, handoverLine?.message)
+        assertEquals("primary", handoverLine?.fields?.get("primary"))
+        assertEquals("secondary", handoverLine?.fields?.get("fallback"))
+        assertEquals("20", handoverLine?.fields?.get("afterMs"))
+    }
+
+    /**
+     * The delay is deliberately absent: nothing waited it out, so reporting it would describe a
+     * wait that never happened.
+     */
+    @Test
+    fun `a failed primary is logged as a failure and reports no delay`() = runBlocking {
+        FallbackTranscriber(
+            primary = backend(5, "", ProviderException("boom")),
+            secondary = backend(10, "secondary"),
+            hedgeAfterMillis = 8_000,
+        ).transcribe("primary", "p-model", "secondary", "s-model")
+
+        assertEquals(FAILED_MESSAGE, handoverLine?.message)
+        assertEquals("primary", handoverLine?.fields?.get("primary"))
+        assertEquals("secondary", handoverLine?.fields?.get("fallback"))
+        assertNull("nothing waited, so there is no delay", handoverLine?.fields?.get("afterMs"))
+    }
+
     /** The case this exists for: the primary stalls, the hedge fires, the user gets words. */
     @Test
     fun `a stalled primary is overtaken by the hedge`() = runBlocking {

docs/PARITY.md

@@ -208,7 +208,8 @@ dictate into, so the fallback has not been needed; it is a gap rather than an im
 | Verbatim, rewrite, summary modes | ✅ | ✅ | ✅ | ✅ |
 | Split long recordings on silence | ✅ | ✅ | ✅ | ✅ |
 | Re-send a stalled request to the same backend | ✅ | ✅ | ✅ | ✅ |
-| Fallback backend when the primary stalls | ✅ | ✅ | ✅ | ✅ |
+| Fallback backend when the primary stalls or fails | ✅ | ✅ | ✅ | ✅ |
+| [Names which of the two started it](#fallback-log-messages) in the log | ✅ | ✅ | ✅ | ✅ |
 | Compress the upload with Opus | ✅ | ✅ | ✅ | ✅ |
 
 ## Other capabilities
@@ -431,14 +432,37 @@ Historical divergence: `rewrite:` and `summary:` used to differ — macOS took t
 rejected it, Android rejected it. No dependent behavior exposed the difference, so it was not
 detected until the parsers were compared directly.
 
+## Fallback log messages
+
+What the hedge logs when it starts the second backend, identically on all three clients that have
+one. Both spellings are repeated verbatim in each platform's test suite.
+
+| Message | Logged when | Fields |
+|---|---|---|
+| `primary stalled; starting the fallback` | the hedge delay elapsed with the primary still running | `primary`, `fallback`, `afterMs` |
+| `primary failed; starting the fallback` | the primary threw, cutting the delay short | `primary`, `fallback` |
+
+Only the stall waited, so only the stall reports a delay. Reporting `afterMs=8000` on a handover
+that happened at 1.7 s describes a wait that never took place.
+
+The distinction is the point: "the primary is slow" and "the primary is broken" want opposite
+responses from whoever reads the log. One message covering both sent readers looking for a slow
+backend when the real cause was a geoblocked one that had been failing in about a second.
+
+Historical divergence, all three different: Windows logged nothing at all — the hedge fired
+silently there, on the one platform whose users cannot fall back to reading a macOS log. macOS and
+Android both called a hard failure a stall. macOS spelled the delay field `after` and formatted it
+as a `Duration` description (`8.0 seconds`) where Android already used `afterMs`.
+
 ## Drift prevention
 
 Ports are by hand, so these tables drift unless they are checked. Three of the mechanisms that
 stop it:
 
 - **Parity tests.** The [mode grammar table](#mode-spellings) is repeated verbatim in each
-  language's test suite, and so are the numeric guard's cases. A shared fixture file would be read
-  by whichever platform remembered to read it.
+  language's test suite, and so are the numeric guard's cases and the
+  [fallback log messages](#fallback-log-messages). A shared fixture file would be read by
+  whichever platform remembered to read it.
 - **Text checked by diffing, not by reading.** For `FailureAdvice`, every case was printed through
   all three implementations and diffed. Reading code side by side finds structural differences and
   misses a word.

windows/DoNotType.Core.Tests/AssemblyInfo.cs

@@ -0,0 +1,17 @@
+using Xunit;
+
+// The log router is process-global: installing a MemoryLogSink captures every entry the whole
+// process emits, not only the ones the installing test provoked. xUnit runs test classes in
+// parallel by default, so a class asserting on what it logged can read an entry produced by a
+// class running beside it.
+//
+// That is not hypothetical. FallbackTranscriberTests picked up the handover line from
+// DictationJourneyTests, which hedges with the same 20 ms delay and names its second backend
+// "fallback", and failed on roughly one full run in five while passing every time its own class
+// was run alone. A test that only fails in company is worse than one that always fails, because
+// the usual response is to run it again.
+//
+// Serialising the assembly costs about two seconds — 631 tests go from ~1 s to ~3 s — and buys
+// determinism outright: eight consecutive full runs green, against one failure in five before.
+// The alternative is remembering forever which classes may log while another class is watching.
+[assembly: CollectionBehavior(DisableTestParallelization = true)]