Engineering

The test that only failed on wasm was measuring the environment

A single-threaded target surfaces every real-clock dependency a JVM run hides.

MobileByteSensei 10 min read
kmptestingwasm

TL;DR

  • A runTest suite with a 2% failure rate on wasmJsTest and zero on the JVM, for four months, retried away in CI by a --tests re-run.
  • Nothing in the test was wasm-specific. The failures were real-clock and real-dispatcher dependencies that a multi-core JVM run had enough slack to absorb.
  • Measured: 1,000 executions per target. The JVM failed 0 times; wasm failed 19. After the dependencies were injected, both were 0 of 1,000.
  • What reading on buys: the three dependency shapes that produce this, and why a wasm run is a better oracle for them than a JVM run with more assertions.

The case this post is about

A debounced search, and the test that had been flaky since the wasm target was added:

// core/search/src/commonMain/kotlin/SearchController.kt
class SearchController(private val repo: SearchRepo) {

    private val scope = CoroutineScope(SupervisorJob() + Dispatchers.Default)
    private val query = MutableStateFlow("")
    val results = MutableStateFlow<List<Hit>>(emptyList())

    init {
        scope.launch {
            query.debounce(300.milliseconds)
                 .filter { it.length >= 2 }
                 .collectLatest { results.value = repo.search(it) }
        }
    }

    fun onType(q: String) { query.value = q }
}
// core/search/src/commonTest/kotlin/SearchControllerTest.kt
@Test
fun debouncesRapidTyping() = runTest {
    val repo = FakeSearchRepo(hits = listOf(hit("kotlin")))
    val c = SearchController(repo)

    c.onType("k"); c.onType("ko"); c.onType("kot"); c.onType("kotl")

    advanceUntilIdle()
    assertEquals(1, repo.calls)
    assertEquals(listOf(hit("kotlin")), c.results.value)
}

The CI record for that one test, over four months:

jvmTest                 0 failures / 1,840 runs
desktopTest             0 failures / 1,840 runs
iosSimulatorArm64Test   2 failures / 1,840 runs
wasmJsTest             37 failures / 1,840 runs

Two percent on wasm. Rare enough that ./gradlew wasmJsTest --tests '*debounces*' almost always went green on the retry, which is exactly the rate at which a test survives for four months.

The symptom

The failure, when it did land, named a count rather than a timeout:

> Task :core:search:wasmJsTest FAILED

SearchControllerTest.debouncesRapidTyping FAILED
    AssertionError: expected:<1> but was:<0>
      at assertEquals (kotlin-test.mjs)
      at SearchControllerTest$debouncesRapidTyping (search-test.mjs:412)

Zero calls, not two. So the debounce had not fired at all by the time the assertion ran — which reads as "the test was too fast", and the obvious reading of that is a wasm scheduling quirk.

The second symptom was the one that should have been decisive and was not. Running the same test 1,000 times on wasm locally reproduced it at roughly the CI rate, and running it 1,000 times on the JVM did not reproduce it once. A per-target failure with a per-target reproduction rate is a very convincing argument for a per-target cause.

Four months of continuous-integration records for one test showing zero failures on the JVM and desktop, two on an iOS simulator and thirty-seven on wasm across eighteen hundred and forty runs each — a two percent rate, rare enough to survive four months of retries

Why the obvious fix failed

The first fix was to give the test more time:

advanceUntilIdle()
withContext(Dispatchers.Default) { delay(50) }     // "let wasm catch up"
assertEquals(1, repo.calls)

Failure rate on wasm: 2% → 0.4%. Which looked like progress and is the single most misleading result in this whole investigation. A fix that reduces a race's frequency without removing the race produces exactly that curve, and the 0.4% survived another six weeks before anyone looked again.

The second fix was runTest(timeout = 30.seconds). No effect, because the test was not timing out — it was asserting early and passing or failing on who won.

The third guess was the wasm dispatcher being single-threaded, and the proposed fix was to skip the test there:

@Test
@IgnoreWasm                 // ← this is where it nearly ended
fun debouncesRapidTyping() = runTest { … }

I wrote that annotation. What stopped me using it was a question I could not answer: if the behaviour is clean on two targets and intermittent on two others, which of them is telling the truth about the code? Ignoring the test assumes the clean pair are right. Nothing had established that.

