Compare commits

...
Author SHA1 Message Date
JMR-dev 27d7cc0a86 Merge remote-tracking branch 'origin/main' into m-127b-tmp 2026-08-26 00:14:07 -05:00
Jason Ross 6df1bdf31a Merge pull request #115 from JMR-dev/docs/coverage-remeasure
Re-measure coverage, because the figure here predates the test push
2026-08-26 00:04:40 -05:00
JMR-dev c27881ab64 Merge remote-tracking branch 'origin/main' into m-127-tmp 2026-08-25 23:57:00 -05:00
JMR-devandClaude Opus 5 0f39964193 Say which misfire the hang watchdog actually has
The comment described adopting a later build's worker as an edge case. It is the
ordinary CI shape: the worker is found by scanning this daemon's descendants for
GradleWorkerMain, which cannot tell one invocation from the next, and the Unit
tests job runs testDebugUnitTest and jacocoTestReport back to back against one
daemon. Still harmless -- the watchdog only reads and writes -- but a reader
should not have to rediscover that.

Refs #125.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-25 23:47:16 -05:00
JMR-devandClaude Opus 5 81ad102f2a Stop a deadlocked unit-test run, and make it say what it deadlocked on
The JVM suite had no timeout of any kind, so #125's Room/WorkManager lock-order
inversion ran until something outside it gave up: 47 minutes locally, and on CI
it would burn the Unit tests job's 30-minute cap and report as a job timeout
with no cause. The deadlock is monitor contention, which no interrupt breaks, so
nothing inside the JVM could have ended it either.

The obvious fix does not work here. A JUnit `Timeout` -- as a rule or as
`@Test(timeout = ...)` -- runs the test body on a separate thread, and every Compose test in this
source set goes through Robolectric's paused main looper. Both forms fail with
"main looper can only be controlled from main thread"; the same tests with the
timeout removed pass, so it is the mechanism and not the probe.

So the bound comes from outside the test JVM, where it moves no threads:
`timeout` on the Test tasks kills the forked worker, and a watchdog jstacks that
worker two minutes earlier. The jstack is the point. Gradle's timeout on its own
kills silently, a timed-out run writes no XML for the class that hung, and the
JVM's own "Found one Java-level deadlock" section naming both monitors is the
only reason #125 could be described at all -- so it goes to stdout as well as to
a file, because the Unit tests job uploads only reports/tests/.

Ten minutes is against the slowest observed passing run, not the typical one:
eight CI samples of the whole invocation ranged 62-90s, so this is ~6.7x that
and a third of the job cap. A timeout that fires on a healthy slow runner turns
a real signal into noise.

Both numbers live in a build script that nothing compiles, so HangBoundTest
reads them back and the build script joins build.yml as a declared input --
without that the guard would go stale on exactly the edit it exists to catch.

Refs #125.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-25 23:35:13 -05:00
3 changed files with 218 additions and 0 deletions
+9
View File
@@ -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.
+111
View File
@@ -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<Test>().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<JacocoTaskExtension> {
isIncludeNoLocationClasses = true
excludes = listOf("jdk.internal.*")
@@ -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
}
}