Compare commits
7
Commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
64d5cbf738 | ||
|
|
842965a479 | ||
|
|
89832563e6 | ||
|
|
ef9d35ed40 | ||
|
|
b0b8b66d31 | ||
|
|
9fd96d08fd | ||
|
|
fa22bf3b13 |
@@ -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 <id> --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
|
||||
|
||||
@@ -1,7 +1,9 @@
|
||||
package org.libremediaconverter.saf
|
||||
|
||||
import android.Manifest
|
||||
import android.app.UiAutomation
|
||||
import android.content.Context
|
||||
import android.content.pm.PackageManager
|
||||
import android.net.Uri
|
||||
import android.provider.DocumentsContract
|
||||
import android.provider.OpenableColumns
|
||||
@@ -33,6 +35,7 @@ import org.junit.Assert.assertFalse
|
||||
import org.junit.Assert.assertNotEquals
|
||||
import org.junit.Assert.assertNotNull
|
||||
import org.junit.Assert.assertTrue
|
||||
import org.junit.Before
|
||||
import org.junit.Rule
|
||||
import org.junit.Test
|
||||
import org.junit.runner.RunWith
|
||||
@@ -361,6 +364,71 @@ class SafPickerRoundTripTest {
|
||||
/** Counts [MainActivity] creations from the moment [watchForRecreation] is called. */
|
||||
private val recreations = AtomicInteger()
|
||||
|
||||
/**
|
||||
* Holds `POST_NOTIFICATIONS`, so tapping Convert cannot open a window this test has to fight.
|
||||
*
|
||||
* ## What this replaces, and why the replacement is not a smaller wait
|
||||
*
|
||||
* Until #268 the tap was followed by `dismissThePermissionDialog`, which waited for
|
||||
* `com.google.android.permissioncontroller` to appear and pressed back on it. That is a
|
||||
* *foreign, focused window* in the middle of the one step this class most needs to be
|
||||
* deterministic, and it is what mechanism B of #268 was: on the API 35 leg of run 34146936252
|
||||
* the tap landed — `START u0 {act=android.content.pm.action.REQUEST_PERMISSIONS ...
|
||||
* GrantPermissionsActivity}` at 17:38:30.516 — back was pressed at 17:38:32.479, and no
|
||||
* `ConversionWorker` was ever enqueued in the five minutes that followed. A back press goes to
|
||||
* whichever window holds *input* focus, and `Until.hasObject` answers about the accessibility
|
||||
* tree, which can carry the dialog's nodes before it has the focus; a back that arrives one
|
||||
* window early lands on `MainActivity` and finishes it, which is a screen no `waitUntil` can
|
||||
* wait for the return of.
|
||||
*
|
||||
* ## Why holding the permission removes the window rather than making it less likely
|
||||
*
|
||||
* `ConverterScreen` wires Convert to `requestNotifications.launch(POST_NOTIFICATIONS)`, and
|
||||
* `ActivityResultContracts.RequestPermission.getSynchronousResult` returns
|
||||
* `SynchronousResult(true)` — *without starting anything* — when
|
||||
* `checkSelfPermission` already answers `PERMISSION_GRANTED`. So with the permission held there
|
||||
* is no `GrantPermissionsActivity`, no foreign window, no back press, and nothing this test
|
||||
* injects can finish the Activity. That is the whole chain, and [holdTheNotificationPermission]
|
||||
* asserts its one premise rather than assuming it.
|
||||
*
|
||||
* ## The KDoc this contradicts, and the measurement that settles it
|
||||
*
|
||||
* `convertToTheDefaultFormat` used to say granting "was tried first and did not take —
|
||||
* `GrantPermissionsActivity` appeared anyway". Re-measured on 2026-09-07, API 34 on this host,
|
||||
* six consecutive runs of this class: logcat carries **zero**
|
||||
* `act=android.content.pm.action.REQUEST_PERMISSIONS` starts and zero `GrantPermissionsActivity`
|
||||
* across all six, and exactly two `WM-SystemJobScheduler: Scheduling work ID` lines per run —
|
||||
* one for each test that converts, so neither Convert tap was lost. Whatever the earlier
|
||||
* attempt did, a `pm grant` issued before the tap does take. The assertion below is what keeps
|
||||
* that from going quietly stale.
|
||||
*
|
||||
* ## Two consequences, both deliberate
|
||||
*
|
||||
* The grant is **not** undone in teardown: revoking a runtime permission restarts the app's
|
||||
* process, which would take the rest of the instrumentation run with it. The suite runs without
|
||||
* Orchestrator, so every class that converts *after* this one now does so with notifications
|
||||
* permitted. That is benign — `ConversionNotifications` builds its channel at
|
||||
* `IMPORTANCE_LOW`, so nothing heads-up over the screen — but it is a real change to the
|
||||
* device state the rest of the run sees, and `NotificationCancelActionTest`'s KDoc is updated
|
||||
* with it.
|
||||
*
|
||||
* And this class no longer takes the denial path. It never asserted anything about it — the
|
||||
* permission is setup for a test whose subject is SAF — and nothing is lost by it: the
|
||||
* callback `ConverterScreen` registers is `{ viewModel.convert() }`, which **ignores its
|
||||
* boolean**, so "converts whichever way the answer goes" is the shape of the code rather than a
|
||||
* branch a test has to choose. `StaleLauncherResultTest` is what pins that callback path.
|
||||
*/
|
||||
@Before
|
||||
fun holdTheNotificationPermission() {
|
||||
device.executeShellCommand("pm grant $appPackage ${Manifest.permission.POST_NOTIFICATIONS}")
|
||||
assertEquals(
|
||||
"POST_NOTIFICATIONS is not held, so tapping Convert would open a permission dialog " +
|
||||
"and this class's determinism argument does not hold -- see the KDoc above",
|
||||
PackageManager.PERMISSION_GRANTED,
|
||||
context.checkSelfPermission(Manifest.permission.POST_NOTIFICATIONS),
|
||||
)
|
||||
}
|
||||
|
||||
/**
|
||||
* Counts a rotation's recreation without asking the Activity anything.
|
||||
*
|
||||
@@ -721,13 +789,10 @@ class SafPickerRoundTripTest {
|
||||
* showed LMC R38 fixtures"*. The default `MP4_H265` produces `video/mp4` and the root is
|
||||
* offered.
|
||||
*
|
||||
* **The notification dialog is dismissed rather than pre-granted, and that is the honest
|
||||
* version.** Convert never calls `convert()` directly — it launches `RequestPermission` for
|
||||
* `POST_NOTIFICATIONS` and converts from the callback **whichever way the answer goes**. So the
|
||||
* dialog only has to be got out of the way; denying it is a real user's path and the conversion
|
||||
* still runs. Granting it programmatically was tried first and did not take —
|
||||
* `GrantPermissionsActivity` appeared anyway, the click that followed went to it rather than to
|
||||
* the app, and the screen sat in `Ready` with nothing enqueued.
|
||||
* **The notification permission is held rather than dismissed**, which is #268's mechanism B
|
||||
* and is argued in [holdTheNotificationPermission]. The short version: `RequestPermission`
|
||||
* starts no Activity at all when the permission is already granted, so the tap below is
|
||||
* followed by no foreign window.
|
||||
*
|
||||
* **Both taps scroll first.** On `Ready` the screen carries a file card, five pickers and then
|
||||
* the button, so Convert is below the fold on a phone. `performClick` on an off-screen node
|
||||
@@ -735,38 +800,94 @@ class SafPickerRoundTripTest {
|
||||
* either way — the first version of this sat waiting for a `Converted` that could never come.
|
||||
*/
|
||||
private fun convertToTheDefaultFormat() {
|
||||
awaitTheProbeHavingLanded()
|
||||
|
||||
composeRule.onNodeWithTag(TestTags.Converter.CONVERT)
|
||||
.performScrollTo()
|
||||
.assertIsEnabled()
|
||||
.performClick()
|
||||
|
||||
dismissThePermissionDialog()
|
||||
requireTheTapToHaveStartedTheJob()
|
||||
awaitNode(TestTags.SAVE_FILE, CONVERSION_TIMEOUT_MS)
|
||||
}
|
||||
|
||||
/**
|
||||
* Gets the `POST_NOTIFICATIONS` dialog out of the way, if this device shows one.
|
||||
* Blocks until the pick's probe has been rendered, so no relayout can straddle the next tap.
|
||||
*
|
||||
* Backing out of it is a denial, and a denial is fine here: the conversion starts either way,
|
||||
* and what that costs the user is a progress notification confined to the Task Manager. Waiting
|
||||
* only briefly, because on a device where the permission is already held no dialog appears at
|
||||
* all and the conversion is already under way.
|
||||
* **This is #268's mechanism A, and the argument is that it becomes impossible rather than
|
||||
* unlikely.** `ConversionViewModel.onInputPicked` writes `_state` exactly twice: once with the
|
||||
* name and size as soon as the metadata query returns, and once more with the probe filled in.
|
||||
* The second write is what grows the file card, which moves everything below it — including the
|
||||
* Convert button. Compose's injection computes the target's centre from the semantics node and
|
||||
* dispatches the touch afterwards; a relayout in that gap hit-tests the stationary coordinate
|
||||
* against the *new* layout, so the down and the up land on whatever moved into the button's old
|
||||
* place. Nothing throws. Measured on the two failing gating legs as the gap between the pick's
|
||||
* FFprobe closing and the tap: 319 ms and 421 ms passed, 46 ms, 98 ms and 124 ms did not.
|
||||
*
|
||||
* A detail row can only be composed from that second write, because `FileCard` renders the rows
|
||||
* exclusively under `input.probe != null`. So once one exists, both of `onInputPicked`'s writes
|
||||
* have landed and been laid out, and every `_state` write still in flight is either landed or
|
||||
* superseded.
|
||||
*
|
||||
* `reattach` has **three** outcomes here, not two. It returns on its `_state.value !is Idle`
|
||||
* guard; or it finds nothing; or — because `pruneWork()` is async and can leave a finished job
|
||||
* unpruned — it passes that guard and starts an `observe()`. This paragraph used to name only
|
||||
* the first two, which was wrong rather than merely incomplete: the third is a live coroutine
|
||||
* with writes ahead of it.
|
||||
*
|
||||
* It is still harmless, and by a different mechanism than the guard. `reattach` reads
|
||||
* `ownership.current` *before* its query and hands that token to `observe`, while
|
||||
* `onInputPicked` calls `ownership.claim()` synchronously on the pick — so by the time a
|
||||
* detail row exists the observation is superseded, and every emission returns at
|
||||
* `stillHeldBy` before it writes. Outside that path `observe` is not started until
|
||||
* `convert()` runs. **The card cannot change height again before the tap**, which is a
|
||||
* different claim from waiting longer.
|
||||
*
|
||||
* The `Container` row specifically, rather than a new "probing finished" tag in `main`, because
|
||||
* this fixture is an MP4 video and that row is already what
|
||||
* [pickingAFileThroughTheSystemPickerFillsInTheFileCard] waits on and asserts. It is a
|
||||
* *presence* wait, which cannot be satisfied by a composition that is momentarily absent — an
|
||||
* absence wait can, and that would tap into nothing.
|
||||
*
|
||||
* **Not in [pickTheFixture].** The rotation test does not tap a Compose affordance in this
|
||||
* window at all, and the picker test already makes this exact wait its own assertion. Putting
|
||||
* it here keeps a broken read grant reddening one test with the message that explains it.
|
||||
*/
|
||||
private fun dismissThePermissionDialog() {
|
||||
if (device.wait(Until.hasObject(By.pkg(PERMISSION_UI_PACKAGE)), PERMISSION_DIALOG_MS) != true) {
|
||||
return
|
||||
private fun awaitTheProbeHavingLanded() {
|
||||
awaitNode(TestTags.Converter.detailRow(CONTAINER_LABEL))
|
||||
}
|
||||
|
||||
/**
|
||||
* Fails fast if the Convert tap started nothing, instead of waiting out the conversion budget.
|
||||
*
|
||||
* **A diagnostic, not the synchronisation** — [awaitTheProbeHavingLanded] is what makes the tap
|
||||
* land, and this cannot rescue a tap that did not. It exists because of what a lost tap used to
|
||||
* look like: `ComposeTimeoutException`, 300000 ms for `action.saveFile`, five minutes after a
|
||||
* screen that had never left `Ready`, which names the save affordance and says nothing about
|
||||
* the tap two steps earlier. Every #268 failure was read from logcat rather than from the
|
||||
* message, and this is the message it should have had.
|
||||
*
|
||||
* The condition is monotonic and needs no budget of its own: `convert()` sets `Converting`
|
||||
* synchronously, and `Ready` is the only state that renders a Convert button, so once the tag
|
||||
* is gone it stays gone. [APP_TIMEOUT_MS] rather than a new constant, because "the app should
|
||||
* have reacted by now" is exactly what that number already means here.
|
||||
*/
|
||||
private fun requireTheTapToHaveStartedTheJob() {
|
||||
val tag = TestTags.Converter.CONVERT
|
||||
try {
|
||||
composeRule.waitUntil("the Convert tap left the Ready screen", APP_TIMEOUT_MS) {
|
||||
// A composition that is momentarily absent throws, and must read as "not yet"
|
||||
// rather than as "the button is gone" -- see awaitNode.
|
||||
runCatching { composeRule.onAllNodesWithTag(tag).fetchSemanticsNodes().isEmpty() }
|
||||
.getOrDefault(false)
|
||||
}
|
||||
} catch (timeout: ComposeTimeoutException) {
|
||||
throw AssertionError(
|
||||
"the Convert tap did not start a conversion: $tag is still on screen " +
|
||||
"${APP_TIMEOUT_MS}ms after it was clicked, so the screen never left Ready",
|
||||
timeout,
|
||||
)
|
||||
}
|
||||
device.pressBack()
|
||||
device.wait(Until.gone(By.pkg(PERMISSION_UI_PACKAGE)), PERMISSION_DIALOG_MS)
|
||||
// And wait for the app to be in front again before anything asks Compose about it.
|
||||
// Querying while another window still owns the screen raises "No compose hierarchies found
|
||||
// in the app", which is what this test did on an API 35 leg: the back press had landed but
|
||||
// the dialog had not finished going away.
|
||||
//
|
||||
// Asked of UiAutomator rather than through awaitAppFocus, which is the opposite of what the
|
||||
// class KDoc argues for elsewhere and is right here: awaitAppFocus goes through
|
||||
// composeRule.waitUntil, so it would raise the very error it is being used to avoid.
|
||||
device.wait(Until.hasObject(By.pkg(context.packageName)), FOCUS_TIMEOUT_MS)
|
||||
}
|
||||
|
||||
/**
|
||||
@@ -857,6 +978,8 @@ class SafPickerRoundTripTest {
|
||||
private fun requireAReadableScreen() {
|
||||
val app = By.pkg(appPackage)
|
||||
if (device.wait(Until.hasObject(app), READABLE_TIMEOUT_MS) == true) return
|
||||
// The return value is deliberately dropped here: the wait on the next line IS the re-probe
|
||||
// that dismissThePicker had to be given, so there is nothing for it to gate.
|
||||
dismissASystemErrorDialog()
|
||||
if (device.wait(Until.hasObject(app), READABLE_TIMEOUT_MS) == true) return
|
||||
unlockTheDevice()
|
||||
@@ -897,14 +1020,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
|
||||
}
|
||||
|
||||
/**
|
||||
@@ -1036,6 +1166,51 @@ 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:35.689 UiObject2: Clicking on (927, 2274) <- iteration 2's dismissal, on button1
|
||||
* 20:59:36.033 MainActivity RESUMED <- so the picker is gone, by our hand
|
||||
* 20:59:36.350 VRI[PickActivity]: visibilityChanged ... newVisibility=false
|
||||
* 20:59:37.068 UiDevice: Pressing back button. <- iteration 2 presses anyway
|
||||
* 20:59:41.094 UiDevice: Retrieving node ... [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. <- iteration 3
|
||||
* 20:59:41.754 TopTaskTracker: onTaskMovedToFront: ... NexusLauncherActivity
|
||||
* 20:59:42.278 MainActivity DESTROYED
|
||||
* ```
|
||||
*
|
||||
* Read the first two lines before the rest, because they are the part that is easy to get
|
||||
* wrong: **the picker did not close on its own — this function closed it**, on iteration 2,
|
||||
* when [dismissASystemErrorDialog] fell through to `android:id/button1` and clicked what was
|
||||
* almost certainly DocumentsUI's own positive button (#271). From `20:59:36.033` onwards there
|
||||
* was nothing left to back out of. Iteration 2 pressed back regardless, iteration 3 dismissed
|
||||
* the launcher's ANR dialog — #93's occluder, still ambient on these runners, and the only
|
||||
* remaining reason the focus read false — and pressed again, and that press finished
|
||||
* `MainActivity`. Every later `onActivity` in the test then threw
|
||||
* `NullPointerException: Cannot run onActivity since Activity has been destroyed already`.
|
||||
*
|
||||
* **With the re-read below, iteration 2 returns** — the app is focused within a second of the
|
||||
* `button1` click — and iterations 2 and 3 never press at all.
|
||||
*
|
||||
* **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.
|
||||
*/
|
||||
@@ -1046,7 +1221,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
|
||||
@@ -1205,8 +1384,9 @@ class SafPickerRoundTripTest {
|
||||
* `fetchSemanticsNodes` **throws** `IllegalStateException: No compose hierarchies found in the
|
||||
* app` when nothing is attached at that instant, and `waitUntil` propagates it on the first
|
||||
* poll instead of waiting out the deadline. This class spends much of its time with another
|
||||
* app in front — the picker, the create-document dialog, the permission dialog — so there is
|
||||
* always a window where the app is coming back and has no composition yet. Before this, that
|
||||
* app in front — the picker and the create-document dialog, and until #268 the permission
|
||||
* dialog too — so there is always a window where the app is coming back and has no composition
|
||||
* yet. Before this, that
|
||||
* window was a hard failure: measured on the API 34 leg of run 34057196628, where **both** SAF
|
||||
* tests died that way while the same commit passed API 33, 35, 36 and 37, and the previous
|
||||
* commit passed API 34 and failed 35. A failing leg that moves between runs is #190's
|
||||
@@ -1240,12 +1420,6 @@ class SafPickerRoundTripTest {
|
||||
const val PICKER_TIMEOUT_MS = 30_000L
|
||||
const val APP_TIMEOUT_MS = 30_000L
|
||||
|
||||
/** The runtime-permission dialog's package, so it can be recognised and dismissed. */
|
||||
const val PERMISSION_UI_PACKAGE = "com.google.android.permissioncontroller"
|
||||
|
||||
/** Short: either the dialog is up almost immediately, or the permission was already held. */
|
||||
const val PERMISSION_DIALOG_MS = 5_000L
|
||||
|
||||
/**
|
||||
* Bounds a hang, and **the first number here was measured on one API level and wrong on
|
||||
* another.** It read 120 s, on the strength of the whole test taking 11.8 s on the API 34
|
||||
|
||||
+10
-4
@@ -37,10 +37,16 @@ import java.util.concurrent.TimeUnit
|
||||
* ## Why this fires the intent rather than reading the shade
|
||||
*
|
||||
* The obvious version asks `NotificationManager.getActiveNotifications()` for id 1001 and taps what
|
||||
* it finds. That was rejected: the instrumented suite grants no runtime permissions, so
|
||||
* `POST_NOTIFICATIONS` is denied throughout, and whether a suppressed foreground-service
|
||||
* notification is returned there is a platform detail that varies — the test would be asserting
|
||||
* something about notification *visibility* rather than about cancellation.
|
||||
* it finds. That was rejected because it would be asserting something about notification
|
||||
* *visibility* rather than about cancellation — and because whether the shade holds the
|
||||
* notification at all is not this class's to know.
|
||||
*
|
||||
* **It used to say `POST_NOTIFICATIONS` is denied throughout, and since #268 that is no longer
|
||||
* true.** `SafPickerRoundTripTest` grants it in `@Before`, so that its Convert tap cannot open a
|
||||
* permission dialog, and a runtime grant cannot be undone in teardown without restarting the app's
|
||||
* process. The suite runs without Orchestrator, so whether this class sees the permission held
|
||||
* depends on class order — which is exactly the reading this test does not do, and the reason it
|
||||
* stays the right shape rather than a reason to change it.
|
||||
*
|
||||
* The `PendingIntent` is the subject; where it is read from is incidental. Building the
|
||||
* notification for a real, live work id and firing its action exercises exactly the thing that can
|
||||
|
||||
@@ -0,0 +1,207 @@
|
||||
# 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`. Mode 6's fix is in #272 and is the only
|
||||
thing here not yet on `main`.
|
||||
|
||||
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<C2BlockPool> 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:35.689 UiObject2: Clicking on (927, 2274) <- iteration 2's dismissal, on button1
|
||||
20:59:36.033 MainActivity RESUMED <- the picker is gone, by the test's own hand
|
||||
20:59:36.350 VRI[PickActivity]: visibilityChanged ... newVisibility=false
|
||||
20:59:37.068 UiDevice: Pressing back button. <- iteration 2 presses anyway
|
||||
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. <- iteration 3
|
||||
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".
|
||||
|
||||
**And the first two lines are the part to read carefully, because the obvious reading is wrong.**
|
||||
The picker did not close on its own: `dismissASystemErrorDialog` closed it on iteration 2, by
|
||||
falling through to `android:id/button1` and clicking DocumentsUI's own positive button (#271). From
|
||||
`20:59:36.033` there was nothing to back out of — and the loop pressed back on iteration 2 anyway,
|
||||
then dismissed the launcher's ANR dialog on iteration 3 and pressed again on the reading taken
|
||||
before doing so. That press finished `MainActivity`. **So this mode and #271 are one incident**, and
|
||||
the fix stops it at iteration 2, where the re-read now returns.
|
||||
|
||||
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 <head>` 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 <id> --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/<device>/logcat-<class>-<method>.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.
|
||||
Reference in New Issue
Block a user