The actual mechanism

runTest gives you a virtual clock, and the code under test was not on it. Three separate dependencies escaped the test scheduler, and each one is invisible on a JVM run:

Dispatchers.Default in the constructor. The controller creates its own scope on a real dispatcher. advanceUntilIdle() drains the test scheduler, and the collecting coroutine is not on it — so "idle" is a statement about tasks the scheduler knows about, and it knows about none of this.

debounce consults the dispatcher's time source, not the test clock. Because the flow runs on Dispatchers.Default, its 300ms is 300 real milliseconds. Nothing the test does advances it.

And collectLatest adds a cancellation race. Four rapid onType calls each cancel the previous collection. Whether the final one survives to call repo.search depends on real scheduling.

So the test was a race between real time and the assertion, and the two sides have different amounts of help per target:

JVM, 8 cores        the collector gets its own thread immediately; 300ms of real time
                    elapses while the test thread is parked; assertion runs after. Wins ~always.

wasm, 1 thread      the collector, the debounce timer and the test body all queue on one
                    event loop. Whether the timer callback runs before the assertion depends
                    on the order the microtask queue happens to drain. Wins ~98%.

Neither number is a property of the code. They are properties of how much slack each runtime gives a bug the test could not see.

The sub-case that reappears after the dispatcher is injected. Threading the test scheduler through fixes every operator that asks the dispatcher for the time. It does nothing for code that asks the system:

// still flaky after the injection, for a different reason
private val lastSync = MutableStateFlow(Clock.System.now())
fun isStale() = Clock.System.now() - lastSync.value > 5.minutes

Clock.System has no relationship to the test scheduler, so a test that advances virtual time by six minutes and then calls isStale() gets false — the virtual clock moved and the system clock did not. This one fails on every target rather than one, which is why it is easier to find, and it is the same class of defect: a dependency on a clock the test does not control. Injecting Clock alongside the dispatcher is the same fix twice.

And the shape where injection is not sufficient. A collectLatest whose body performs two suspending calls is cancellable between them, and no amount of clock control makes that deterministic:

.collectLatest {
    val hits = repo.search(it)       // suspension point 1
    analytics.track("searched")      // suspension point 2 — may never run
}

Advancing the virtual clock makes the cancellation point predictable in a single test, and the behaviour is still genuinely racy in production: a user typing fast will sometimes get the search without the analytics event. The test can pin one ordering; deciding whether that ordering is the correct one is a product question the scheduler cannot answer. We moved the tracking above the search, so the event fires for the attempt rather than for the completion, and wrote down why.

Which answers the question that stopped me from adding @IgnoreWasm: wasm was telling the truth. The code has a real dependency on wall-clock scheduling, and a production build on a slow device has less slack than a wasm test run, not more. The JVM's 0-of-1,840 was not evidence of correctness; it was evidence of a wide margin.

The same race measured against how much scheduling slack each runtime offers, with the original production code failing seventeen times in a thousand on the JVM once it is restricted to a single thread — so the eight-core margin was hiding the bug rather than proving its absence

The fix

Inject the dispatcher, so the controller's scope is on the test's scheduler and debounce consults the virtual clock.

// core/search/src/commonMain/kotlin/SearchController.kt
class SearchController(
    private val repo: SearchRepo,
    // The dispatcher is a CONSTRUCTOR PARAMETER, not a default inside the class. A default
    // of Dispatchers.Default here would make the test's override optional, and an optional
    // override is one somebody forgets in the next test.
    dispatcher: CoroutineDispatcher,
) {
    private val scope = CoroutineScope(SupervisorJob() + dispatcher)
    private val query = MutableStateFlow("")
    val results = MutableStateFlow<List<Hit>>(emptyList())

    init {
        scope.launch {
            query.debounce(DEBOUNCE)            // now consults whatever clock `dispatcher` has
                 .filter { it.length >= 2 }
                 .collectLatest { results.value = repo.search(it) }
        }
    }

    fun onType(q: String) { query.value = q }

    fun close() = scope.cancel()

    companion object { val DEBOUNCE = 300.milliseconds }
}

