From 55f1f59e3d7e32dd3ed49726113ad9bc145c73fe Mon Sep 17 00:00:00 2001 From: Jason Ross Date: Tue, 7 Jul 2026 05:07:11 -0500 Subject: [PATCH] refactor(scripts): fold cold-fetch pause-hook A/B into device-testing harness (#405) Bakes the proven 2026-07-06 cold-vs-warm pause-hook flow into scripts/device-testing/ as a first-class, reproducible `cold-fetch-ab` scenario, upstreaming the scratchpad driver. - fetchgate.py: FETCH_GATE pause/resume/query helpers through the guarded adb wrapper, with ordered-broadcast read-back parsing (paused=[...]). - scenarios.cold_fetch_ab: pre-arm halt -> detect sign-in (sync all breadcrumb) -> confirm halt (prefetch skipped) -> wait for header sync -> measure cold opens -> resume -> measure warm opens. ALWAYS resumes on exit (finally), even on error -- never leaves fetch paused. - report.render_cold_fetch_ab: gate summary, cold/warm tables, cold-vs-warm delta, connect=0ms reuse proof, throttle signature. - Portability (subsumes #392): file-based uiautomator dump (not /dev/tty), UTF-8 adb decode + PYTHONUTF8/console I/O, openMessage-breadcrumb readiness, row-selection hardening (skip non-message rows). The pause hook is debug-build-only (#393/#395), so the scenario needs a debug APK. Automated validation: mocked unittest coverage (adb/breadcrumbs/gate) for the helpers and the A/B scenario incl. restore-on-error, plus a --dry-run path exercised end-to-end through perf_harness.main. A full on-device run is a follow-up. Dev-tooling only; no app/src changes. Co-Authored-By: Claude Opus 4.8 --- scripts/device-testing/README.md | 45 +- scripts/device-testing/adb.py | 41 +- scripts/device-testing/breadcrumbs.py | 40 ++ scripts/device-testing/fetchgate.py | 169 +++++++ scripts/device-testing/perf_harness.py | 40 +- scripts/device-testing/report.py | 90 ++++ scripts/device-testing/scenarios.py | 292 ++++++++++++ .../device-testing/tests/test_fetchgate.py | 172 +++++++ .../tests/test_scenarios_coldfetch.py | 421 ++++++++++++++++++ scripts/device-testing/uidump.py | 8 + 10 files changed, 1310 insertions(+), 8 deletions(-) create mode 100644 scripts/device-testing/fetchgate.py create mode 100644 scripts/device-testing/tests/test_fetchgate.py create mode 100644 scripts/device-testing/tests/test_scenarios_coldfetch.py diff --git a/scripts/device-testing/README.md b/scripts/device-testing/README.md index 506ec6c..0df6c99 100644 --- a/scripts/device-testing/README.md +++ b/scripts/device-testing/README.md @@ -38,6 +38,7 @@ Scenarios (each independently selectable): | `back-nav` | Time reader→mailbox back transitions ×N (dump-latency-bound; see caveat in the report). | | `prefetch-ab` | Run `message-open` under **Fetch all on Wi-Fi** (prefetch ON) vs **Always on-demand** (prefetch OFF), cache cleared between conditions. | | `cross-provider` | Open N messages from the (unified) inbox and tabulate per provider (`imap:…` vs `outlook:…`) from the breadcrumb account refs. | +| `cold-fetch-ab` | Pause-hook cold-vs-warm A/B (**debug build only**). Pre-arm the FETCH_GATE halt, detect sign-in, confirm the halt, let headers sync, measure genuine **cold** opens, `resume`, then measure **warm** (cached) re-opens — reports the delta, the `connect=0ms` reuse proof, and any throttle signature. | Common options: @@ -73,6 +74,34 @@ only as a "content is ready" signal so the driver knows when to move on: `cold-open` instead parses `am start -W`'s `TotalTime` / `WaitTime`. +## Cold-fetch A/B (pause hook) — `cold-fetch-ab` + +Folds in the proven 2026-07-06 cold-vs-warm methodology (issue #405) as a first-class, +reproducible scenario so the connection-reuse / throttle A/B can be re-run on demand to catch +perf regressions. The flow: + +1. **Pre-arm the halt** — broadcast `FETCH_GATE pause backfill,prefetch` *before* sign-in, so + proactive body fetch is gated the instant sync starts (bodies stay uncached). The receiver + echoes its state back as ordered-broadcast result data (`data="paused=[backfill,prefetch]"`), + which the harness parses for a race-free read-back. +2. **Detect sign-in** — tail the log for `MailSyncer: sync all: N accounts` (sign-in is manual; + OAuth can’t be automated, so add the account on the device when prompted). +3. **Confirm the halt** — wait for `prefetch skipped: fetch-gate paused` (proof the gate held). +4. **Wait for header sync** — until uncached message rows appear. +5. **Measure cold opens** — genuine uncached opens (`ImapPerf` connect/work + `MailReader + openMessage fetchedBody=true`). +6. **Resume + measure warm opens** — `FETCH_GATE resume`, then re-open the same messages (now + cached) for the A/B. + +It reports the cold-vs-warm median delta, the **`connect=0ms`** connection-reuse proof, and any +**server-side throttle signature** (a very high cold IMAP `work`). The gate is **always cleared +on exit** (even on error) — the scenario never leaves a device with fetch paused. + +> **Needs a debug build.** The `FETCH_GATE` pause hook (`FetchGateReceiver` / `DebugFetchGate`, +> issues #393/#395) is compiled **only** into `src/debug` and R8-stripped from release, so this +> scenario requires the **debug** APK. A full on-device run is a follow-up; the mocked unit +> tests + `--dry-run` are the automated validation. + ## Output Each run writes a timestamped directory under `--out`: @@ -131,11 +160,18 @@ plus the lockscreen and deskclock-alarm negatives the keyguard/foreground guards - The safety guardrails accept the known-good commands and refuse every forbidden one. - Screen recognition (mailbox rows + cached flag, reader, lockscreen, foreign app). - The report renders the same tables/aggregates as the manual write-up. -- `--dry-run` emits the correct command plan for all five scenarios. +- **Pause-hook helpers** (`fetchgate.py`): the `FETCH_GATE` pause/resume/query broadcast is the + one the safety wrapper accepts, and the ordered-broadcast read-back (`paused=[…]`) parses. +- **Cold-fetch A/B** flow: sign-in / halt-confirm detection, cold/warm open correlation, the + `connect=0ms` reuse proof + throttle signature, and the **always-resume** restore on error. +- `--dry-run` emits the correct command plan for all six scenarios. **Needs the first monitored live run** (a device makes the state real): - End-to-end timing capture on hardware (streamed logcat → per-sample breadcrumb tailing). +- **On-device `cold-fetch-ab` run** (needs a **debug** APK for the `FETCH_GATE` hook): pre-arm → + manual sign-in → cold/warm A/B. The pause/resume broadcasts, read-back parsing, and flow are + validated offline; the live run confirms the timings on real hardware. - **Settings-screen navigation for `prefetch-ab`.** No uiautomator dump of the settings screen was captured in the manual run, so `set_fetch_policy` navigates by the on-screen option text (`"Fetch all on Wi-Fi"`, `"Always on-demand"`, from `res/values/strings.xml`) @@ -155,5 +191,12 @@ plus the lockscreen and deskclock-alarm negatives the keyguard/foreground guards - **Back-nav** timings are dominated by the ~2.5–3 s uiautomator-dump latency floor; the report labels them accordingly (true in-app back is sub-second and not resolvable via adb UI polling under load). +- **Portability (subsumes #392).** The UI dump is **file-based** (`uiautomator dump + /sdcard/window_dump.xml` + `cat`), not `dump /dev/tty`, which interleaves a status banner + with the XML and is unreliable across devices/hosts. All adb output is decoded as **UTF-8** + (and the harness forces `PYTHONUTF8`/UTF-8 console I/O) so non-ASCII sender/subject text + doesn’t mojibake or crash on a Windows cp1252 console. Reader-open readiness is taken from + the `MailReader openMessage` **breadcrumb** (authoritative) rather than UI polling alone, and + row selection **skips non-message rows** (a tappable container with no sender/subject label). - Dev-script convention: Python 3, standard library only, cross-platform (Windows-primary), matching `.claude/skills/preflight/*.py`. diff --git a/scripts/device-testing/adb.py b/scripts/device-testing/adb.py index b0c371d..0dc7d66 100644 --- a/scripts/device-testing/adb.py +++ b/scripts/device-testing/adb.py @@ -33,6 +33,12 @@ from typing import List, Optional, Sequence DEFAULT_PACKAGE = "org.libremail.app" DEFAULT_COMPONENT = "org.libremail.app/org.libremail.MainActivity" +# uiautomator's default public scratch file. The harness dumps the view hierarchy to this +# file and ``cat``s it back (a file-based dump) rather than dumping to ``/dev/tty``: the tty +# path interleaves the "dumped to" status banner with the XML and is unreliable across +# devices/hosts (issue #392). It is public external storage -- never app-private data. +UI_DUMP_DEVICE_PATH = "/sdcard/window_dump.xml" + # adb subcommands the harness is ever allowed to invoke. _ALLOWED_SUBCOMMANDS = frozenset( {"devices", "get-state", "install", "shell", "logcat", "wait-for-device", "start-server"} @@ -227,7 +233,8 @@ class Adb: completed = subprocess.run( argv, capture_output=True, - text=True, + encoding="utf-8", + errors="replace", timeout=timeout if timeout is not None else self.default_timeout, ) result = AdbResult(list(args), completed.returncode, completed.stdout, completed.stderr) @@ -257,6 +264,22 @@ class Adb: args += ["-n", component] return self.run(args) + def broadcast( + self, action: str, component: str, extras: Optional[dict] = None + ) -> AdbResult: + """Send an ``am broadcast`` to ``component`` (constrained to our package by the guard). + + ``extras`` are sent as string extras (``--es ``). Used for the debug + FETCH_GATE pause/resume/query hook (see :mod:`fetchgate`): ``am broadcast`` delivers + ordered, so the receiver echoes its result data back on stdout for a race-free + read-back. The ``-n`` component's package must equal our target package or the + :func:`assert_safe` guard refuses the command. + """ + args = ["shell", "am", "broadcast", "-a", action, "-n", component] + for key, value in (extras or {}).items(): + args += ["--es", str(key), str(value)] + return self.run(args) + def clear_cache(self) -> AdbResult: """Clear ONLY the app's ``cache/`` via run-as. The sole sanctioned mutation.""" return self.run(["shell", "run-as", self.package, "sh", "-c", "rm -rf cache/*"]) @@ -278,8 +301,15 @@ class Adb: return self.run(["shell", "input", "keyevent", str(keycode)]) def uiautomator_dump(self) -> str: - """Return the current window's uiautomator XML (via ``dump /dev/tty``).""" - out = self.run(["shell", "uiautomator", "dump", "/dev/tty"], timeout=90).stdout + """Return the current window's uiautomator XML via a portable file-based dump. + + Dumps to an on-device scratch file (``uiautomator dump ``) and ``cat``s it back + rather than dumping to ``/dev/tty``: the tty path interleaves the "dumped to" status + banner with the XML and is unreliable across devices/hosts (issue #392). The path is + uiautomator's own public default (:data:`UI_DUMP_DEVICE_PATH`), never app storage. + """ + self.run(["shell", "uiautomator", "dump", UI_DUMP_DEVICE_PATH], timeout=90) + out = self.run(["shell", "cat", UI_DUMP_DEVICE_PATH], timeout=30).stdout return _extract_xml(out) # -- screen / keyguard --------------------------------------------------- # @@ -360,7 +390,10 @@ def parse_am_start(output: str) -> dict: def _extract_xml(raw: str) -> str: - """Pull the ```` payload out of ``uiautomator dump /dev/tty`` output.""" + """Pull the ```` payload out of a uiautomator dump's ``cat`` output. + + Tolerant of a leading ``UI hierchary dumped to: `` banner or other noise around the + XML payload (the file-based ``cat``; historically the ``/dev/tty`` output too).""" start = raw.find(" bool: return parsed is not None and parsed.tag in PERF_TAGS +# --------------------------------------------------------------------------- # +# Control-signal line matchers (not perf metrics -- flow signals for the harness) +# --------------------------------------------------------------------------- # +# These are *not* perf breadcrumbs (they carry no timing), so they are deliberately kept out +# of PERF_TAGS / the Event dispatch. The cold-fetch scenario tails the live log for them to +# know when sign-in/sync has started and whether the pre-armed fetch-gate halt took effect. +_SYNC_ALL_RE = re.compile(r"^sync all:\s+(?P\d+)\s+accounts?$") + +# Verbatim from MailSyncer.kt / MailBackfiller.kt when a paused FETCH_GATE skips prefetch. +FETCH_GATE_SKIP_MESSAGE = "prefetch skipped: fetch-gate paused" + + +def match_sync_all(line: str) -> Optional[int]: + """If ``line`` is the ``MailSyncer: sync all: N accounts`` breadcrumb, return N. + + N is the account count logged at the start of a sync pass -- the harness's sign-in / + sync-start signal (a fresh sign-in triggers the first ``syncAll``). Returns ``None`` for + any other line. + """ + log = parse_logcat_line(line) + if log is None or log.tag != "MailSyncer": + return None + m = _SYNC_ALL_RE.match(log.message) + return int(m.group("n")) if m else None + + +def is_fetch_gate_skip(line: str) -> bool: + """True if ``line`` is the debug ``prefetch skipped: fetch-gate paused`` breadcrumb. + + Emitted by ``MailSyncer``/``MailBackfiller`` when a pre-armed FETCH_GATE pause is honoured + -- the harness's proof the halt actually took effect (bodies will stay uncached). + """ + log = parse_logcat_line(line) + return ( + log is not None + and log.tag in ("MailSyncer", "MailBackfiller") + and log.message == FETCH_GATE_SKIP_MESSAGE + ) + + # --------------------------------------------------------------------------- # # Typed breadcrumb events # --------------------------------------------------------------------------- # diff --git a/scripts/device-testing/fetchgate.py b/scripts/device-testing/fetchgate.py new file mode 100644 index 0000000..f0f00c2 --- /dev/null +++ b/scripts/device-testing/fetchgate.py @@ -0,0 +1,169 @@ +#!/usr/bin/env python3 +# SPDX-License-Identifier: GPL-3.0-or-later +"""fetchgate.py -- the debug FETCH_GATE pause-hook helpers. + +Thin, testable wrapper around the debug-only ``FetchGateReceiver`` broadcast hook +(issues #393/#395) that lets the perf harness pause/resume the app's *proactive* body-fetch +activities (``backfill`` + ``prefetch``) so a genuinely uncached message-open can be measured. +Everything goes through the guarded :class:`adb.Adb` wrapper, so the device-safety guardrails +apply unchanged (the broadcast targets our own package/component; nothing destructive). + +The broadcast the harness sends (delivered *ordered*, targeted by ``-n`` so it needs no +````):: + + adb shell am broadcast -a org.libremail.debug.FETCH_GATE \ + -n org.libremail.app/org.libremail.debug.FetchGateReceiver \ + --es action --es scope backfill,prefetch + +Because ``am broadcast`` delivers ordered, the receiver returns the resulting gate state as +result data, which ``am`` prints, e.g.:: + + Broadcast completed: result=0, data="paused=[backfill,prefetch]" + +:func:`parse_broadcast_result` turns that into a typed :class:`BroadcastResult` for a +synchronous, race-free read-back. **This hook only exists in a debug build** -- it is declared +solely in ``app/src/debug`` and R8-stripped from release -- so the cold-fetch scenario needs a +debug APK installed. +""" + +from __future__ import annotations + +import re +from dataclasses import dataclass +from typing import Callable, FrozenSet, Optional + +# Wire constants -- mirror FetchGateReceiver / FetchScope in the app source. +FETCH_GATE_ACTION = "org.libremail.debug.FETCH_GATE" +FETCH_GATE_RECEIVER = "org.libremail.debug.FetchGateReceiver" + +ACTION_PAUSE = "pause" +ACTION_RESUME = "resume" +ACTION_QUERY = "query" + +# The two proactive scopes the harness pauses to keep bodies uncached (FetchScope wire names). +SCOPE_BACKFILL = "backfill" +SCOPE_PREFETCH = "prefetch" +DEFAULT_SCOPE = f"{SCOPE_BACKFILL},{SCOPE_PREFETCH}" + + +# --------------------------------------------------------------------------- # +# Read-back parsing (pure; unit-tested) +# --------------------------------------------------------------------------- # +# `am broadcast` prints e.g. `Broadcast completed: result=0, data="paused=[backfill,prefetch]"`. +# Parsed in two steps so a trailing `, extras: ...` (absent here, but possible) can't be +# swallowed into the data payload: match the result code, then the quoted data separately. +_RESULT_RE = re.compile(r"Broadcast completed:\s*result=(?P-?\d+)") +_DATA_RE = re.compile(r'data="(?P[^"]*)"') +# The receiver's result-data payload: `paused=[]`. +_PAUSED_RE = re.compile(r"paused=\[(?P[^\]]*)\]") + + +@dataclass(frozen=True) +class BroadcastResult: + """The parsed outcome of one FETCH_GATE ``am broadcast`` read-back. + + * ``result_code`` -- the ordered-broadcast result code (``0`` from the receiver), or + ``None`` if the ``Broadcast completed:`` line was absent (e.g. dry-run / no read-back). + * ``data`` -- the raw result-data payload (``paused=[backfill,prefetch]``) or ``None``. + * ``paused`` -- the scope wire-names parsed out of ``data`` (``frozenset``; empty when the + gate is clear or unparseable). + """ + + result_code: Optional[int] + data: Optional[str] + paused: FrozenSet[str] + + @property + def read_back(self) -> bool: + """True iff a real ``Broadcast completed: ... data=...`` read-back was parsed.""" + return self.data is not None + + def is_paused(self, scope: str) -> bool: + return scope in self.paused + + +def parse_paused_scopes(data: Optional[str]) -> FrozenSet[str]: + """Parse ``paused=[backfill,prefetch]`` -> ``{"backfill", "prefetch"}`` (empty if none).""" + if not data: + return frozenset() + m = _PAUSED_RE.search(data) + if not m: + return frozenset() + inner = m.group("scopes").strip() + if not inner: + return frozenset() + return frozenset(tok.strip() for tok in inner.split(",") if tok.strip()) + + +def parse_broadcast_result(output: str) -> BroadcastResult: + """Parse ``am broadcast`` stdout into a :class:`BroadcastResult`. + + Tolerant of surrounding lines (the ``Broadcasting: Intent {...}`` echo) and of a missing + ``data=`` (a non-read-back send); returns an all-empty result when no completion line is + present (e.g. dry-run stdout is empty). + """ + if not output: + return BroadcastResult(result_code=None, data=None, paused=frozenset()) + code: Optional[int] = None + data: Optional[str] = None + for line in output.splitlines(): + m = _RESULT_RE.search(line) + if not m: + continue + code = int(m.group("code")) + dm = _DATA_RE.search(line) + if dm: + data = dm.group("data") + break + return BroadcastResult(result_code=code, data=data, paused=parse_paused_scopes(data)) + + +# --------------------------------------------------------------------------- # +# The pause-hook helper (drives the guarded adb wrapper) +# --------------------------------------------------------------------------- # +def _noop(_msg: str) -> None: + pass + + +class FetchGate: + """Pause/resume/query the debug FETCH_GATE through a guarded :class:`adb.Adb`. + + Construct with the harness's ``Adb`` (its ``package`` fixes the broadcast component and is + enforced by the safety guard). Each call sends the broadcast and returns the parsed + :class:`BroadcastResult` read-back. In dry-run the underlying ``adb`` prints the command + plan and returns empty stdout, so the result is an all-empty (no read-back) record. + """ + + def __init__( + self, + adb, + receiver: str = FETCH_GATE_RECEIVER, + action: str = FETCH_GATE_ACTION, + log: Optional[Callable[[str], None]] = None, + ) -> None: + self.adb = adb + self.action = action + # `-n /` (assert_safe requires the component package == adb.package). + self.component = f"{adb.package}/{receiver}" + self._log = log or _noop + + def _send(self, gate_action: str, scope: str) -> BroadcastResult: + res = self.adb.broadcast( + self.action, self.component, {"action": gate_action, "scope": scope} + ) + parsed = parse_broadcast_result(res.stdout) + shown = parsed.data if parsed.read_back else "(no read-back)" + self._log(f"fetch-gate {gate_action} scope={scope} -> {shown}") + return parsed + + def pause(self, scope: str = DEFAULT_SCOPE) -> BroadcastResult: + """Pause the given proactive-fetch scope(s); returns the read-back gate state.""" + return self._send(ACTION_PAUSE, scope) + + def resume(self, scope: str = DEFAULT_SCOPE) -> BroadcastResult: + """Resume (clear) the given scope(s); returns the read-back gate state.""" + return self._send(ACTION_RESUME, scope) + + def query(self, scope: str = DEFAULT_SCOPE) -> BroadcastResult: + """Query the current gate state without changing it; returns the read-back.""" + return self._send(ACTION_QUERY, scope) diff --git a/scripts/device-testing/perf_harness.py b/scripts/device-testing/perf_harness.py index c91c633..d4f83d6 100644 --- a/scripts/device-testing/perf_harness.py +++ b/scripts/device-testing/perf_harness.py @@ -10,6 +10,7 @@ repeatable, cross-platform, standard-library-only tool. Run one scenario at a ti python scripts/device-testing/perf_harness.py back-nav [opts] python scripts/device-testing/perf_harness.py prefetch-ab [opts] python scripts/device-testing/perf_harness.py cross-provider [opts] + python scripts/device-testing/perf_harness.py cold-fetch-ab [opts] # needs a debug build Common options: ``--serial`` (auto-detected if exactly one device), ``--count/-n``, ``--out``, ``--package``, ``--component``, ``--adb``, and ``--dry-run`` (print the exact @@ -33,20 +34,47 @@ from typing import List, Optional # tests inject it explicitly. (The dir name contains a hyphen, so it is not an importable # package -- hence flat modules rather than `python -m`.) import breadcrumbs +import fetchgate import report import scenarios from adb import Adb, DEFAULT_COMPONENT, DEFAULT_PACKAGE -SCENARIOS = ("cold-open", "message-open", "back-nav", "prefetch-ab", "cross-provider") +SCENARIOS = ( + "cold-open", + "message-open", + "back-nav", + "prefetch-ab", + "cross-provider", + "cold-fetch-ab", +) _DEFAULT_COUNTS = { "cold-open": 5, "message-open": 6, "back-nav": 6, "prefetch-ab": 3, "cross-provider": 8, + "cold-fetch-ab": 3, } +def _configure_utf8_io() -> None: + """Force UTF-8 for this process and its console (issue #392). + + Non-ASCII sender/subject text in a uiautomator dump -- and the harness's own output on a + Windows cp1252 console -- otherwise mojibake or raise ``UnicodeEncodeError``. adb output is + already decoded UTF-8 in :meth:`adb.Adb.run`; this covers the interpreter and console. + """ + os.environ.setdefault("PYTHONUTF8", "1") + os.environ.setdefault("PYTHONIOENCODING", "utf-8") + for stream in (sys.stdout, sys.stderr): + reconfigure = getattr(stream, "reconfigure", None) + if reconfigure is not None: + try: + reconfigure(encoding="utf-8", errors="replace") + except (ValueError, OSError): # pragma: no cover - stream already detached + pass + + def _make_logger(log_path: Optional[str]): handle = open(log_path, "a", encoding="utf-8") if log_path else None @@ -125,6 +153,8 @@ def _render_sections(scenario: str, results, adb: Adb, count: int) -> List[str]: if not sections: sections.append("## Cross-provider\n\nNo opens captured.\n") return sections + if scenario == "cold-fetch-ab": + return [report.render_cold_fetch_ab(results)] return [] @@ -142,7 +172,7 @@ def _ab_comparison(results: dict) -> str: ) -def _run_scenario(scenario: str, adb: Adb, tailer, args, log): +def _run_scenario(scenario: str, adb: Adb, tailer, gate, args, log): package, component, count = args.package, args.component, args.count if scenario == "cold-open": return scenarios.cold_open(adb, component, count, log) @@ -154,6 +184,8 @@ def _run_scenario(scenario: str, adb: Adb, tailer, args, log): return scenarios.prefetch_ab(adb, package, component, tailer, count, log) if scenario == "cross-provider": return scenarios.cross_provider(adb, package, tailer, count, log) + if scenario == "cold-fetch-ab": + return scenarios.cold_fetch_ab(adb, package, component, tailer, gate, count, log) raise SystemExit(f"unknown scenario {scenario!r}") @@ -183,6 +215,7 @@ def build_arg_parser() -> argparse.ArgumentParser: def main(argv: Optional[List[str]] = None) -> int: + _configure_utf8_io() args = build_arg_parser().parse_args(argv) if args.count is None: args.count = _DEFAULT_COUNTS[args.scenario] @@ -206,6 +239,7 @@ def main(argv: Optional[List[str]] = None) -> int: dry_run=args.dry_run, logger=log, ) + gate = fetchgate.FetchGate(adb, log=log) logcat_proc = None raw_handle = None @@ -220,7 +254,7 @@ def main(argv: Optional[List[str]] = None) -> int: scenarios.ensure_awake(adb, log) time.sleep(1.0) - results = _run_scenario(args.scenario, adb, tailer, args, log) + results = _run_scenario(args.scenario, adb, tailer, gate, args, log) sections = _render_sections(args.scenario, results, adb, args.count) finally: Adb.stop_logcat(logcat_proc) diff --git a/scripts/device-testing/report.py b/scripts/device-testing/report.py index 6fd0212..9ca105f 100644 --- a/scripts/device-testing/report.py +++ b/scripts/device-testing/report.py @@ -19,6 +19,10 @@ from breadcrumbs import OpenSample # (see perf_summary.md: nav/back were dominated by the ~2.5-3 s dump latency). UIAUTOMATOR_LATENCY_FLOOR_MS = 3000 +# A cold IMAP ``work`` time at/above this reads as a server-side throttle signature (the manual +# Gmail run saw 26-72 s of work vs Outlook's sub-second control). +THROTTLE_WORK_MS = 10000 + # --------------------------------------------------------------------------- # # Stats + markdown helpers @@ -237,6 +241,92 @@ def render_back_nav(samples: Sequence[BackNavSample]) -> str: return "## Reader -> mailbox (back)\n\n" + table + summary + caveat + "\n" +# --------------------------------------------------------------------------- # +# Cold-fetch pause-hook A/B (issue #405) +# --------------------------------------------------------------------------- # +def _gate_data(state) -> str: + """The read-back payload of a fetchgate ``BroadcastResult`` (duck-typed), for display.""" + if state is None: + return "(none)" + data = getattr(state, "data", None) + return data if data else "(no read-back)" + + +def _uncached_took(rows: Sequence["ReaderOpenRow"]) -> List[int]: + return [r.took_ms for r in rows if not r.skipped and r.took_ms is not None] + + +def render_gate_summary(results: dict) -> str: + """Render the FETCH_GATE control summary: pre-arm, sign-in, halt-confirm, restore.""" + accounts = results.get("sign_in_accounts") + sign_in = f"yes ({accounts} account(s))" if accounts is not None else "no / not detected" + lines = [ + "## Fetch-gate A/B control", + "", + f"- Pre-armed halt read-back: `{_gate_data(results.get('gate_prearm'))}`", + f"- Sign-in detected (sync all breadcrumb): {sign_in}", + "- Halt confirmed (prefetch-skipped breadcrumb): " + + ("yes" if results.get("gate_confirmed") else "no"), + "- Header sync ready: " + ("yes" if results.get("header_ready") else "no"), + f"- Gate restored/cleared read-back: `{_gate_data(results.get('gate_restored'))}`", + "", + "> The pause hook is **debug-build-only** (#393/#395): the scenario needs a debug APK.", + "", + ] + return "\n".join(lines) + + +def render_cold_warm_comparison( + cold: Sequence["ReaderOpenRow"], warm: Sequence["ReaderOpenRow"] +) -> str: + """Render the cold-vs-warm delta, the connect=0ms reuse proof, and any throttle signature.""" + cold_agg = aggregate(_uncached_took(cold)) + warm_agg = aggregate(_uncached_took(warm)) + lines = ["## Cold vs warm (A/B)", ""] + lines.append( + f"- Cold median openMessage: {_ms(cold_agg.median)} ms (n={cold_agg.n})" + ) + lines.append( + f"- Warm median openMessage: {_ms(warm_agg.median)} ms (n={warm_agg.n})" + ) + if cold_agg.median and warm_agg.median: + lines.append( + f"- Speedup (cold/warm median): {cold_agg.median / warm_agg.median:.1f}x" + ) + + # connect=0ms connection-reuse proof (from the cold opens' ImapPerf op). + connects = [r.connect_ms for r in cold if not r.skipped and r.connect_ms is not None] + if connects: + zero = [c for c in connects if c == 0] + proof = "reuse active" if zero else "no reuse observed" + lines.append( + f"- Connection reuse: connect=0ms on {len(zero)}/{len(connects)} " + f"cold opens ({proof})" + ) + + # Throttle signature -- a very high cold IMAP work time. + works = [r.work_ms for r in cold if not r.skipped and r.work_ms is not None] + if works: + peak = max(works) + note = " -- server-side throttle signature" if peak >= THROTTLE_WORK_MS else "" + lines.append(f"- Peak cold IMAP work: {peak} ms{note}") + lines.append("") + return "\n".join(lines) + + +def render_cold_fetch_ab(results: dict) -> str: + """Assemble the whole cold-fetch A/B section: control summary, cold/warm tables, A/B delta.""" + cold = results.get("cold", []) + warm = results.get("warm", []) + parts = [ + render_gate_summary(results), + render_message_open("Cold opens (fetch-gate paused, uncached bodies)", cold), + render_message_open("Warm opens (gate resumed, cached re-open)", warm), + render_cold_warm_comparison(cold, warm), + ] + return "\n".join(parts) + + # --------------------------------------------------------------------------- # # Document assembly # --------------------------------------------------------------------------- # diff --git a/scripts/device-testing/scenarios.py b/scripts/device-testing/scenarios.py index 136d106..5abc3c5 100644 --- a/scripts/device-testing/scenarios.py +++ b/scripts/device-testing/scenarios.py @@ -25,6 +25,7 @@ import time from typing import Callable, List, Optional import breadcrumbs +import fetchgate import uidump from adb import Adb, parse_am_start from report import BackNavSample, ColdOpenSample, ReaderOpenRow @@ -35,6 +36,13 @@ OPEN_TIMEOUT_S = 150.0 POLL_INTERVAL_S = 2.0 SETTLE_S = 1.5 +# Cold-fetch A/B: waiting for a human-driven sign-in, then for header sync, then for the +# pre-armed halt's confirming breadcrumb. Sign-in is manual (OAuth can't be automated), so +# it gets the most headroom. +SIGN_IN_TIMEOUT_S = 300.0 +GATE_CONFIRM_TIMEOUT_S = 120.0 +HEADER_SYNC_TIMEOUT_S = 180.0 + # Fetch-policy option labels (from res/values/strings.xml) used to drive the A/B toggle. FETCH_WIFI_LABEL = "Fetch all on Wi-Fi" # prefetch ON (Condition A / WIFI_ONLY) FETCH_ON_DEMAND_LABEL = "Always on-demand" # prefetch OFF (Condition B / ON_DEMAND) @@ -443,3 +451,287 @@ def cross_provider( key = row.account_ref or "unknown" buckets.setdefault(key, []).append(row) return buckets + + +# --------------------------------------------------------------------------- # +# Scenario 6: cold-fetch pause-hook A/B (issue #405) +# --------------------------------------------------------------------------- # +# The proven flow (2026-07-06): pre-arm the FETCH_GATE halt BEFORE sign-in so proactive body +# fetch is gated the instant sync starts; detect sign-in; confirm the halt took effect; let +# headers sync (bodies stay uncached); measure genuine COLD opens; resume the gate; measure +# WARM (cached) re-opens of the same messages; report the cold-vs-warm delta, the connect=0ms +# connection-reuse proof, and any server-side throttle signature. Needs a **debug build** -- +# the pause hook (#393/#395) is compiled only into src/debug and R8-stripped from release. + + +def wait_for_open_breadcrumb( + tailer: LogTailer, timeout_s: float, log: Callable[[str], None] +) -> List[breadcrumbs.Event]: + """Poll the tail until a ``MailReader openMessage`` breadcrumb lands; return every event. + + An ``openMessage`` marker is the authoritative "the reader open finished" signal -- far + more reliable than UI polling for a spinner under load (issue #392). All perf events seen + (the ``ImapPerf``/``body-fetch`` lines precede the marker) are returned so the caller can + correlate the full open without re-reading -- draining them here would lose them. + """ + deadline = time.monotonic() + timeout_s + collected: List[breadcrumbs.Event] = [] + while True: + for line in tailer.read_new().splitlines(): + event = breadcrumbs.parse_breadcrumb(line) + if event is not None: + collected.append(event) + if any(isinstance(e, breadcrumbs.OpenMessage) for e in collected): + return collected + if time.monotonic() >= deadline: + log("openMessage breadcrumb not seen before timeout") + return collected + time.sleep(POLL_INTERVAL_S) + + +def wait_for_sign_in( + tailer: LogTailer, timeout_s: float, log: Callable[[str], None] +) -> Optional[int]: + """Tail the log until the ``MailSyncer: sync all: N accounts`` breadcrumb; return N. + + Sign-in is manual on the device (OAuth can't be automated), so this simply waits for the + first sync pass a fresh sign-in kicks off. ``None`` on timeout. + """ + deadline = time.monotonic() + timeout_s + while True: + for line in tailer.read_new().splitlines(): + accounts = breadcrumbs.match_sync_all(line) + if accounts is not None: + log(f"sign-in detected: sync all: {accounts} account(s)") + return accounts + if time.monotonic() >= deadline: + log("sign-in not detected within timeout") + return None + time.sleep(POLL_INTERVAL_S) + + +def wait_for_gate_skip( + tailer: LogTailer, timeout_s: float, log: Callable[[str], None] +) -> bool: + """Tail until the ``prefetch skipped: fetch-gate paused`` breadcrumb proves the halt held.""" + deadline = time.monotonic() + timeout_s + while True: + for line in tailer.read_new().splitlines(): + if breadcrumbs.is_fetch_gate_skip(line): + log("fetch-gate halt confirmed: prefetch skipped") + return True + if time.monotonic() >= deadline: + log("fetch-gate skip breadcrumb not seen (halt unconfirmed)") + return False + time.sleep(POLL_INTERVAL_S) + + +def wait_for_header_sync( + adb: Adb, package: str, timeout_s: float, log: Callable[[str], None] +) -> bool: + """Poll the mailbox until at least one uncached message row is visible (headers synced).""" + deadline = time.monotonic() + timeout_s + while True: + root = goto_mailbox(adb, package, log) + if root is not None: + rows = uidump.find_message_rows(root, package) + uncached = [r for r in rows if not r.cached] + if uncached: + log(f"header sync ready: {len(uncached)} uncached row(s) visible") + return True + if time.monotonic() >= deadline: + log("header sync not confirmed within timeout") + return False + time.sleep(POLL_INTERVAL_S) + + +def _open_target( + adb: Adb, + package: str, + tailer: LogTailer, + index: int, + label: str, + center: Optional[tuple], + log: Callable[[str], None], +) -> ReaderOpenRow: + """Tap a known message row, time the open from the ``openMessage`` breadcrumb, go back.""" + if center is None: + return ReaderOpenRow(index=index, label=label, skipped=True, reason="no tap target") + tailer.mark() + log(f"opening #{index} {label!r} at {center}") + adb.input_tap(*center) + events = wait_for_open_breadcrumb(tailer, OPEN_TIMEOUT_S, log) + row = _row_from_events(index, label, events) + if not any(isinstance(e, breadcrumbs.OpenMessage) for e in events) and not row.skipped: + row.skipped = True + row.reason = "no openMessage breadcrumb" + adb.input_keyevent("KEYCODE_BACK") + time.sleep(SETTLE_S) + return row + + +def _next_uncached( + adb: Adb, package: str, already: set, log: Callable[[str], None] +) -> Optional[uidump.MessageRow]: + """The next not-yet-opened uncached mailbox row (scrolling once to reveal more).""" + root = goto_mailbox(adb, package, log) + if root is None: + return None + rows = uidump.find_message_rows(root, package) + cands = [r for r in rows if not r.cached and r.label not in already] + if cands: + return cands[0] + adb.input_swipe(672, 2000, 672, 900, 400) + time.sleep(SETTLE_S) + root = guard_ready(adb, package, log) + if root is None: + return None + cands = [ + r + for r in uidump.find_message_rows(root, package) + if not r.cached and r.label not in already + ] + return cands[0] if cands else None + + +def measure_cold_opens( + adb: Adb, + package: str, + tailer: LogTailer, + count: int, + log: Callable[[str], None], +) -> tuple: + """Open up to ``count`` distinct uncached messages; return ``(rows, [(label, center)])``. + + The ``(label, center)`` list identifies exactly which messages to re-open for the warm + phase. + """ + rows: List[ReaderOpenRow] = [] + opened: List[tuple] = [] + already: set = set() + for i in range(1, count + 1): + target = _next_uncached(adb, package, already, log) + if target is None: + log("no more uncached messages to open (cold phase)") + break + already.add(target.label) + rows.append(_open_target(adb, package, tailer, i, target.label, target.center, log)) + opened.append((target.label, target.center)) + return rows, opened + + +def measure_warm_opens( + adb: Adb, + package: str, + tailer: LogTailer, + opened: List[tuple], + log: Callable[[str], None], +) -> List[ReaderOpenRow]: + """Re-open each message from :func:`measure_cold_opens`; bodies are now cached (warm).""" + rows: List[ReaderOpenRow] = [] + for i, (label, center) in enumerate(opened, start=1): + # Re-find the row by label for a fresh centre (the list may have shifted); fall back + # to the cold-phase centre. + tgt_center = center + root = goto_mailbox(adb, package, log) + if root is not None: + for r in uidump.find_message_rows(root, package): + if r.label == label: + tgt_center = r.center + break + rows.append(_open_target(adb, package, tailer, i, label, tgt_center, log)) + return rows + + +def _gate_shown(state) -> str: + """The read-back payload for a log line (duck-typed on the fetchgate BroadcastResult).""" + if state is not None and getattr(state, "read_back", False): + return state.data + return "(no read-back)" + + +def cold_fetch_ab( + adb: Adb, + package: str, + component: str, + tailer: LogTailer, + gate: "fetchgate.FetchGate", + count: int, + log: Callable[[str], None], + sign_in_timeout_s: float = SIGN_IN_TIMEOUT_S, + gate_confirm_timeout_s: float = GATE_CONFIRM_TIMEOUT_S, + header_sync_timeout_s: float = HEADER_SYNC_TIMEOUT_S, +) -> dict: + """Cold-fetch pause-hook A/B: pre-arm halt, sign-in, cold opens, resume, warm opens. + + ALWAYS clears the gate at the end (``finally``) so a device is never left with proactive + fetch paused, even on error. + """ + results: dict = { + "gate_prearm": None, + "sign_in_accounts": None, + "gate_confirmed": False, + "header_ready": False, + "cold": [], + "warm": [], + "gate_resume": None, + "gate_restored": None, + } + try: + # 1. Pre-arm the halt BEFORE sign-in so proactive fetch is gated as soon as sync starts. + log(f"pre-arming fetch-gate halt (pause {fetchgate.DEFAULT_SCOPE})") + results["gate_prearm"] = gate.pause(fetchgate.DEFAULT_SCOPE) + log(f"pre-armed halt read-back: {_gate_shown(results['gate_prearm'])}") + + if adb.dry_run: + _dry_run_cold_fetch_demo(adb, gate, log) + results["cold"] = [ + ReaderOpenRow(index=1, label="", skipped=True, reason="dry-run") + ] + results["warm"] = [ + ReaderOpenRow(index=1, label="", skipped=True, reason="dry-run") + ] + return results + + # 2. Detect the manual sign-in via the sync-start breadcrumb. + log("waiting for sign-in (add an account on the device now)") + results["sign_in_accounts"] = wait_for_sign_in(tailer, sign_in_timeout_s, log) + # 3. Confirm the pre-armed halt actually took effect. + results["gate_confirmed"] = wait_for_gate_skip(tailer, gate_confirm_timeout_s, log) + # 4. Wait for header sync so uncached rows exist to open. + results["header_ready"] = wait_for_header_sync( + adb, package, header_sync_timeout_s, log + ) + # 5. Measure COLD opens -- bodies uncached because prefetch is gated. + log("measuring cold opens (uncached bodies)") + cold_rows, opened = measure_cold_opens(adb, package, tailer, count, log) + results["cold"] = cold_rows + # 6. Resume (restore normal fetch), then measure WARM re-opens of the same messages. + log(f"resuming fetch-gate before warm phase (resume {fetchgate.DEFAULT_SCOPE})") + results["gate_resume"] = gate.resume(fetchgate.DEFAULT_SCOPE) + log("measuring warm opens (cached re-open of the same messages)") + results["warm"] = measure_warm_opens(adb, package, tailer, opened, log) + finally: + # Restore semantics: ALWAYS clear the gate, even on error -- never leave fetch paused. + results["gate_restored"] = gate.resume(fetchgate.DEFAULT_SCOPE) + log(f"fetch-gate restored (cleared): {_gate_shown(results['gate_restored'])}") + return results + + +def _dry_run_cold_fetch_demo( + adb: Adb, gate: "fetchgate.FetchGate", log: Callable[[str], None] +) -> None: + """Issue the canonical cold-fetch A/B command shape once (dry-run only). + + The pre-arm ``pause`` and the final restoring ``resume`` are issued by :func:`cold_fetch_ab` + itself (the latter in its ``finally``); this fills in a representative cold open, the + warm-phase ``resume``, a warm re-open, and a state ``query`` so the whole plan is auditable. + """ + adb.uiautomator_dump() + adb.input_tap(672, 504) # cold-open a representative message row + adb.input_keyevent("KEYCODE_BACK") + gate.resume(fetchgate.DEFAULT_SCOPE) # restore normal fetch before the warm phase + adb.uiautomator_dump() + adb.input_tap(672, 504) # warm re-open (now cached) + adb.input_keyevent("KEYCODE_BACK") + gate.query(fetchgate.DEFAULT_SCOPE) # confirm the gate state diff --git a/scripts/device-testing/tests/test_fetchgate.py b/scripts/device-testing/tests/test_fetchgate.py new file mode 100644 index 0000000..4414844 --- /dev/null +++ b/scripts/device-testing/tests/test_fetchgate.py @@ -0,0 +1,172 @@ +# SPDX-License-Identifier: GPL-3.0-or-later +"""Tests for the debug FETCH_GATE pause-hook helpers (issue #405). + +Cover the ordered-broadcast read-back parser and the :class:`fetchgate.FetchGate` wrapper, +mocking adb so the pause/resume/query flow is exercised without a device. The fake adb runs +the *real* :func:`adb.assert_safe` guard on every broadcast, so these tests also prove the +FETCH_GATE command the harness builds is one the safety wrapper accepts. +""" + +import os +import sys +import unittest + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +import adb # noqa: E402 +import fetchgate # noqa: E402 +from adb import Adb, AdbSafetyError # noqa: E402 + +PKG = "org.libremail.app" + +# A verbatim `am broadcast` read-back from the debug FetchGateReceiver (ordered delivery). +COMPLETED_PAUSED = ( + "Broadcasting: Intent { act=org.libremail.debug.FETCH_GATE flg=0x400000 " + "cmp=org.libremail.app/org.libremail.debug.FetchGateReceiver (has extras) }\n" + 'Broadcast completed: result=0, data="paused=[backfill,prefetch]"\n' +) +COMPLETED_CLEARED = 'Broadcast completed: result=0, data="paused=[]"\n' + + +class RecordingAdb: + """A fake Adb that validates every broadcast through the real guard, records it, and + returns canned ``am broadcast`` stdout -- FetchGate end-to-end without a device.""" + + def __init__(self, package=PKG, stdout=""): + self.package = package + self.dry_run = False + self.calls = [] + self.stdout = stdout + + def broadcast(self, action, component, extras=None): + args = ["shell", "am", "broadcast", "-a", action, "-n", component] + for key, value in (extras or {}).items(): + args += ["--es", str(key), str(value)] + adb.assert_safe(self.package, args) # real guard -- raises on anything unsafe + self.calls.append(args) + return adb.AdbResult(args, 0, self.stdout, "") + + +class TestParsePausedScopes(unittest.TestCase): + def test_two_scopes(self): + self.assertEqual( + fetchgate.parse_paused_scopes("paused=[backfill,prefetch]"), + frozenset({"backfill", "prefetch"}), + ) + + def test_single_scope(self): + self.assertEqual(fetchgate.parse_paused_scopes("paused=[backfill]"), frozenset({"backfill"})) + + def test_empty_gate(self): + self.assertEqual(fetchgate.parse_paused_scopes("paused=[]"), frozenset()) + + def test_none_and_garbage(self): + self.assertEqual(fetchgate.parse_paused_scopes(None), frozenset()) + self.assertEqual(fetchgate.parse_paused_scopes(""), frozenset()) + self.assertEqual(fetchgate.parse_paused_scopes("no brackets here"), frozenset()) + + +class TestParseBroadcastResult(unittest.TestCase): + def test_paused_read_back(self): + res = fetchgate.parse_broadcast_result(COMPLETED_PAUSED) + self.assertEqual(res.result_code, 0) + self.assertEqual(res.data, "paused=[backfill,prefetch]") + self.assertEqual(res.paused, frozenset({"backfill", "prefetch"})) + self.assertTrue(res.read_back) + self.assertTrue(res.is_paused("prefetch")) + + def test_cleared_read_back(self): + res = fetchgate.parse_broadcast_result(COMPLETED_CLEARED) + self.assertEqual(res.result_code, 0) + self.assertEqual(res.data, "paused=[]") + self.assertEqual(res.paused, frozenset()) + self.assertTrue(res.read_back) + self.assertFalse(res.is_paused("backfill")) + + def test_completion_without_data(self): + res = fetchgate.parse_broadcast_result("Broadcast completed: result=0") + self.assertEqual(res.result_code, 0) + self.assertIsNone(res.data) + self.assertEqual(res.paused, frozenset()) + self.assertFalse(res.read_back) + + def test_trailing_extras_not_swallowed(self): + line = 'Broadcast completed: result=0, data="paused=[backfill]", extras: Bundle[...]' + res = fetchgate.parse_broadcast_result(line) + self.assertEqual(res.data, "paused=[backfill]") + self.assertEqual(res.paused, frozenset({"backfill"})) + + def test_empty_output_is_no_read_back(self): + res = fetchgate.parse_broadcast_result("") + self.assertIsNone(res.result_code) + self.assertIsNone(res.data) + self.assertFalse(res.read_back) + + +class TestFetchGateHelper(unittest.TestCase): + def test_pause_builds_targeted_broadcast_and_parses(self): + fake = RecordingAdb(stdout=COMPLETED_PAUSED) + gate = fetchgate.FetchGate(fake) + state = gate.pause() + self.assertEqual(state.paused, frozenset({"backfill", "prefetch"})) + self.assertEqual(len(fake.calls), 1) + args = fake.calls[0] + # Correct action, component (our package) and default scope on the wire. + self.assertEqual(args[:5], ["shell", "am", "broadcast", "-a", fetchgate.FETCH_GATE_ACTION]) + self.assertIn("-n", args) + self.assertEqual(args[args.index("-n") + 1], f"{PKG}/{fetchgate.FETCH_GATE_RECEIVER}") + self.assertIn("pause", args) + self.assertIn("backfill,prefetch", args) + + def test_resume_and_query_actions(self): + fake = RecordingAdb(stdout=COMPLETED_CLEARED) + gate = fetchgate.FetchGate(fake) + self.assertEqual(gate.resume().paused, frozenset()) + self.assertIn("resume", fake.calls[-1]) + gate.query() + self.assertIn("query", fake.calls[-1]) + + def test_custom_scope_passed_through(self): + fake = RecordingAdb(stdout=COMPLETED_CLEARED) + gate = fetchgate.FetchGate(fake) + gate.pause("backfill") + self.assertIn("backfill", fake.calls[-1]) + self.assertNotIn("backfill,prefetch", fake.calls[-1]) + + def test_logs_read_back(self): + fake = RecordingAdb(stdout=COMPLETED_PAUSED) + logged = [] + gate = fetchgate.FetchGate(fake, log=logged.append) + gate.pause() + self.assertTrue(any("paused=[backfill,prefetch]" in m for m in logged)) + + +class TestFetchGateThroughRealGuardedAdb(unittest.TestCase): + """FetchGate over a real dry-run Adb: the guard runs, the exact plan is logged, no device.""" + + def test_dry_run_issues_safe_command_and_no_read_back(self): + logged = [] + real = Adb(serial="SERIAL1", package=PKG, dry_run=True, logger=logged.append) + gate = fetchgate.FetchGate(real, log=logged.append) + state = gate.pause() + # Dry-run has no stdout -> no read-back, but also no exception (command was safe). + self.assertFalse(state.read_back) + plan = "\n".join(logged) + self.assertIn("am broadcast", plan) + self.assertIn("-a org.libremail.debug.FETCH_GATE", plan) + self.assertIn(f"{PKG}/{fetchgate.FETCH_GATE_RECEIVER}", plan) + self.assertIn("--es action pause", plan) + self.assertIn("--es scope backfill,prefetch", plan) + + def test_foreign_component_is_refused_by_guard(self): + real = Adb(package=PKG, dry_run=True) + gate = fetchgate.FetchGate(real, receiver="com.other.app/.Evil") + # component becomes "org.libremail.app/com.other.app/.Evil" -> comp pkg still ours, + # so instead assert a genuinely foreign package target is refused: + gate.component = "com.other.app/org.libremail.debug.FetchGateReceiver" + with self.assertRaises(AdbSafetyError): + gate.pause() + + +if __name__ == "__main__": + unittest.main() diff --git a/scripts/device-testing/tests/test_scenarios_coldfetch.py b/scripts/device-testing/tests/test_scenarios_coldfetch.py new file mode 100644 index 0000000..a7c1246 --- /dev/null +++ b/scripts/device-testing/tests/test_scenarios_coldfetch.py @@ -0,0 +1,421 @@ +# SPDX-License-Identifier: GPL-3.0-or-later +"""Tests for the cold-fetch pause-hook A/B scenario (issue #405). + +Everything runs against fakes (adb / breadcrumb tailer / fetch-gate) so the whole flow -- +pre-arm halt, sign-in detection, halt confirmation, cold opens, resume, warm opens, and the +always-resume restore -- is exercised without a device, plus the ``--dry-run`` path end to end +through :func:`perf_harness.main`. +""" + +import contextlib +import glob +import io +import os +import sys +import tempfile +import unittest +from unittest.mock import patch + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +import breadcrumbs # noqa: E402 +import fetchgate # noqa: E402 +import perf_harness # noqa: E402 +import report # noqa: E402 +import scenarios # noqa: E402 +import uidump # noqa: E402 +from report import ReaderOpenRow # noqa: E402 + +PKG = "org.libremail.app" +COMPONENT = "org.libremail.app/org.libremail.MainActivity" +FIX = os.path.join(os.path.dirname(__file__), "fixtures") + +SYNC_ALL = "07-06 15:00:06.896 15192 15217 I MailSyncer: sync all: 1 accounts" +GATE_SKIP = "07-06 15:00:07.100 15192 15217 I MailSyncer: prefetch skipped: fetch-gate paused" + +COLD_1 = "\n".join( + [ + "07-06 15:01:00.000 10261 15306 D ImapPerf: body-fetch select=2566ms body=14253ms " + "flag=2356ms rfc822=60457B chars=51610 att=0", + "07-06 15:01:00.100 10261 15306 D ImapPerf: body-fetch connect=0ms work=26211ms live=3", + "07-06 15:01:00.200 10261 15306 I MailReader: openMessage imap:94058a folder=INBOX " + "fetchedBody=true took=31227ms", + "07-06 15:01:00.300 10261 10261 D Reader : reader ready took=31617ms html=true inline=0", + ] +) +COLD_2 = "\n".join( + [ + "07-06 15:01:40.000 10261 15306 D ImapPerf: body-fetch select=2000ms body=13000ms " + "flag=2000ms rfc822=59000B chars=50000 att=0", + "07-06 15:01:40.100 10261 15306 D ImapPerf: body-fetch connect=0ms work=27000ms live=3", + "07-06 15:01:40.200 10261 15306 I MailReader: openMessage imap:94058a folder=INBOX " + "fetchedBody=true took=32059ms", + "07-06 15:01:40.300 10261 10261 D Reader : reader ready took=32100ms html=true inline=0", + ] +) +WARM_1 = "\n".join( + [ + "07-06 15:03:00.000 10261 15306 I MailReader: openMessage imap:94058a folder=INBOX " + "fetchedBody=false took=21ms", + "07-06 15:03:00.050 10261 10261 D Reader : reader ready took=82ms html=true inline=0", + ] +) +WARM_2 = "\n".join( + [ + "07-06 15:03:10.000 10261 15306 I MailReader: openMessage imap:94058a folder=INBOX " + "fetchedBody=false took=18ms", + "07-06 15:03:10.050 10261 10261 D Reader : reader ready took=70ms html=true inline=0", + ] +) + + +def _mailbox_xml(): + with open(os.path.join(FIX, "ui_mailbox.xml"), encoding="utf-8") as fh: + return fh.read() + + +# --------------------------------------------------------------------------- # +# Fakes +# --------------------------------------------------------------------------- # +class FakeTailer: + """Yields scripted chunks, one per ``read_new()`` (empty once exhausted).""" + + def __init__(self, chunks): + self._chunks = list(chunks) + self.marks = 0 + + def mark(self): + self.marks += 1 + + def read_new(self): + return self._chunks.pop(0) if self._chunks else "" + + +class RaisingTailer: + def mark(self): + pass + + def read_new(self): + raise RuntimeError("logcat pipe broke") + + +class FakeAdb: + """Minimal adb stand-in for the UI-driving parts of the scenario.""" + + def __init__(self, dump_xml, package=PKG): + self.package = package + self.dry_run = False + self.dump_xml = dump_xml + self.taps = [] + self.keyevents = [] + self.swipes = 0 + + def uiautomator_dump(self): + return self.dump_xml + + def input_tap(self, x, y): + self.taps.append((x, y)) + + def input_keyevent(self, key): + self.keyevents.append(key) + + def input_swipe(self, *args): + self.swipes += 1 + + def settle(self, seconds): + pass + + def wake(self): + pass + + def stay_on(self, on=True): + pass + + +class FakeGate: + """Records pause/resume/query and returns canned read-backs.""" + + _PAUSED = fetchgate.BroadcastResult(0, "paused=[backfill,prefetch]", frozenset({"backfill", "prefetch"})) + _CLEARED = fetchgate.BroadcastResult(0, "paused=[]", frozenset()) + + def __init__(self): + self.pauses = [] + self.resumes = [] + self.queries = [] + + def pause(self, scope=fetchgate.DEFAULT_SCOPE): + self.pauses.append(scope) + return self._PAUSED + + def resume(self, scope=fetchgate.DEFAULT_SCOPE): + self.resumes.append(scope) + return self._CLEARED + + def query(self, scope=fetchgate.DEFAULT_SCOPE): + self.queries.append(scope) + return self._PAUSED + + +def _noop(_msg): + pass + + +# --------------------------------------------------------------------------- # +# Breadcrumb control-signal matchers +# --------------------------------------------------------------------------- # +class TestControlSignalMatchers(unittest.TestCase): + def test_match_sync_all(self): + self.assertEqual(breadcrumbs.match_sync_all(SYNC_ALL), 1) + self.assertEqual( + breadcrumbs.match_sync_all( + "07-06 15:00:06.896 15192 15217 I MailSyncer: sync all: 3 accounts" + ), + 3, + ) + + def test_match_sync_all_rejects_other_lines(self): + self.assertIsNone(breadcrumbs.match_sync_all(GATE_SKIP)) + self.assertIsNone(breadcrumbs.match_sync_all(COLD_1.splitlines()[0])) + self.assertIsNone(breadcrumbs.match_sync_all("garbage")) + + def test_is_fetch_gate_skip(self): + self.assertTrue(breadcrumbs.is_fetch_gate_skip(GATE_SKIP)) + self.assertTrue( + breadcrumbs.is_fetch_gate_skip( + "07-06 15:00:07.100 15192 15217 I MailBackfiller: prefetch skipped: fetch-gate paused" + ) + ) + + def test_is_fetch_gate_skip_rejects_other_lines(self): + self.assertFalse(breadcrumbs.is_fetch_gate_skip(SYNC_ALL)) + self.assertFalse( + breadcrumbs.is_fetch_gate_skip( + "07-06 15:00:07.100 15192 15217 I Other: prefetch skipped: fetch-gate paused" + ) + ) + + +# --------------------------------------------------------------------------- # +# Wait helpers +# --------------------------------------------------------------------------- # +class TestWaitHelpers(unittest.TestCase): + def test_wait_for_sign_in_detects(self): + tailer = FakeTailer([SYNC_ALL]) + self.assertEqual(scenarios.wait_for_sign_in(tailer, 5.0, _noop), 1) + + def test_wait_for_sign_in_timeout(self): + tailer = FakeTailer([]) + self.assertIsNone(scenarios.wait_for_sign_in(tailer, 0.0, _noop)) + + def test_wait_for_gate_skip_detects(self): + tailer = FakeTailer(["noise\n" + GATE_SKIP]) + self.assertTrue(scenarios.wait_for_gate_skip(tailer, 5.0, _noop)) + + def test_wait_for_gate_skip_timeout(self): + self.assertFalse(scenarios.wait_for_gate_skip(FakeTailer([]), 0.0, _noop)) + + def test_wait_for_open_breadcrumb_returns_all_events(self): + events = scenarios.wait_for_open_breadcrumb(FakeTailer([COLD_1]), 5.0, _noop) + kinds = [type(e).__name__ for e in events] + self.assertIn("OpenMessage", kinds) + self.assertIn("BodyFetch", kinds) + self.assertIn("ImapPerfOp", kinds) + + def test_wait_for_open_breadcrumb_timeout_returns_partial(self): + # A chunk with perf lines but no openMessage -> returns what it saw, no hang. + partial = COLD_1.splitlines()[0] + events = scenarios.wait_for_open_breadcrumb(FakeTailer([partial]), 0.0, _noop) + self.assertFalse(any(isinstance(e, breadcrumbs.OpenMessage) for e in events)) + + def test_wait_for_header_sync(self): + adb = FakeAdb(_mailbox_xml()) + self.assertTrue(scenarios.wait_for_header_sync(adb, PKG, 5.0, _noop)) + + def test_wait_for_header_sync_timeout_no_rows(self): + adb = FakeAdb(_mailbox_xml().replace('scrollable="true"', 'scrollable="false"')) + self.assertFalse(scenarios.wait_for_header_sync(adb, PKG, 0.0, _noop)) + + +# --------------------------------------------------------------------------- # +# Row-selection hardening (subsumes #392) +# --------------------------------------------------------------------------- # +class TestRowHardening(unittest.TestCase): + HARDENING_XML = ( + "" + '' + '' + # A real message row (has a multi-char text label). + '' + '' + '' + "" + # A non-message tappable row: only a single-letter monogram, no real label. + '' + '' + "" + "" + ) + + def test_non_message_rows_skipped(self): + root = uidump.parse_dump(self.HARDENING_XML) + rows = uidump.find_message_rows(root, PKG) + self.assertEqual(len(rows), 1) + self.assertIn("Alice", rows[0].label) + + def test_existing_mailbox_still_three_rows(self): + # Hardening must not drop legitimate rows from the real fixture. + root = uidump.parse_dump(_mailbox_xml()) + self.assertEqual(len(uidump.find_message_rows(root, PKG)), 3) + + +# --------------------------------------------------------------------------- # +# The scenario +# --------------------------------------------------------------------------- # +class TestColdFetchScenario(unittest.TestCase): + def _run(self, adb, tailer, gate, **kw): + with patch("time.sleep"), patch.object(scenarios, "OPEN_TIMEOUT_S", 1.0): + return scenarios.cold_fetch_ab( + adb, + PKG, + COMPONENT, + tailer, + gate, + count=3, + log=_noop, + sign_in_timeout_s=5.0, + gate_confirm_timeout_s=5.0, + header_sync_timeout_s=5.0, + **kw, + ) + + def test_happy_path(self): + adb = FakeAdb(_mailbox_xml()) + tailer = FakeTailer([SYNC_ALL, GATE_SKIP, COLD_1, COLD_2, WARM_1, WARM_2]) + gate = FakeGate() + results = self._run(adb, tailer, gate) + + # Flow signals. + self.assertEqual(results["sign_in_accounts"], 1) + self.assertTrue(results["gate_confirmed"]) + self.assertTrue(results["header_ready"]) + + # Cold opens: two uncached, connect=0ms (reuse), throttle-level work. + cold = results["cold"] + self.assertEqual(len(cold), 2) + self.assertTrue(all(not r.cached for r in cold)) + self.assertEqual([r.took_ms for r in cold], [31227, 32059]) + self.assertEqual([r.connect_ms for r in cold], [0, 0]) + self.assertEqual([r.work_ms for r in cold], [26211, 27000]) + + # Warm opens: same messages, now cached and fast. + warm = results["warm"] + self.assertEqual(len(warm), 2) + self.assertTrue(all(r.cached for r in warm)) + self.assertEqual([r.took_ms for r in warm], [21, 18]) + + # Gate lifecycle: pre-armed once, resumed for warm phase AND in the finally. + self.assertEqual(gate.pauses, [fetchgate.DEFAULT_SCOPE]) + self.assertEqual(gate.resumes, [fetchgate.DEFAULT_SCOPE, fetchgate.DEFAULT_SCOPE]) + self.assertEqual(results["gate_prearm"].paused, frozenset({"backfill", "prefetch"})) + self.assertEqual(results["gate_restored"].paused, frozenset()) + + # Two distinct messages were tapped in each phase (4 opens -> 4 BACK presses). + self.assertEqual(adb.keyevents.count("KEYCODE_BACK"), 4) + + def test_always_resumes_on_error(self): + adb = FakeAdb(_mailbox_xml()) + gate = FakeGate() + with self.assertRaises(RuntimeError): + self._run(adb, RaisingTailer(), gate) + # Pre-armed, then the finally cleared the gate despite the mid-run exception. + self.assertEqual(gate.pauses, [fetchgate.DEFAULT_SCOPE]) + self.assertEqual(gate.resumes, [fetchgate.DEFAULT_SCOPE]) + + def test_dry_run_issues_pause_resume_plan(self): + logged = [] + real = perf_harness.Adb(package=PKG, dry_run=True, logger=logged.append) + gate = fetchgate.FetchGate(real, log=logged.append) + results = scenarios.cold_fetch_ab( + real, PKG, COMPONENT, scenarios._NullTailer(), gate, count=3, log=logged.append + ) + plan = "\n".join(logged) + self.assertIn("--es action pause", plan) + self.assertIn("--es action resume", plan) + self.assertIn("--es action query", plan) + self.assertTrue(results["cold"][0].skipped) + self.assertTrue(results["warm"][0].skipped) + + +# --------------------------------------------------------------------------- # +# The report renderer +# --------------------------------------------------------------------------- # +class TestColdFetchReport(unittest.TestCase): + def _results(self): + paused = fetchgate.BroadcastResult(0, "paused=[backfill,prefetch]", frozenset({"backfill", "prefetch"})) + cleared = fetchgate.BroadcastResult(0, "paused=[]", frozenset()) + return { + "gate_prearm": paused, + "sign_in_accounts": 1, + "gate_confirmed": True, + "header_ready": True, + "cold": [ + ReaderOpenRow(index=1, label="A1", cached=False, took_ms=31227, connect_ms=0, work_ms=26211), + ReaderOpenRow(index=2, label="A2", cached=False, took_ms=32059, connect_ms=0, work_ms=27000), + ], + "warm": [ + ReaderOpenRow(index=1, label="A1", cached=True, took_ms=21), + ReaderOpenRow(index=2, label="A2", cached=True, took_ms=18), + ], + "gate_resume": cleared, + "gate_restored": cleared, + } + + def test_render_sections_and_proofs(self): + md = report.render_cold_fetch_ab(self._results()) + self.assertIn("Fetch-gate A/B control", md) + self.assertIn("paused=[backfill,prefetch]", md) + self.assertIn("Cold opens", md) + self.assertIn("Warm opens", md) + # connect=0ms reuse proof, throttle signature, and the cold/warm speedup. + self.assertIn("connect=0ms on 2/2 cold opens (reuse active)", md) + self.assertIn("throttle signature", md) + self.assertIn("Speedup", md) + self.assertIn("debug-build-only", md) + + def test_render_handles_empty_dry_run_results(self): + results = { + "gate_prearm": fetchgate.BroadcastResult(None, None, frozenset()), + "cold": [ReaderOpenRow(index=1, label="", skipped=True, reason="dry-run")], + "warm": [ReaderOpenRow(index=1, label="", skipped=True, reason="dry-run")], + "gate_restored": fetchgate.BroadcastResult(None, None, frozenset()), + } + md = report.render_cold_fetch_ab(results) # must not raise on missing/empty fields + self.assertIn("Fetch-gate A/B control", md) + self.assertIn("no read-back", md) + + +# --------------------------------------------------------------------------- # +# End-to-end --dry-run through the CLI entry point +# --------------------------------------------------------------------------- # +class TestDryRunThroughMain(unittest.TestCase): + def test_cold_fetch_ab_dry_run(self): + with tempfile.TemporaryDirectory() as tmp: + with contextlib.redirect_stdout(io.StringIO()): + rc = perf_harness.main(["cold-fetch-ab", "--dry-run", "--out", tmp]) + self.assertEqual(rc, 0) + tables = glob.glob(os.path.join(tmp, "*", "timing-tables.md")) + self.assertEqual(len(tables), 1) + with open(tables[0], encoding="utf-8") as fh: + doc = fh.read() + self.assertIn("Fetch-gate A/B control", doc) + self.assertIn("Cold vs warm (A/B)", doc) + + +if __name__ == "__main__": + unittest.main() diff --git a/scripts/device-testing/uidump.py b/scripts/device-testing/uidump.py index 661bf5f..1a77f61 100644 --- a/scripts/device-testing/uidump.py +++ b/scripts/device-testing/uidump.py @@ -203,6 +203,11 @@ def find_message_rows(root: UiNode, package: str) -> List[MessageRow]: ``ui_mailbox.xml``). A row carrying the ``"Available offline"`` content-desc has its body cached already, so it is marked ``cached`` (callers pick uncached rows for the uncached-open scenarios). + + Row-selection hardening: a candidate is skipped unless it carries at least one multi-char + text label. A real message row always shows a sender/subject; a bare tappable container + (a stray clickable spacer, a "load more"/footer affordance, an empty section row) has + none, and tapping it would open nothing and corrupt a sample -- so it is not returned. """ scrollables = root.find_all(lambda n: n.scrollable and n.package == package) rows: List[MessageRow] = [] @@ -217,6 +222,9 @@ def find_message_rows(root: UiNode, package: str) -> List[MessageRow]: texts = child.descendant_texts() # Drop single-letter avatar monograms; keep sender/subject/time. texts = [t for t in texts if len(t) > 1] + if not texts: + # No sender/subject label -> not a message row; skip it (hardening). + continue cached = any(d == "Available offline" for d in child.descendant_descs()) rows.append( MessageRow(