diff --git a/CLAUDE.md b/CLAUDE.md index d577cf8..e188c74 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -148,6 +148,17 @@ Still true, and the reason the advisory job is not simply deleted: **API 37 need the Pixel 10 Pro XL before each release.** Those seven tests are the one thing CI cannot answer for. +**When a gating leg goes red on a diff that cannot explain it, read `docs/ci-failure-modes.md` +before anything else.** It is the census of all 129 gating failures in the repo's history against +1489 leg-attempts, with a per-mode disposition, and it is what closed #102. Three things from it +that are easy to get wrong and expensive: **count per leg-attempt, never per run** — a re-run to +green replaces the conclusion, so counting runs sees about 40% of the failures; **every mode has +its own denominator**, because the API 37 row filters seven tests out and some tests are younger +than the window; and **a re-run destroys the log** — `gh run view --job --log` resolves by run +and serves the latest attempt, so capture evidence before retrying, or read the attempt through +`gh api /repos/.../actions/jobs/{job_id}/logs`. The artifacts do survive, one per attempt under the +same name; `gh run download` takes the newest, which is the wrong one. + On a device or emulator, build only the ABI it can execute: ```bash diff --git a/app/src/androidTest/java/org/libremediaconverter/saf/SafPickerRoundTripTest.kt b/app/src/androidTest/java/org/libremediaconverter/saf/SafPickerRoundTripTest.kt index 4a2e2fc..55a5765 100644 --- a/app/src/androidTest/java/org/libremediaconverter/saf/SafPickerRoundTripTest.kt +++ b/app/src/androidTest/java/org/libremediaconverter/saf/SafPickerRoundTripTest.kt @@ -1018,14 +1018,21 @@ class SafPickerRoundTripTest { * would click whatever system window happened to be there. `aerr_wait` first: it dismisses the * dialog and leaves the offending app alone, which is the polite answer when the app is not * ours. Back is not tried — `BaseErrorDialog` swallows key events. + * + * **Returns whether it clicked anything, and the caller has to care.** Dismissing the dialog + * changes the window focus, so every reading taken before this ran is stale afterwards — + * which is the whole of #102's `MainActivity`-destroyed mode. [requireAReadableScreen] already + * re-probes after calling this; [dismissThePicker] could not, because it had no way to know + * whether there had been anything to dismiss. */ - private fun dismissASystemErrorDialog() { + private fun dismissASystemErrorDialog(): Boolean { for (id in ERROR_DIALOG_BUTTONS) { val button = device.findObject(By.res(id)) ?: continue button.click() device.waitForIdle() - return + return true } + return false } /** @@ -1157,6 +1164,41 @@ class SafPickerRoundTripTest { * enough from Recent and two are needed from inside the root, but a third from Recent would * finish `MainActivity` and take the rest of the test with it. * + * **That hazard was reached, and the guard above is why it could be** (#102). A system + * app-error dialog is a fullscreen `system_server` window, so it takes the focus away from + * `MainActivity` too — [awaitAppFocus] cannot tell "the picker is still up" from "a dialog is + * on top of an app that is already in front". Measured on the API 35 gating leg of run + * `34161043035` attempt 1, which is #269's own head: + * + * ``` + * 20:59:36.033 MainActivity RESUMED <- the save picker has already returned + * 20:59:41.094 UiDevice: Retrieving node with selector: BySelector [RES='android:id/aerr_wait'] + * 20:59:41.169 Input channel object 'Application Not Responding: + * com.google.android.apps.nexuslauncher' was disposed + * 20:59:41.713 UiDevice: Pressing back button. + * 20:59:41.754 TopTaskTracker: onTaskMovedToFront: ... NexusLauncherActivity + * 20:59:42.278 MainActivity DESTROYED + * ``` + * + * The launcher's ANR dialog — #93's occluder, still ambient on these runners — was the only + * reason the focus read false. Removing it made the app focused, and the back press aimed at a + * picker that had closed five seconds earlier finished `MainActivity` instead. Every later + * `onActivity` in the test then threw + * `NullPointerException: Cannot run onActivity since Activity has been destroyed already`. + * + * **So the reading is retaken after the dialog goes, and only then.** This removes a back + * press sent on a stale reading; it does not retry one, and it does not make the dismissal + * more tolerant. A picker that really is in front still leaves the app unfocused, so the press + * still happens and a genuinely stuck picker still fails here. On the ordinary path — no + * dialog — nothing is re-read and nothing is waited on, which is why the check is behind the + * `&&`. [requireAReadableScreen] has always re-probed after dismissing a dialog; this is the + * same rule in the one place that did not follow it. + * + * **It cannot be proved by re-running**, and that is worth saying rather than glossing: the + * launcher ANR is ambient and unreproducible on demand, so a green sweep is not evidence. What + * the fix rests on is the trace above: the launcher comes to the front 41 ms after a back press + * that this change does not send, and the Activity is destroyed 565 ms after that. + * * **[forceStopThePicker] is the escalation after the presses, and it exists because a back * press is not always deliverable.** See its own KDoc for the measurement. */ @@ -1167,7 +1209,11 @@ class SafPickerRoundTripTest { // so a back aimed at the picker lands on the dialog and nothing moves. Measured -- // API 34 of run 32813885120 exhausted all four presses with `android` in front, which // is that dialog, while the launcher it belonged to went on ANRing behind everything. - dismissASystemErrorDialog() + // + // And re-read the focus if one was dismissed: the dialog is itself a reason the + // reading above can be false, so a press sent on it can land on an app that is + // already in front. See the KDoc -- that is how MainActivity got destroyed. + if (dismissASystemErrorDialog() && awaitAppFocus()) return device.pressBack() } // The check after the last press, and not a spare one: `repeat` presses on its final diff --git a/docs/ci-failure-modes.md b/docs/ci-failure-modes.md new file mode 100644 index 0000000..9583cb2 --- /dev/null +++ b/docs/ci-failure-modes.md @@ -0,0 +1,198 @@ +# When a gating E2E leg goes red and the diff cannot explain it + +**Status:** a census of every gating E2E leg-attempt in the repo's history, classified by mode, +with a disposition for each. **1489 gating leg-attempts, 129 failures, 8.7%** — 2026-08-20 to +2026-09-07. This is the standing answer to "my docs-only PR turned an emulator leg red, what is +it?", and it is what #102 asked for before being closed as an umbrella. +**Last verified:** 2026-09-07, against `main` at `ef9d35e`. + +This document is about **the emulator failing underneath the suite**. It is not a defect record +(`docs/defect-audit.md`), not a coverage read (`docs/coverage-read-findings.md`), and not a +test-suite read (`docs/e2e-read-findings.md`). Nothing here is a bug in the app. + +## Read this first: three counting rules, each learned by getting it wrong + +**Count per leg-attempt, never per run.** Measured here rather than asserted: the 129 failing +leg-attempts sit in **83 distinct runs, and 45 of those 83 ended green** once someone re-ran them. +So a census that counts failed *runs* finds 38 events where there were 129 — it does not +under-report evenly, it deletes exactly the failures somebody already decided were noise, which are +the ones this document is about. Every number here is per leg-attempt, with `cancelled` legs +excluded: those are `concurrency: cancel-in-progress` cancellations rather than runs, and there are +135 of them. + +**Every mode has its own denominator, and it is not 1489.** Derive it from where and when the +*test* ran, not from the leg count, and two things move it. The API 37 row filters out every test +carrying `@FailsOnEmulatorApi37` with `notAnnotation` — **all four of `SafPickerRoundTripTest` and +three of `Media3EngineTest`, seven today** — which is every mode in the table below except 3 and 5. +And **that set has grown across this window**: the picker test and the two saves only joined it on +2026-09-06, which is why `SafPickerRoundTripTest` has 25 API 37 failures on record — 14 of them +since 2026-08-27 — that could not happen now. The saves did +not exist at all before 2026-09-06T15:12. A rate quoted over "all gating leg-attempts" is wrong for +every one of them, and is how "8% of legs" gets said about a thing that happens on one row. + +**Anchor the mode to the test name beside the `FAILED` marker, then to the message under it.** +The name alone is not enough: `transcodesH264ToH265AndReportsProgress` has failed for three +different reasons, one of which was the whole suite going down around it. + +## The modes + +| # | mode | signature | where | disposition | +|---|---|---|---|---| +| 1 | SAF picker will not close | `the system picker would not close: after 4 back presses ...` | 37 only, since #96 | **#108** — collateral of the gralloc abort | +| 1b | picker never showed, from the rotation test | `never showed BySelector [PKG=...], in 3 separate pickers` | 33, 34 — 3 times | #268/#269; no gating attempt on `main` since | +| 2 | wedge | gradle never returns; leg killed at `WEDGE_TIMEOUT`; `wedged: yes` in the shape row | 33/34 only | **#122**, addressed by #219 — see below | +| 3 | emulator never came up | `adb ... failed with exit code 224`, before any test | 37 only, 3 times | infra, before the suite; nothing to attribute | +| 4 | Media3 export watchdog | `ExportException: Muxer error` / `no output sample written in the last 25000 milliseconds` | 34, 36 | **environmental, measured** — see below | +| 5 | `system_server` gone mid-suite | `Can't find service: package`, `am get-current-user` fails, `INSTRUMENTATION_ABORTED` | 37 only | **#108** — `hasReadColorBufferDma` | +| 6 | app Activity destroyed under the SAF save tests | `NullPointerException: Cannot run onActivity since Activity has been destroyed already` | 35, once | **fixed** — see below | + +**#96 held, and mode 1 is worth stating as a number rather than a memory.** +`pickingAFileThroughTheSystemPickerFillsInTheFileCard` — the test #93 and #96 were about — has +failed **zero times on API 33-36 in the 881 gating leg-attempts since #96 merged**. Every remaining +failure of that class on those four rows is a *different* test: three of the rotation test (1b) and +seven of the two save tests (mode 6). The picker mode is an API 37 mode now. + +Background noise that is **not** a mode on its own: `Failed to find ColorBuffer: N` and `bad color +buffer handle N` never name anything in this app and appear on green legs. Measured over 12 green +gating legs sampled from 2026-09-02 onwards, all reporting `failed: 0`: `bad color buffer handle` +in **6** of them, `Failed to find ColorBuffer` in **2**. Neither is evidence of anything on its own. + +## Mode 4 — the Media3 export watchdog is the emulator's codec HAL segfaulting + +**This is the mode #102 was filed for, and it is not starvation.** The per-test logcat in +`e2e-report-api34` of run `34000816016` attempt 1, 62 ms after the test starts: + +``` +00:20:39.814 D MediaCodec: MediaCodec::reclaim(...) c2.goldfish.h264.decoder +00:20:39.822 F DEBUG : Cmdline: /vendor/bin/hw/android.hardware.media.c2@1.0-service-goldfish +00:20:39.822 F DEBUG : signal 0 (SIGSEGV), code 1 (SEGV_MAPERR) +00:20:39.822 F DEBUG : Cause: null pointer dereference + #00 C2Block2D::handle() const+4 libcodec2_vndk.so + #01 getClientUsage(std::shared_ptr const&) libcodec2_goldfish_common.so + #02 android::C2GoldfishAvcDec::process(...) libcodec2_goldfish_avcdec.so +00:20:39.839 E CCodec : Codec2 component "c2.goldfish.h264.decoder" died. +00:20:39.846 E MediaCodec: Codec reported err 0xffffffe0/DEAD_OBJECT +``` + +The decoder HAL process dies and respawns. Media3 is left with a dead codec, writes no output +sample, and its own 25-second export watchdog aborts the export — which is the `Muxer error` the +job log shows. **The crashing code is `/vendor/lib64/*` inside the system image**, so this is +environmental in the same sense `@FailsOnEmulatorApi37` is, and now with the same kind of evidence. + +**Six for six.** Every leg-attempt that has failed this way carries the crash in the same job's +`--- native crashes (tail 60) ---` dump. **Grep `c2@1.0-service-goldfish` and not the friendlier +line**: `Codec2 component "c2.goldfish.h264.decoder" died` is a `CCodec` message in the main +buffer and is in **none** of the six job logs, because that dump is `adb logcat -d -b crash` and +what reaches it is the tombstone, whose `Cmdline:` names the HAL. The six are +`32855014836` a1 (36), `32857067112` a1 (34), +`32919928048` a1 (36), `33261618358` a1 (34), `33588264439` a1 (36), `34000816016` a1 (34). +**Six in 1210 API 33-36 leg-attempts — 0.5%**, split 3 on API 34 and 3 on API 36, none on 33 or 35. + +**It is the same weakness the API 37 marker names.** `FailsOnEmulatorApi37`'s stated reason is that +Media3 transcodes "fail inside the emulator's own `c2.goldfish.h264.decoder`". That is this HAL. +One weakness, deterministic on the android-37 images and 0.5% below them. + +**What is not settled:** *why* it dereferences null. `MediaCodec::reclaim` is logged 8 ms earlier, +and a reclaim is the resource manager taking a codec instance away — so "a reclaim races +`C2GoldfishAvcDec::process` and the block pool goes out under it" is the obvious hypothesis and is +**untested**. Recorded as a hypothesis, not as a cause. + +**Two failures of that test are excluded and it matters that they are.** `32545625459` a1 (API 37) +had 37 tests fail together with the gralloc assertion present — that is mode 5, and this test was +collateral. `32669190757` a1 (API 35) predates #111's shape report and carries a bare `FAILED` +marker with no message at all; it is **unclassifiable, and is not classified**. + +## Mode 6 — the back press that finished `MainActivity` + +Traced on the API 35 gating leg of run `34161043035` **attempt 1**, whose head is #269's own +commit: + +``` +20:59:36.033 MainActivity RESUMED <- the save picker has already returned +20:59:37.068 UiDevice: Pressing back button. +20:59:41.094 UiDevice: Retrieving node ... [RES='android:id/aerr_wait'] +20:59:41.169 Input channel 'Application Not Responding: ...nexuslauncher' was disposed +20:59:41.713 UiDevice: Pressing back button. +20:59:41.754 TopTaskTracker: onTaskMovedToFront: ... NexusLauncherActivity +20:59:42.278 MainActivity DESTROYED +``` + +`dismissThePicker` guarded its back presses on `Activity.hasWindowFocus`. A system app-error dialog +is a fullscreen `system_server` window, so **it makes that false too** — the guard could not tell +"the picker is still up" from "a dialog is on top of an app that is already in front". The loop +dismissed the launcher's ANR dialog (#93's occluder, still ambient) and then pressed back on the +reading it had taken before doing so, into an app with nothing left to go back to. + +Fixed by re-reading the focus after a dialog is actually dismissed, and only then — +`SafPickerRoundTripTest.dismissThePicker` carries the trace. That **removes** a press sent on a +stale reading rather than retrying one, and a picker genuinely in front still fails there. + +**It cannot be demonstrated by re-running.** The launcher ANR is ambient and not reproducible on +demand, so a green sweep is not evidence for this fix; the trace is. + +### The other six failures of those save tests are four different things + +Filed as one mode, they are not one: seven occurrences, **five distinct messages** counting the +destroy above. Three of the six below are on heads that predate their own follow-up fix, and one is +on a head that **contains** the fix meant for it. This is the worked example for "split by message +before diagnosing". **The two rows still open are #270**; the `button1` finding below is **#271**. + +| run / attempt | head | message | what it is | +|---|---|---|---| +| `34041593697` a1 (35) | `fa10d94` — the commit that **added** the test | `No compose hierarchies found`, thrown directly | pre-`b23ff0f` | +| `34056545386` a1 (35) | `cbbaf74` | `ComposeTimeoutException ... after 120000 ms` | the `CONVERSION_TIMEOUT_MS` case `19e3539` fixed. **Not a system-service failure at all** — API 35's software encode measured 134.8 s against a 120 s bound | +| `34057706195` a1 (34) | `19e3539` | `No compose hierarchies found` ×2 | **contains `b23ff0f`**, so that fix did not close this shape. Open | +| `34067653670` a1 (35), `34146936252` a1 (35) | `d45abe7`, `73482520` | `waited 300000ms for a node tagged action.saveFile`, **no** composition error | `awaitNode` appends the composition error only when `fetchSemanticsNodes` threw, so the composition was readable throughout. `34067653670`'s per-test logcat has `MainActivity` `RESUMED` for the whole 300 s and **no conversion running at all**. Open | +| `34146936252` a2 (35) | `73482520` | `waited 300000ms ...; last composition error: No compose hierarchies` | app `PAUSED` and never resumed; the back press at `17:38:32.479` follows `Waiting 5000ms for ... permissioncontroller`, the permission-dialog helper #269 replaced with `pm grant` | + +### And the dismissal can click a dialog that is not a system dialog (#271) + +In the same trace, at `20:59:35.689`, `aerr_wait` and `aerr_close` both missed and +`android:id/button1` — the framework's generic `AlertDialog` positive button, present on every +`AlertDialog` on the device — was found and clicked. `MainActivity` came back 339 ms later and +`PickActivity`'s window went away with it, so what was clicked was a button inside **DocumentsUI's +own create-document flow**. It did no harm on that run. Filed rather than fixed here, because +narrowing the selector is a decision about what `dismissASystemErrorDialog` may reach. + +## Mode 2 — the wedge, and why this says "consistent with" rather than "fixed" + +Nine occurrences, **all on API 33/34**, 9 in 497 leg-attempts before 2026-09-06T02:00Z — **1.8%** +— and **0 in the 106 since**. The last one, `34001741668` (2026-09-06T00:36), is +`thePickedInputSurvivesARealRotation` again, and `git merge-base --is-ancestor 32ab54d ` says +that head **does not contain** #219's fix, so no wedge has ever been recorded against the fix. + +At the prior rate, P(0 in 106) ≈ 0.15. **That is suggestive and it is not evidence.** Re-count +before writing "fixed" here. + +Its diagnostics say the framework is fine, which is what separates it from every other mode in this +document: `e2e-wedge-api34` of `34001741668` has `started:` the rotation test with no `finished:`, +and `input`, `window`, `activity` and `media.player` all `found`. + +## Reading the evidence, when the leg is already gone + +Four things that are not obvious and each cost a wrong answer: + +- **A re-run destroys the log.** `gh run view --job --log` resolves by *run* and serves the + latest attempt, so after a re-run to green it hands back a green log for a red attempt. Use + `gh api --allow-escape-sequences /repos/{owner}/{repo}/actions/jobs/{job_id}/logs`, with the job + id from `/actions/runs/{run}/attempts/{n}/jobs`. Without `--allow-escape-sequences`, `gh` writes + nothing and exits 0. +- **A re-run does *not* destroy the artifacts, but the convenient command hides them.** + `/actions/runs/{run}/artifacts` returns every attempt's upload under the same name with different + ids and `created_at`; `gh run download` takes the newest, which after a re-run-to-green is the + green one. Match `created_at` to the attempt's window and fetch + `/actions/artifacts/{id}/zip`. +- **The per-test logcat is the evidence, not the job log.** `e2e-report-apiNN` carries + `outputs/androidTest-results/connected/debug//logcat--.txt` — one file per + test, scoped to that test's window — plus the JUnit XML with the untruncated stack. The job log + truncates a stack to its first frame, which is why the `ActivityScenario` frames in mode 6 are + invisible there. +- **Grep the fault, not the thread.** #102 once split one bug into two by grepping + `TaskSnapshotPer` — a thread name from a ticket title — instead of `hasReadColorBufferDma`, the + assertion. The assertion is the invariant; the thread is only which caller tripped it. + +## What this does not cover + +The advisory `E2E API 37 Media3 hardware transcode (advisory)` job is **red on every PR by design** +and is not a signal. `docs/api-37-emulator-crash.md` has API 37's own story; +`.github/scripts/e2e-report-shape.sh` explains the shape table every leg prints.