fix: prove the FGS video's scan start by notification, not by the service record

The script could report "scan started" on runs where the app was being killed, which sent me
chasing a "mid-scan death" that never happened. The mistake was the signal: dumpsys activity
services lists a service *record* from the moment startForegroundService() is called, so it says
nothing about whether startForeground() was reached - and that gap is exactly what the platform's
deadline measures. logcat's events buffer shows what really happened on every attempt:

  am_crash: [..., android.app.ForegroundServiceDidNotStartInTimeException,
             Context.startForegroundService() did not then call
             Service.startForeground(): .../ScanService]
  am_proc_died: [...]

No am_kill, no low-memory record: not memory pressure, and not a crash in the app's own code. The
script now waits for the app's notification, which only exists once startForeground() has been
called, and prints that am_crash line when the service never starts, so a failure is never
mistaken for a success again.

Also in the script:

- let the emulator settle before the run (first-boot work competes for the same CPU) and give the
  process time to load its classes before asking it to start a service inside the budget, both
  overridable as SETTLE_SECONDS and WARM_SECONDS,
- give up with a non-zero exit and an explicit "record this on a real device" message rather than
  carrying on to record a video whose scan never started,
- read the events buffer rather than the main one when reporting the reason.

Verdict for the docs, corrected: this capture cannot be done on a KVM-less emulator, and the
previous "second failure mode" was this one misread. The last crash landed on a process that had
been alive and idle for over a minute, so no amount of warming fixes it - while on the phone the
same build scans 5,363 photos in 20 s with the notification up the whole time. The take belongs on
the phone; the script is the checklist for what it has to show.
This commit is contained in:
2026-10-14 11:39:49 +02:00
parent ae05a0dad4
commit 179bc2cc33
3 changed files with 72 additions and 34 deletions
+48 -20
View File
@@ -112,13 +112,22 @@ wait_for_exact() {
return 1
}
scan_running() { "${adb[@]}" shell dumpsys activity services 2>/dev/null | grep -q -i ScanService; }
notifications_from_app() {
"${adb[@]}" shell dumpsys notification --noredact 2>/dev/null \
| grep -c 'NotificationRecord(.*fotodup' || true
}
# The signal that actually matters. A service *record* appears as soon as startForegroundService() is
# called, so it does not prove that startForeground() succeeded - and that five-second gap is exactly
# what kills this app on a slow emulator. The first version of this script used the record as its
# "scan started" evidence and therefore reported success on runs where the app was being killed
# (logcat's events buffer shows am_crash ForegroundServiceDidNotStartInTimeException moments later).
# The app's notification only exists once startForeground() has been called, so wait for that.
fgs_started() { [ "$(notifications_from_app)" != "0" ]; }
# Secondary signal, for logging only.
scan_running() { "${adb[@]}" shell dumpsys activity services 2>/dev/null | grep -q -i ScanService; }
checkpoint() { # <label> — one PNG per milestone, so the video can be verified without decoding it
"${adb[@]}" exec-out screencap -p > "$out/checkpoint-$1.png" 2>/dev/null || true
printf ' checkpoint-%s.png %s\n' "$1" "$(identify -format '%wx%h' "$out/checkpoint-$1.png" 2>/dev/null || echo '?')"
@@ -165,36 +174,56 @@ sleep 2
# --------------------------------------------------------------------- warm-up
#
# On a software-emulated device (no /dev/kvm) a *cold* app can miss Android's five-second
# startForegroundService() deadline. The platform then kills the process with
# ForegroundServiceDidNotStartInTimeException and force-finishes the activity, so the launcher
# appears where the scan should have started. That reproduced every single time on a freshly
# started process and never on one that had already run a scan, so: run a scan, cancel it, and only
# then record. Cancelling early also leaves the hash index half-built, which keeps the recorded scan
# long enough for the notification to be on screen.
say "Warming the app up (a cold process can miss the FGS deadline - see the note in this script)"
# The one thing that reliably kills this capture on a software-emulated device (no /dev/kvm) is the
# platform's five-second startForegroundService() deadline: the app is killed with
# ForegroundServiceDidNotStartInTimeException and the activity is force-finished, so the launcher
# appears where the scan should have started. logcat's events buffer names it:
#
# am_crash: [..., android.app.ForegroundServiceDidNotStartInTimeException,
# Context.startForegroundService() did not then call Service.startForeground(): ...]
# am_proc_died: [...]
#
# It is a question of CPU, not of the app: the same build starts the service immediately when the
# process has been alive for a while (classes loaded, JIT warm) and the emulator is not still doing
# first-boot work. So warm the app up first, and only start recording once a real scan has been
# confirmed - by the notification, for the reason given at fgs_started().
if [ "${SETTLE_SECONDS:-150}" != "0" ]; then
say "Letting the emulator settle (first-boot work competes for the same CPU)"
sleep "${SETTLE_SECONDS:-150}"
fi
say "Warming the app up (a cold process misses the FGS deadline - see the note in this script)"
attempt=0
while [ "$attempt" -lt 3 ]; do
while [ "$attempt" -lt 4 ]; do
attempt=$(( attempt + 1 ))
"${adb[@]}" shell am force-stop "$pkg"
"${adb[@]}" shell am start -n "$activity" >/dev/null
# Time for the process to load its classes before it is asked to start a service in under five
# seconds. This is the difference between the runs that worked and the ones that crashed.
sleep "${WARM_SECONDS:-75}"
if ! start="$(wait_for 'Start scan' 120)"; then
echo "error: the empty state never appeared - right APK installed? photo access granted?" >&2
exit 3
fi
"${adb[@]}" shell input tap $start
started=no
# dumpsys only while the service starts: every `uiautomator dump` spawns a JVM on the device and
# competes for exactly the CPU that the five-second deadline is measured against.
for _ in $(seq 1 10); do
if scan_running; then break; fi
for _ in $(seq 1 12); do
if fgs_started; then started=yes; break; fi
sleep 3
done
if scan_running; then
printf ' attempt %s: scan started - this process has now met the deadline once\n' "$attempt"
if [ "$started" = yes ]; then
printf ' attempt %s: the service started (notification posted)\n' "$attempt"
break
fi
printf ' attempt %s: the service never started\n' "$attempt"
"${adb[@]}" logcat -b events -d -t 400 2>/dev/null | grep -m1 'am_crash' || true
done
if [ "$started" != yes ]; then
echo "error: no scan could be started on this emulator - record the video on a real device" >&2
exit 4
fi
# Let the warm-up scan run to *completion* instead of cancelling it: cancelling does not lead back to
# the intro, and restarting the app to get there throws away exactly the warmth that keeps the
@@ -225,15 +254,14 @@ fi
printf ' Scan (top bar) at %s\n' "$scan_button"
"${adb[@]}" shell input tap $scan_button
sleep 8 # deliberately dump-free: this is the deadline window
if ! scan_running; then
printf ' the service did not start; the platform said:\n'
"${adb[@]}" logcat -d -t 300 2>/dev/null \
| grep -m1 -E 'ForegroundServiceDidNotStartInTimeException' || true
if ! fgs_started; then
printf ' the service did not start; the events buffer said:\n'
"${adb[@]}" logcat -b events -d -t 400 2>/dev/null | grep -m1 'am_crash' || true
echo "warn: no scan running - the video will not show the service" >&2
else
checkpoint 1-scanning
printf ' the service started (notification posted) on a process warmed by attempt %s\n' "$attempt"
fi
printf ' scan running: %s\n' "$(scan_running && echo yes || echo no)"
# Away from the app: from here on the service is what keeps the scan alive.
sleep 3