The test, with the scheduler threaded through and the waiting made explicit:

@Test
fun debouncesRapidTyping() = runTest {
    val repo = FakeSearchRepo(hits = listOf(hit("kotlin")))

    // StandardTestDispatcher(testScheduler) — passing THIS test's scheduler is the
    // load-bearing argument. A bare StandardTestDispatcher() builds its own scheduler,
    // which puts the work back outside the one advanceUntilIdle drains: the same bug,
    // wearing a test-dispatcher costume.
    val c = SearchController(repo, StandardTestDispatcher(testScheduler))

    c.onType("k"); c.onType("ko"); c.onType("kot"); c.onType("kotl")

    // Assert the debounce has NOT fired yet — the half that makes this a debounce test
    // rather than an eventually-consistent one.
    advanceTimeBy(SearchController.DEBOUNCE - 1.milliseconds)
    runCurrent()
    assertEquals(0, repo.calls, "search fired before the debounce window closed")

    advanceTimeBy(2.milliseconds)
    runCurrent()
    assertEquals(1, repo.calls)
    assertEquals(listOf(hit("kotlin")), c.results.value)

    c.close()
}

Two things changed beyond portability. The test now asserts the debounce window from both sides, which the original could not — advanceUntilIdle() jumps past the window, so a controller with no debounce at all would have passed it. And the virtual clock means the test takes microseconds instead of 300 real milliseconds per case.

And the output it produced, 1,000 executions per target:

$ ./gradlew :core:search:allTests -Prepeat=1000

                          before            after
jvmTest                   0 / 1000          0 / 1000
desktopTest               0 / 1000          0 / 1000
iosSimulatorArm64Test     3 / 1000          0 / 1000
wasmJsTest               19 / 1000          0 / 1000

wall clock (wasmJsTest)   312s              1.4s

How we proved it

That the race was real on every target and only visible on one. The decisive measurement is not the failure count — it is forcing the JVM to have as little slack as wasm, with the production code unchanged:

// jvmTest only, deliberately: one thread, to match wasm's shape
@Test fun debouncesRapidTyping_singleThreaded() =
    runTest { /* same body, Dispatchers.Default replaced by a 1-thread executor */ }
$ ./gradlew :core:search:jvmTest --tests '*singleThreaded*' -Prepeat=1000
17 / 1000 failed

Seventeen of a thousand, on the JVM, from the original production code. The bug was never wasm-specific; the JVM's eight cores were hiding it. That one run is what retired the @IgnoreWasm idea for good.

That the first "fix" reduced the rate without removing the race, which is the result most likely to end an investigation early:

                        wasm failures / 1000
original                       19
+ a 50ms real delay             4        ← looked like progress
+ injected dispatcher           0

That the rewritten test fails when the debounce is removed — because a test that only asserts the eventual call would not:

# debounce(DEBOUNCE) deleted from the production code
$ ./gradlew :core:search:allTests
FAILED: search fired before the debounce window closed
  expected:<0> but was:<1>          × 4 targets

The original test passes that mutation on all five, which is worth sitting with: it had been flaky and unable to detect the absence of the feature it was named after.

What I cannot tell you is a general rate. This is one test in one module, and the three dependency shapes it had — a self-created scope, a real-clock operator, and a cancellation race — are the three I now look for, not an exhaustive list. A module whose flakiness comes from a filesystem or a network fake would not be found by this at all.

A thousand executions per target before and after injecting the dispatcher, with every target reaching zero failures and the wasm suite's wall clock falling from three hundred and twelve seconds to one point four

What this generalizes to

A flaky test on one target is usually not a fact about that target. It is a dependency the code genuinely has, surfaced by the runtime with the least slack — and the runtime with the least slack is the better oracle, however inconvenient. The practical version is to resist the two moves that make the signal go away: raising a timeout, which changes the rate and not the race, and ignoring the test on the target that disagrees, which assumes the majority is right about the code when what the majority has is a wider margin. Ask instead what the failing target had less of, and whether production has less of it too.


Keep reading

One post a week on shipping mobile software. No digests, no course pitch. Subscribe.

One post a week, no digest

New writing when it lands. No roundups, no course pitch, no "10 tips".

Follow by RSS