diff --git a/Sources/DoNotTypeCore/FallbackTranscriber.swift b/Sources/DoNotTypeCore/FallbackTranscriber.swift index 8d1e719..443aed0 100644 --- a/Sources/DoNotTypeCore/FallbackTranscriber.swift +++ b/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 - ) 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 { diff --git a/Tests/DoNotTypeCoreTests/FallbackTranscriberTests.swift b/Tests/DoNotTypeCoreTests/FallbackTranscriberTests.swift index e1f309b..31f925d 100644 --- a/Tests/DoNotTypeCoreTests/FallbackTranscriberTests.swift +++ b/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( diff --git a/android/app/src/main/kotlin/app/donottype/core/FallbackTranscriber.kt b/android/app/src/main/kotlin/app/donottype/core/FallbackTranscriber.kt index 75286c8..19b4f85 100644 --- a/android/app/src/main/kotlin/app/donottype/core/FallbackTranscriber.kt +++ b/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) { diff --git a/android/app/src/test/kotlin/app/donottype/core/FallbackTranscriberTest.kt b/android/app/src/test/kotlin/app/donottype/core/FallbackTranscriberTest.kt index 67adbb8..2b30500 100644 --- a/android/app/src/test/kotlin/app/donottype/core/FallbackTranscriberTest.kt +++ b/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 { diff --git a/docs/PARITY.md b/docs/PARITY.md index e1437f1..633211d 100644 --- a/docs/PARITY.md +++ b/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. diff --git a/windows/DoNotType.Core.Tests/AssemblyInfo.cs b/windows/DoNotType.Core.Tests/AssemblyInfo.cs new file mode 100644 index 0000000..251086d --- /dev/null +++ b/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)] diff --git a/windows/DoNotType.Core.Tests/FallbackTranscriberTests.cs b/windows/DoNotType.Core.Tests/FallbackTranscriberTests.cs index 9f90141..ee3ffc1 100644 --- a/windows/DoNotType.Core.Tests/FallbackTranscriberTests.cs +++ b/windows/DoNotType.Core.Tests/FallbackTranscriberTests.cs @@ -9,8 +9,25 @@ namespace DoNotType.Core.Tests; /// that fires at a different moment on one platform means that app has a different latency profile /// from the one the evaluation describes. /// -public class FallbackTranscriberTests +public class FallbackTranscriberTests : IDisposable { + /// + /// 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 const string StalledMessage = "primary stalled; starting the fallback"; + + private const string FailedMessage = "primary failed; starting the fallback"; + + private readonly MemoryLogSink _sink = new(); + + public FallbackTranscriberTests() => LogRouter.Install([_sink], LogLevel.Trace); + + public void Dispose() => LogRouter.Install([], LogLevel.Off); + + /// The line that announced the handover, the first thing the category logs. + private LogEvent? HandoverLine => _sink.Events.FirstOrDefault(e => e.Category == "fallback"); + private static Func> Backend( int delayMs, string text, Exception? failure = null) => async token => @@ -34,6 +51,45 @@ public async Task AFastPrimaryIsNeverSecondGuessed() Assert.Equal("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. This port logged neither until now — the hedge fired silently on + /// Windows, so the one platform whose users cannot read a macOS log got no line at all. + /// + [Fact] + public async Task AStalledPrimaryIsLoggedAsAStall() + { + await new FallbackTranscriber( + Backend(30_000, "primary"), "primary", "p-model", + Backend(10, "secondary"), "secondary", "s-model", + TimeSpan.FromMilliseconds(20)).TranscribeAsync(); + + Assert.Equal(StalledMessage, HandoverLine?.Message); + Assert.Equal("primary", HandoverLine?.Fields["primary"]); + Assert.Equal("secondary", HandoverLine?.Fields["fallback"]); + Assert.Equal("20", HandoverLine?.Fields["afterMs"]); + } + + /// + /// The delay is deliberately absent: nothing waited it out, so reporting it would describe a + /// wait that never happened. + /// + [Fact] + public async Task AFailedPrimaryIsLoggedAsAFailureAndReportsNoDelay() + { + await new FallbackTranscriber( + Backend(5, "", new ProviderException("boom")), "primary", "p-model", + Backend(10, "secondary"), "secondary", "s-model", + TimeSpan.FromSeconds(8)).TranscribeAsync(); + + Assert.Equal(FailedMessage, HandoverLine?.Message); + Assert.Equal("primary", HandoverLine?.Fields["primary"]); + Assert.Equal("secondary", HandoverLine?.Fields["fallback"]); + Assert.False(HandoverLine?.Fields.ContainsKey("afterMs")); + } + /// The case this exists for: the primary stalls, the hedge fires. [Fact] public async Task AStalledPrimaryIsOvertakenByTheHedge() diff --git a/windows/DoNotType.Core/FallbackTranscriber.cs b/windows/DoNotType.Core/FallbackTranscriber.cs index f517e1f..31c3c35 100644 --- a/windows/DoNotType.Core/FallbackTranscriber.cs +++ b/windows/DoNotType.Core/FallbackTranscriber.cs @@ -28,7 +28,9 @@ public sealed class FallbackTranscriber( { private readonly TimeSpan _hedgeAfter = hedgeAfter ?? TimeSpan.FromSeconds(8); - /// True when the primary stalled and the secondary answered first. + private static readonly Log Log = new("fallback"); + + /// True when the primary stalled or failed and the secondary answered first. public readonly record struct Attribution(string Provider, string Model, bool WasFallback); public readonly record struct Outcome(TranscriptionResult Result, Attribution Attribution); @@ -102,19 +104,47 @@ await primary(cancellationToken).ConfigureAwait(false), TaskCompletionSource primaryFailed, CancellationToken cancellationToken) { + bool primaryHadFailed; try { // Wait out the hedge delay, but cut it short if the primary has already failed — // there is then nothing left to wait for. var delay = Task.Delay(_hedgeAfter, cancellationToken); - await Task.WhenAny(delay, primaryFailed.Task).ConfigureAwait(false); + var first = await Task.WhenAny(delay, primaryFailed.Task).ConfigureAwait(false); cancellationToken.ThrowIfCancellationRequested(); + primaryHadFailed = first == primaryFailed.Task; } catch (OperationCanceledException) { return null; } + // 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. + // + // 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 (primaryHadFailed) + { + Log.Info(() => "primary failed; starting the fallback", new Dictionary + { + ["primary"] = primaryName, + ["fallback"] = secondaryName, + }); + } + else + { + Log.Info(() => "primary stalled; starting the fallback", new Dictionary + { + ["primary"] = primaryName, + ["fallback"] = secondaryName, + ["afterMs"] = ((long)_hedgeAfter.TotalMilliseconds).ToString( + System.Globalization.CultureInfo.InvariantCulture), + }); + } + return await RunAsync(secondary!, attribution, new TaskCompletionSource(), cancellationToken).ConfigureAwait(false); }