diff --git a/CLAUDE.md b/CLAUDE.md index ce5cf09..c8282ab 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -246,3 +246,12 @@ Because versions float, a build can change without a commit. `./gradlew :app:dep `@OptIn`. Android lint's `UnsafeOptInUsageError` catches a missed one. - **Release builds ship both ABIs.** `-PabiFilters` is a test-run override only; `build.yml` verifies the released APK carries every ABI and that all native libraries are 16 KB aligned. +- **A JUnit `Timeout` — rule or `@Test(timeout=)` — cannot be used in the JVM suite.** Both run the + test body on a separate thread, and every Compose test here goes through Robolectric's paused + main looper: `UnsupportedOperationException: main looper can only be controlled from main + thread`, from `ShadowPausedLooper` under `RobolectricIdlingStrategy.runUntilIdle`. The identical + tests pass with the timeout removed, so it is the mechanism, not the test. What bounds a hung + run instead is `timeout` on the `Test` tasks plus the jstack watchdog beside it in + `app/build.gradle.kts`, neither of which moves a thread. `HangBoundTest` guards both numbers, + and **a timed-out run writes no XML for the class that hung** — the dump is its only + attribution, so do not delete the watchdog as stray config. diff --git a/app/build.gradle.kts b/app/build.gradle.kts index e7f7716..1405c7e 100644 --- a/app/build.gradle.kts +++ b/app/build.gradle.kts @@ -1,5 +1,7 @@ import org.gradle.api.tasks.PathSensitivity import org.gradle.testing.jacoco.tasks.JacocoReport +import java.io.File +import java.time.Duration plugins { // Applied by id: these two come from the root buildscript classpath, which is what @@ -217,6 +219,115 @@ tasks.withType().configureEach { .withPropertyName("releaseWorkflow") .withPathSensitivity(PathSensitivity.RELATIVE) + // Same reasoning, same trap: HangBoundTest reads the two numbers below out of this file, and + // they are the one part of the change that does not compile. Without this the task stays + // UP-TO-DATE when the build script changes, so the guard would go stale on exactly the edit + // it exists to catch. + inputs.file(project.file("build.gradle.kts")) + .withPropertyName("moduleBuildScript") + .withPathSensitivity(PathSensitivity.RELATIVE) + + // --- Bounding a hung run (#125) ----------------------------------------------------------- + // + // This suite had no timeout of any kind, so a hang ran until something outside it gave up. + // #125 is a real Java-level deadlock -- a lock-order inversion between Room's + // TransactionExecutor and WorkManager's SerialExecutorImpl, reached through the WorkInfo flow + // -- and one local run sat in it for 47 minutes. On CI it would burn the Unit tests job's + // 30-minute cap and report as a job timeout with no cause at all. + // + // WHY NOT A JUnit `Timeout` RULE, which is the obvious answer: it runs the test body on a + // separate thread, and this suite is thread-affine. Measured here, `@Rule Timeout` and + // `@Test(timeout = ...)` against a `createComposeRule()` Robolectric test both give: + // + // java.lang.UnsupportedOperationException: main looper can only be controlled from main + // at org.robolectric.shadows.ShadowPausedLooper.executeOnLooper + // at androidx.compose.ui.test.RobolectricIdlingStrategy.runUntilIdle + // + // The same two tests with the timeout removed pass, so that is the mechanism and not the + // probe. Nothing that moves a test off its own thread can be used here. + // + // `Task.timeout` moves nothing -- it stops the forked test JVM from outside. Its weakness is + // that it kills without a thread dump, and the jstack is the only reason #125 could be named + // at all; the watchdog below is what answers that, and it only dumps. + // + // THE NUMBER, against the slowest observed *pass* rather than the typical one. Eight CI runs + // sampled 2026-08-26, whole `./gradlew :app:testDebugUnitTest` invocation with compilation in + // it and this task a subset: 62, 76, 77, 79, 81, 84, 86 and 90 seconds. Locally the task + // itself is ~11 s over 454 tests. Ten minutes is ~6.7x the slowest of those and a third of + // the job's 30-minute cap, so a fired timeout still has room to be reported and uploaded. It + // is deliberately nowhere near the observed duration: a timeout that fires on a healthy slow + // runner turns a real signal into noise and teaches people to re-run reflexively. + timeout.set(Duration.ofMinutes(10)) + + // The dump, two minutes before the kill. jstack is what turned #125 from "CI timed out" into + // a named lock-order inversion, and `Task.timeout` on its own would have thrown it away. + // + // It is deliberately incapable of failing a build: it reads a live process and writes a file. + // Nothing here kills, interrupts or signals anything, so the worst a misfire can do is leave a + // stack trace nobody needed. It has one, and it is the ordinary CI shape rather than an exotic + // case: the worker is found by scanning this daemon's descendants for GradleWorkerMain, which + // cannot tell one invocation's worker from the next, and the Unit tests job runs + // testDebugUnitTest and jacocoTestReport back to back against the same daemon. If this task's + // own worker lived and died inside a single poll, the watchdog can adopt the following one. + // + // Everything it needs is read here, at configuration time, and captured by value. Reaching + // back through the task or the project from inside the action would not survive the + // configuration cache, which `gradle.properties` turns on for every build. + val threadDump = layout.buildDirectory.file("reports/hang/$name-threads.txt").get().asFile + val taskPath = path + val dumpAfterNanos = Duration.ofMinutes(8).toNanos() + val captureWindowNanos = Duration.ofMinutes(1).toNanos() + val pollMillis = 1_000L + doFirst { + val watchdog = Thread { + val startedAt = System.nanoTime() + var worker: ProcessHandle? = null + while (true) { + Thread.sleep(pollMillis) + val elapsed = System.nanoTime() - startedAt + val watched = worker + if (watched == null) { + // Gradle forks the worker moments after this task starts. If none has shown + // up by the end of the capture window there is nothing to watch, and going on + // polling would only risk adopting some other build's. + if (elapsed > captureWindowNanos) return@Thread + worker = ProcessHandle.current().descendants() + .filter { it.info().commandLine().orElse("").contains("GradleWorkerMain") } + .findFirst().orElse(null) + } else if (!watched.isAlive) { + return@Thread // the run finished; this is the healthy exit + } else if (elapsed >= dumpAfterNanos) { + val jstack = File(File(System.getProperty("java.home"), "bin"), "jstack") + threadDump.parentFile.mkdirs() + if (jstack.canExecute()) { + ProcessBuilder(jstack.absolutePath, "-l", watched.pid().toString()) + .redirectErrorStream(true) + .redirectOutput(threadDump) + .start() + .waitFor() + } else { + threadDump.writeText("no jstack at ${jstack.absolutePath}\n") + } + // To stdout as well as to the file, and that is the half that matters on CI: + // the Unit tests job uploads app/build/reports/tests/ and nothing else, so a + // dump that only ever existed under reports/hang/ would be unreachable from a + // red run -- which is the "timed out with no cause" this exists to end. The + // step log always survives, and needs no workflow edit to say so. + println( + "$taskPath is still running after ${Duration.ofNanos(elapsed).toMinutes()} " + + "minutes and is about to be timed out. Thread dump of pid " + + "${watched.pid()}, also written to $threadDump -- look for 'Found one " + + "Java-level deadlock' (that is #125).\n" + threadDump.readText(), + ) + return@Thread + } + } + } + watchdog.isDaemon = true + watchdog.name = "hang-watchdog" + watchdog.start() + } + extensions.configure { isIncludeNoLocationClasses = true excludes = listOf("jdk.internal.*") diff --git a/app/src/test/java/org/libremediaconverter/ci/HangBoundTest.kt b/app/src/test/java/org/libremediaconverter/ci/HangBoundTest.kt new file mode 100644 index 0000000..9b7c7b7 --- /dev/null +++ b/app/src/test/java/org/libremediaconverter/ci/HangBoundTest.kt @@ -0,0 +1,98 @@ +package org.libremediaconverter.ci + +import org.junit.Assert.assertTrue +import org.junit.Test +import java.io.File + +/** + * That a hung unit-test run still ends by itself, and still says why. + * + * `:app:testDebugUnitTest` had no timeout of any kind until #125 was filed. That ticket is a real + * Java-level deadlock between Room's `TransactionExecutor` and WorkManager's `SerialExecutorImpl`, + * reached through the WorkInfo flow the ViewModel collects, and one local run sat in it for 47 + * minutes. Nothing inside the suite could break it: the deadlock is monitor contention, which is + * not interruptible, so it runs until something outside the JVM gives up. + * + * Two numbers in `app/build.gradle.kts` are what bound it now, and neither compiles, so nothing + * else would notice their removal: + * + * - `timeout.set(...)` on every `Test` task, which stops the forked test JVM. + * - the watchdog's `dumpAfterNanos`, which jstacks that JVM *before* the timeout kills it. + * + * The second is the one worth guarding hardest, and the one that most looks like stray config. + * Gradle's timeout kills without a thread dump, and the jstack -- with its "Found one Java-level + * deadlock" section naming both monitors -- is the only reason #125 could be described at all. + * The ordering between the two numbers is what makes it work: dump first, kill second. Reverse + * them, or delete the watchdog, and the suite still stops hanging but every hang from then on + * reports as a bare "Timeout has been exceeded" with nothing to read. Measured against a probe + * that hung one test: no test XML was written for the class that hung, so the hanging test itself + * gets no attribution from the report at all. + * + * The range on the timeout is not decoration either, and it is the half a future edit is most + * likely to get wrong. Below it, a healthy-but-slow runner trips the bound and a real signal + * becomes noise people learn to re-run through; above it, CI's 30-minute job cap fires first and + * the bound never gets to say anything. + * + * `ReleasePermissionTest` is the precedent and its caveat applies here too. This asserts the two + * numbers are present, sanely sized and correctly ordered. It cannot assert that the timeout + * fires -- that needs a hang, which is what the whole change exists to prevent. Refs #125. + */ +class HangBoundTest { + + @Test + fun `every Test task is bounded, and bounded between the slow runner and the job cap`() { + assertTrue( + "app/build.gradle.kts sets its Test task timeout to ${timeoutMinutes}m, which is " + + "outside $SANE_MINUTES. Under that range a slow CI runner trips a bound meant for " + + "deadlocks -- the slowest observed passing run of the whole invocation was 90s. " + + "Over it, the Unit tests job's own 30-minute cap kills the job first and the " + + "timeout never reports. `null` means the line is gone or the block was rewritten, " + + "and without it #125's deadlock has nothing to stop it: monitor contention breaks " + + "no interrupt, so it runs until CI gives up and reports a timeout with no cause.", + timeoutMinutes in SANE_MINUTES, + ) + } + + @Test + fun `the thread dump is taken before the timeout kills the JVM it would dump`() { + assertTrue( + "app/build.gradle.kts takes its hang thread dump after ${dumpAfterMinutes}m but times " + + "the task out at ${timeoutMinutes}m, so the JVM is already dead when jstack runs " + + "and every future hang reports as a bare `Timeout has been exceeded`. The dump " + + "has to come first -- it is the only attribution a hanging test gets, since the " + + "test XML never names it.", + (dumpAfterMinutes ?: 0) < (timeoutMinutes ?: 0), + ) + } + + /** Minutes given to a whole `Test` task before Gradle stops the forked JVM. */ + private val timeoutMinutes: Int? + get() = minutesIn("""timeout\.set\(Duration\.ofMinutes\((\d+)\)\)""") + + /** Minutes the watchdog waits before jstacking the forked JVM. */ + private val dumpAfterMinutes: Int? + get() = minutesIn("""val dumpAfterNanos = Duration\.ofMinutes\((\d+)\)""") + + /** + * Read out of the build script rather than from a model: the numbers live in a Kotlin DSL block + * that no unit test can instantiate, and a scan that reports `null` when the shape changes is a + * better trade than not checking them at all. + */ + private fun minutesIn(pattern: String): Int? = + Regex(pattern).find(buildScript.readText())?.groupValues?.get(1)?.toInt() + + /** + * Found by walking up rather than by a fixed relative path: Gradle's working directory for the + * unit tests is the module, but that is a default rather than a promise. + */ + private val buildScript: File + get() = generateSequence(File(".").absoluteFile) { it.parentFile } + .map { File(it, "app/build.gradle.kts") } + .firstOrNull { it.isFile } + ?: error("could not find app/build.gradle.kts above ${File(".").absolutePath}") + + private companion object { + /** Above the slowest observed passing run, below the Unit tests job's `timeout-minutes`. */ + val SANE_MINUTES = 3..29 + } +}