Synchronise SafPickerRoundTripTest on state, not on timing (#268) #269

Merged
JMR-dev merged 2 commits from fix/268-saf-picker-determinism into main 2026-09-07 21:21:35 +00:00
JMR-dev commented 2026-09-07 20:52:31 +00:00 (Migrated from github.com)

Closes #268.

SafPickerRoundTripTest's two picker tests failed on roughly half of gating runs, by two
separately measured mechanisms. Both are removed rather than re-tuned. The fix is entirely in
app/src/androidTest; no production file is touched.

Mechanism B first, because it is the strongest claim

One observed failure had a 416 ms gap between the probe landing and the tap, so it was not
mechanism A: the tap landed, GrantPermissionsActivity started 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 is delivered to whichever window holds input focus, while 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, and a finished Activity is
a screen no waitUntil can wait for the return of.

The window is now removed rather than fought. POST_NOTIFICATIONS is granted in @Before.
ConverterScreen wires Convert to requestNotifications.launch(POST_NOTIFICATIONS), and
ActivityResultContracts.RequestPermission.getSynchronousResult returns SynchronousResult(true)
— without starting any Activity — when checkSelfPermission already answers
PERMISSION_GRANTED. So 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 it is a
structural property rather than a probability.

@Before asserts the grant instead of assuming it. If it ever fails to take, every test in the
class fails there in milliseconds, before the picker is opened or anything is tapped, naming the
permission and what it would cause — rather than decaying into the old 300 s timeout on
action.saveFile, which is a symptom two steps removed from the cause.

Evidence, and a correction to how I first measured it

My first grep of /tmp/logcat-apiNN.txt returned 16 / 32 / 24 REQUEST_PERMISSIONS hits and
appeared to contradict the claim. It was an artifact, and the trap is worth writing down because
the next person will hit it:
.github/scripts/e2e-run.sh opens LOGCAT_LOG with >>, so those
files accumulate — 13 to 19 stacked sections each, going back to Sep 6 — and a naive grep is
reading mostly runs of the unfixed code.

Scoped to the last section and to this class's TestRunner window, on the green sweep:

level SafPicker tests completed REQUEST_PERMISSIONS starts GrantPermissionsActivity
33 4 / 4 0 0
34 4 / 4 0 0
35 4 / 4 0 0
36 4 / 4 0 0

Those zeroes are for the entire 72-test run at each level, not merely inside this class.
Corroborating, at a lower weight: six consecutive single-class runs at API 34 showed the same
zeroes plus exactly two WM-SystemJobScheduler: Scheduling work ID lines per run — one for each
test that converts, so neither Convert tap was lost.

Mechanism A — the tap lost in the post-probe relayout

ConversionViewModel.onInputPicked writes _state exactly twice: name and size as soon as the
metadata query returns, then again with the probe filled in. The second write grows the file card,
which moves the Convert button. Compose computes the tap's coordinate from the semantics node and
dispatches the touch afterwards, so a relayout in that gap hit-tests a stationary coordinate
against the new layout and the touch lands on whatever moved into the button's place. Nothing
throws. Measured 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.

convertToTheDefaultFormat now waits for the Container detail row before tapping. That row is
composed only under input.probe != null, so its presence means both writes have landed and
been laid out. At that instant every write in flight is either landed or superseded: reattach
has returned on its _state.value !is Idle guard, or found nothing, or — since pruneWork() is
async — started an observe() whose writes the pick's ownership.claim() drops at
stillHeldBy. And observe for this job does not start until convert() runs. The card
cannot change height again before the tap.
That is a different claim from waiting longer.

A presence wait, deliberately: an absence wait can be satisfied by a composition that is
momentarily missing, which would tap into nothing.

Why the test and not production

#268 raised this and left it open. The double write is deliberate, documented progressive
disclosure — onInputPicked's own comment says blocking the screen on an FFprobe process spawn
"would read as the app having ignored the tap" — and reversing it to suit a test is the tail
wagging the dog. More decisively: a layout fix (pinning the button, reserving the card's height)
makes A less likely for one widget, whereas waiting on the probe makes it impossible for every
tap
, because there is then no pending state write at all.

The ticket's supporting argument — that each added OutputFormat widens the window — has been
withdrawn
, see https://github.com/JMR-dev/LibreMediaConverter/issues/268#issuecomment-5574676086.
The format FlowRow's height is constant across the probe landing; chip count changes where
Convert starts, not how far it moves.

Acceptance

  • No timing dependence. No Thread.sleep, no enlarged waitUntil budget, no retry count. Two
    constants were deleted (PERMISSION_UI_PACKAGE, PERMISSION_DIALOG_MS); none added. The
    fail-fast reuses the existing APP_TIMEOUT_MS.
  • The assertion did not weaken. Both tests still round-trip through the real system picker and
    assert exactly what they did: bytes reaching the document DocumentsUI created, and a failed save
    deleting it.
  • Mutation, run not predicted. Deleting publish's
    if (destinationWasEmpty) deletePartialOutput(destination, failure) arm reddened
    aFailedSaveDeletesTheDocumentItCouldNotWrite with "publish did not delete the document it
    could not write: content://org.libremediaconverter.test.fixtures/document/dest%2F…"
    — and
    reddened nothing else: 4 tests, 1 failure, its sibling green, since the success path never
    enters that catch. Restored afterwards.

Also added: a fail-fast that reports "the Convert tap did not start a conversion" instead of
spending the 300 s conversion budget and then naming action.saveFile. Explicitly a diagnostic,
not the synchronisation — the KDoc says so.

Counts, re-derived with the scripts' own patterns

figure value
androidTest @Test total 72
@FailsOnEmulatorApi37 markers 7
gating leg 65
FAILS_ON_EMULATOR_API37_BASELINE 7

Unchanged — no test is added or removed and no marker moves. Both picker tests keep
@FailsOnEmulatorApi37.

Local gate

Green on API 33, 34, 35 and 36 — expected: 72, received: 72, failed: 0, completed cleanly: yes
at every level. NOT COVERED LOCALLY: API 37 (no Pixel 10 Pro XL attached); CI's gating leg
answers for it.

API 37 is not exercised by this change at all, and that gap should be named rather than
implied: both tests carry the marker, so CI's gating leg skips them, and the advisory leg cannot
reach them because the rotation test truncates the run first. This wants the manual Pixel check
before release, like the rest of that set.

Collateral

NotificationCancelActionTest's KDoc asserted "the instrumented suite grants no runtime
permissions, so POST_NOTIFICATIONS is denied throughout"
. The @Before grant makes that false,
and a runtime grant cannot be undone in teardown — revoking restarts the app process, which would
take the rest of the instrumentation run with it. The suite runs without Orchestrator, so whether
that class sees the permission held now depends on class order. Its KDoc says so; no test logic
changed. The leak is benign: ConversionNotifications builds its channel at IMPORTANCE_LOW, so
nothing heads-up over the screen.

🤖 Generated with Claude Code

Closes #268. `SafPickerRoundTripTest`'s two picker tests failed on roughly half of gating runs, by two separately measured mechanisms. Both are removed rather than re-tuned. **The fix is entirely in `app/src/androidTest`; no production file is touched.** ## Mechanism B first, because it is the strongest claim One observed failure had a **416 ms** gap between the probe landing and the tap, so it was not mechanism A: the tap landed, `GrantPermissionsActivity` started 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 is delivered to whichever window holds *input* focus, while `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, and a finished Activity is a screen no `waitUntil` can wait for the return of. **The window is now removed rather than fought.** `POST_NOTIFICATIONS` is granted in `@Before`. `ConverterScreen` wires Convert to `requestNotifications.launch(POST_NOTIFICATIONS)`, and `ActivityResultContracts.RequestPermission.getSynchronousResult` returns `SynchronousResult(true)` — **without starting any Activity** — when `checkSelfPermission` already answers `PERMISSION_GRANTED`. So 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 it is a structural property rather than a probability. `@Before` **asserts** the grant instead of assuming it. If it ever fails to take, every test in the class fails there in milliseconds, before the picker is opened or anything is tapped, naming the permission and what it would cause — rather than decaying into the old 300 s timeout on `action.saveFile`, which is a symptom two steps removed from the cause. ### Evidence, and a correction to how I first measured it My first grep of `/tmp/logcat-apiNN.txt` returned 16 / 32 / 24 `REQUEST_PERMISSIONS` hits and appeared to contradict the claim. **It was an artifact, and the trap is worth writing down because the next person will hit it:** `.github/scripts/e2e-run.sh` opens `LOGCAT_LOG` with `>>`, so those files accumulate — 13 to 19 stacked sections each, going back to Sep 6 — and a naive grep is reading mostly runs of the *unfixed* code. Scoped to the last section and to this class's `TestRunner` window, on the green sweep: | level | SafPicker tests completed | `REQUEST_PERMISSIONS` starts | `GrantPermissionsActivity` | |---|---|---|---| | 33 | 4 / 4 | 0 | 0 | | 34 | 4 / 4 | 0 | 0 | | 35 | 4 / 4 | 0 | 0 | | 36 | 4 / 4 | 0 | 0 | Those zeroes are for the **entire 72-test run** at each level, not merely inside this class. Corroborating, at a lower weight: six consecutive single-class runs at API 34 showed the same zeroes plus exactly two `WM-SystemJobScheduler: Scheduling work ID` lines per run — one for each test that converts, so neither Convert tap was lost. ## Mechanism A — the tap lost in the post-probe relayout `ConversionViewModel.onInputPicked` writes `_state` exactly twice: name and size as soon as the metadata query returns, then again with the probe filled in. The second write grows the file card, which moves the Convert button. Compose computes the tap's coordinate from the semantics node and dispatches the touch afterwards, so a relayout in that gap hit-tests a stationary coordinate against the *new* layout and the touch lands on whatever moved into the button's place. Nothing throws. Measured 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. `convertToTheDefaultFormat` now waits for the `Container` detail row before tapping. That row is composed **only** under `input.probe != null`, so its presence means both writes have landed and been laid out. At that instant every write in flight is either landed or superseded: `reattach` has returned on its `_state.value !is Idle` guard, or found nothing, or — since `pruneWork()` is async — started an `observe()` whose writes the pick's `ownership.claim()` drops at `stillHeldBy`. And `observe` for *this* job does not start until `convert()` runs. **The card cannot change height again before the tap.** That is a different claim from waiting longer. A *presence* wait, deliberately: an absence wait can be satisfied by a composition that is momentarily missing, which would tap into nothing. ## Why the test and not production #268 raised this and left it open. The double write is deliberate, documented progressive disclosure — `onInputPicked`'s own comment says blocking the screen on an FFprobe process spawn "would read as the app having ignored the tap" — and reversing it to suit a test is the tail wagging the dog. More decisively: a layout fix (pinning the button, reserving the card's height) makes A *less likely for one widget*, whereas waiting on the probe makes it *impossible for every tap*, because there is then no pending state write at all. The ticket's supporting argument — that each added `OutputFormat` widens the window — **has been withdrawn**, see https://github.com/JMR-dev/LibreMediaConverter/issues/268#issuecomment-5574676086. The format `FlowRow`'s height is constant across the probe landing; chip count changes where Convert *starts*, not how far it *moves*. ## Acceptance - **No timing dependence.** No `Thread.sleep`, no enlarged `waitUntil` budget, no retry count. Two constants were *deleted* (`PERMISSION_UI_PACKAGE`, `PERMISSION_DIALOG_MS`); none added. The fail-fast reuses the existing `APP_TIMEOUT_MS`. - **The assertion did not weaken.** Both tests still round-trip through the real system picker and assert exactly what they did: bytes reaching the document DocumentsUI created, and a failed save deleting it. - **Mutation, run not predicted.** Deleting `publish`'s `if (destinationWasEmpty) deletePartialOutput(destination, failure)` arm reddened `aFailedSaveDeletesTheDocumentItCouldNotWrite` with *"publish did not delete the document it could not write: content://org.libremediaconverter.test.fixtures/document/dest%2F…"* — and reddened **nothing else**: 4 tests, 1 failure, its sibling green, since the success path never enters that catch. Restored afterwards. Also added: a fail-fast that reports *"the Convert tap did not start a conversion"* instead of spending the 300 s conversion budget and then naming `action.saveFile`. Explicitly a diagnostic, not the synchronisation — the KDoc says so. ## Counts, re-derived with the scripts' own patterns | figure | value | |---|---| | `androidTest` `@Test` total | 72 | | `@FailsOnEmulatorApi37` markers | 7 | | gating leg | 65 | | `FAILS_ON_EMULATOR_API37_BASELINE` | 7 | Unchanged — no test is added or removed and no marker moves. Both picker tests keep `@FailsOnEmulatorApi37`. ## Local gate Green on API 33, 34, 35 and 36 — `expected: 72, received: 72, failed: 0, completed cleanly: yes` at every level. `NOT COVERED LOCALLY: API 37` (no Pixel 10 Pro XL attached); CI's gating leg answers for it. **API 37 is not exercised by this change at all**, and that gap should be named rather than implied: both tests carry the marker, so CI's gating leg skips them, and the advisory leg cannot reach them because the rotation test truncates the run first. This wants the manual Pixel check before release, like the rest of that set. ## Collateral `NotificationCancelActionTest`'s KDoc asserted *"the instrumented suite grants no runtime permissions, so `POST_NOTIFICATIONS` is denied throughout"*. The `@Before` grant makes that false, and a runtime grant cannot be undone in teardown — revoking restarts the app process, which would take the rest of the instrumentation run with it. The suite runs without Orchestrator, so whether that class sees the permission held now depends on class order. Its KDoc says so; no test logic changed. The leak is benign: `ConversionNotifications` builds its channel at `IMPORTANCE_LOW`, so nothing heads-up over the screen. 🤖 Generated with [Claude Code](https://claude.com/claude-code)
JMR-dev commented 2026-09-07 21:11:11 +00:00 (Migrated from github.com)

The first E2E API 35 attempt was red; it is a #102 sighting, not this diff

Recording it here so the run history does not have to be re-diagnosed by the next reader.

Job 101862812172 failed one test:

SafPickerRoundTripTest > aFailedSaveDeletesTheDocumentItCouldNotWrite[test(AVD) - 15] FAILED
  java.lang.NullPointerException: Cannot run onActivity since Activity has been destroyed already
    at androidx.test.internal.util.Checks.checkNotNull(Checks.java:50)
    at androidx.test.core.app.ActivityScenario.lambda$onActivity$2(ActivityScenario.java:792)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:487)
    at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:2612)
    at android.os.Looper.loop(Looper.java:317)
expected: 72   received: 72   failed: 1   completed cleanly: yes

It is not the failure this PR fixes. That one was ComposeTimeoutException, 300 000 ms on
action.saveFile, after a screen that never left Ready and with nothing enqueued. This is a
destroyed Activity, and the suite ran to completion.

Four things place it in #102 rather than here:

  1. No frame from the test file. The stack is the main looper's — Checks.checkNotNull ←
    ActivityScenario.lambda$onActivity$2 ← Instrumentation$SyncRunnable ← Looper.loop. The
    Activity was already gone when something asked for it.
  2. Bracketed by the colour-buffer noise #102 keeps recording: ERROR | Failed to find ColorBuffer: 512 at 20:59:36, the failure at 20:59:43, ColorBuffer: 562 at 20:59:46.
  3. #102's own framing fits exactly — "three modes name the emulator's colour-buffer path, and
    none of them names anything in this app"
    , and its latest entry pairs the same Failed to find ColorBuffer noise with a PR whose production diff provably could not cause it.
  4. Re-run of the same job on the same commit passed (101864620664, 6m42s), and the commit had
    already passed API 33, 34, 36 and 37 gating on the first attempt, plus API 35 locally at
    72/72/0 in the gate sweep.

The honest caveat, since the failing test is one this PR edits: pattern-matching is not proof, which
is why the job was re-run rather than waved through. composeRule.activity is reached only through
awaitAppFocus, on the picker-retry path — dismissThePicker, awaitAppFocus and
saveThroughTheSystemPicker are all untouched here.

Worth a sighting on #102 if a maintainer agrees; I have not added one, as that ticket is not this
PR's to edit.

## The first E2E API 35 attempt was red; it is a #102 sighting, not this diff Recording it here so the run history does not have to be re-diagnosed by the next reader. Job `101862812172` failed one test: ``` SafPickerRoundTripTest > aFailedSaveDeletesTheDocumentItCouldNotWrite[test(AVD) - 15] FAILED java.lang.NullPointerException: Cannot run onActivity since Activity has been destroyed already at androidx.test.internal.util.Checks.checkNotNull(Checks.java:50) at androidx.test.core.app.ActivityScenario.lambda$onActivity$2(ActivityScenario.java:792) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:487) at android.app.Instrumentation$SyncRunnable.run(Instrumentation.java:2612) at android.os.Looper.loop(Looper.java:317) ``` ``` expected: 72 received: 72 failed: 1 completed cleanly: yes ``` **It is not the failure this PR fixes.** That one was `ComposeTimeoutException`, 300 000 ms on `action.saveFile`, after a screen that never left `Ready` and with nothing enqueued. This is a destroyed Activity, and the suite ran to completion. Four things place it in #102 rather than here: 1. **No frame from the test file.** The stack is the main looper's — `Checks.checkNotNull` ← `ActivityScenario.lambda$onActivity$2` ← `Instrumentation$SyncRunnable` ← `Looper.loop`. The Activity was already gone when something asked for it. 2. **Bracketed by the colour-buffer noise** #102 keeps recording: `ERROR | Failed to find ColorBuffer: 512` at 20:59:36, the failure at 20:59:43, `ColorBuffer: 562` at 20:59:46. 3. **#102's own framing fits exactly** — *"three modes name the emulator's colour-buffer path, and none of them names anything in this app"*, and its latest entry pairs the same `Failed to find ColorBuffer` noise with a PR whose production diff provably could not cause it. 4. **Re-run of the same job on the same commit passed** (`101864620664`, 6m42s), and the commit had already passed API 33, 34, 36 and **37 gating** on the first attempt, plus API 35 locally at 72/72/0 in the gate sweep. The honest caveat, since the failing test is one this PR edits: pattern-matching is not proof, which is why the job was re-run rather than waved through. `composeRule.activity` is reached only through `awaitAppFocus`, on the picker-retry path — `dismissThePicker`, `awaitAppFocus` and `saveThroughTheSystemPicker` are all untouched here. Worth a sighting on #102 if a maintainer agrees; I have not added one, as that ticket is not this PR's to edit.
Sign in to join this conversation.