From 2f32657aff940aa5a20c9f80be9406d8752a44b6 Mon Sep 17 00:00:00 2001 From: Jason Ross Date: Mon, 6 Jul 2026 21:31:53 -0500 Subject: [PATCH] ci: capture thread-dump + service state on an E2E wedge to prove the root cause (#404) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit E2E legs intermittently WEDGE (hang) with no fast-fail until the job force-kill, and GitHub's post-force-kill step behavior is unreliable, so #388's diagnostics don't reliably capture the wedge — and don't capture wedge-specific state anyway. Wrap the `connectedDebugAndroidTest` run (both the `e2e` matrix first-attempt + retry, and each `e2e-preview` shard) in an explicit `timeout -k 30s 1200` (20 min) — comfortably above a normal run (~13-15 min), well below the hard cap — so a wedge trips the wrapper (exit 124), NOT the force-kill, GUARANTEEING the capture runs while the emulator is still alive. On 124, capture_wedge grabs the smoking gun into a `wedge-diagnostics-api` artifact: the running/last test (logcat TestRunner), SIGQUIT (kill -3) thread dumps of the app + instrumentation processes (ART -> logcat + /data/anr), dumpsys activity/window, `service list` + `service check input/window/activity` (the boot-race crux), sys.boot_completed + init.svc.* state, the snapshot cache-hit note, and accel/kvm/mem/disk. Then it exits with the real status so #388's diagnostics + the existing retry still fire; a normal run finishes before the wrapper and is unaffected. EVIDENCE ONLY — no boot-readiness guard/fix (maintainer: prove the cause first). Co-Authored-By: Claude Opus 4.8 --- .github/workflows/ci.yml | 229 +++++++++++++++++++++++++++++++++++++-- 1 file changed, 219 insertions(+), 10 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index c00abe3..db316d3 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -529,9 +529,75 @@ jobs: # so a test failure or emulator flake is diagnosable from the uploaded artifact. # Backgrounded; gradle stays the last foreground command so the step's exit status is # still the test result (a real failure still trips continue-on-error -> the retry). + # WEDGE CAPTURE (#404): the gradle run is wrapped in an explicit `timeout` well below the + # job's hard cap but comfortably above a normal run (~13-15 min), so a WEDGE (hang) trips + # the wrapper (exit 124) instead of hanging until the force-kill — GUARANTEEING the + # capture below runs WHILE THE EMULATOR IS STILL ALIVE (the runner action tears it down as + # soon as this script returns, so a post-step can't probe it). A normal run finishes long + # before 1200s and is unaffected. See the shared capture body in `capture_wedge`. script: | - adb logcat -v time > "$RUNNER_TEMP/logcat-api${{ matrix.api-level }}.txt" 2>&1 & - ./gradlew connectedDebugAndroidTest --stacktrace + WEDGE_TIMEOUT=1200 + LOGCAT="$RUNNER_TEMP/logcat-api${{ matrix.api-level }}.txt" + WEDGE="$RUNNER_TEMP/wedge-diagnostics-api${{ matrix.api-level }}.txt" + adb logcat -v time > "$LOGCAT" 2>&1 & + # On a wedge, grab the smoking gun: which test was running, SIGQUIT (kill -3) thread + # dumps of the app + instrumentation processes (ART -> logcat + /data/anr), activity/ + # window state, and — the boot-race crux — whether the binder services are published. + # Every probe guarded (|| true) so a missing tool / dead device can't abort it; appended + # (not overwritten) so a wedge on attempt 1 survives even if the retry later passes. + capture_wedge() { + { + echo "===================================================================" + echo "===== E2E WEDGE — API ${{ matrix.api-level }} — $1 =====" + echo "===== $(date -u +%FT%TZ) — after ${WEDGE_TIMEOUT}s wrapper timeout =====" + echo "===================================================================" + echo "--- snapshot: was 'Create AVD' a cache-hit (warm snapshot restore)? ---" + echo "avd-cache cache-hit: '${{ steps.avd-cache.outputs.cache-hit }}'" + echo "--- running/last instrumented test (logcat TestRunner) ---" + grep -a TestRunner "$LOGCAT" 2>/dev/null | tail -25 || true + echo "--- getprop sys.boot_completed ---" + adb shell getprop sys.boot_completed 2>&1 || true + echo "--- getprop init.svc.* (per-service init state) ---" + adb shell getprop 2>&1 | grep -a init.svc || true + echo "--- service list (are binder services published?) ---" + adb shell service list 2>&1 || true + for svc in input window activity; do + echo "--- service check $svc ---" + adb shell service check "$svc" 2>&1 || true + done + echo "--- pids ---" + APP_PID="$(adb shell pidof org.libremail.app 2>/dev/null | tr -d '\r')" || true + TEST_PID="$(adb shell pidof org.libremail.app.test 2>/dev/null | tr -d '\r')" || true + echo "app pid: ${APP_PID:-}" + echo "test pid: ${TEST_PID:-}" + echo "--- SIGQUIT (kill -3) thread dumps -> ART writes to logcat + /data/anr ---" + for pid in $APP_PID $TEST_PID; do + [ -n "$pid" ] && adb shell kill -3 "$pid" 2>&1 || true + done + sleep 5 + echo "--- /data/anr/* (SIGQUIT + ANR traces) ---" + adb shell 'cat /data/anr/* 2>/dev/null' 2>&1 || true + echo "--- dumpsys activity ---" + adb shell dumpsys activity 2>&1 || true + echo "--- dumpsys window ---" + adb shell dumpsys window 2>&1 || true + echo "--- logcat -d (tail 400 — includes the SIGQUIT thread dump) ---" + adb logcat -d 2>&1 | tail -400 || true + echo "--- emulator accel / kvm / mem / disk ---" + "$ANDROID_SDK_ROOT/emulator/emulator" -accel-check 2>&1 || true + ls -l /dev/kvm 2>&1 || true + free -h 2>&1 || true + df -h 2>&1 || true + } >> "$WEDGE" 2>&1 || true + echo "::warning::E2E API ${{ matrix.api-level }} WEDGED ($1) — see the wedge-diagnostics-api${{ matrix.api-level }} artifact" + } + # `|| status=$?` (not `if timeout; then`) so the exit code survives regardless of `set -e`; + # -k 30s SIGKILLs a gradle client that ignores SIGTERM. 124 == wedge -> capture, then exit + # with the real status so continue-on-error still fires the retry. + status=0 + timeout -k 30s "$WEDGE_TIMEOUT" ./gradlew connectedDebugAndroidTest --stacktrace || status=$? + if [ "$status" -eq 124 ]; then capture_wedge "attempt 1"; fi + exit "$status" - name: Run E2E tests (retry after emulator boot race) if: steps.e2e.outcome == 'failure' @@ -545,10 +611,64 @@ jobs: disable-animations: true # Retry runs a fresh emulator boot; stream its logcat the same way. `>` overwrites # attempt 1's file so the artifact holds the FINAL attempt's logs, matching the - # failure-time dump below (which reflects this last attempt's state). + # failure-time dump below (which reflects this last attempt's state). Same #404 wrapper + # timeout + wedge capture as attempt 1 (appended to the same WEDGE file) so a wedge is + # captured on the RETRY too, not just the first attempt. script: | - adb logcat -v time > "$RUNNER_TEMP/logcat-api${{ matrix.api-level }}.txt" 2>&1 & - ./gradlew connectedDebugAndroidTest --stacktrace + WEDGE_TIMEOUT=1200 + LOGCAT="$RUNNER_TEMP/logcat-api${{ matrix.api-level }}.txt" + WEDGE="$RUNNER_TEMP/wedge-diagnostics-api${{ matrix.api-level }}.txt" + adb logcat -v time > "$LOGCAT" 2>&1 & + capture_wedge() { + { + echo "===================================================================" + echo "===== E2E WEDGE — API ${{ matrix.api-level }} — $1 =====" + echo "===== $(date -u +%FT%TZ) — after ${WEDGE_TIMEOUT}s wrapper timeout =====" + echo "===================================================================" + echo "--- snapshot: was 'Create AVD' a cache-hit (warm snapshot restore)? ---" + echo "avd-cache cache-hit: '${{ steps.avd-cache.outputs.cache-hit }}'" + echo "--- running/last instrumented test (logcat TestRunner) ---" + grep -a TestRunner "$LOGCAT" 2>/dev/null | tail -25 || true + echo "--- getprop sys.boot_completed ---" + adb shell getprop sys.boot_completed 2>&1 || true + echo "--- getprop init.svc.* (per-service init state) ---" + adb shell getprop 2>&1 | grep -a init.svc || true + echo "--- service list (are binder services published?) ---" + adb shell service list 2>&1 || true + for svc in input window activity; do + echo "--- service check $svc ---" + adb shell service check "$svc" 2>&1 || true + done + echo "--- pids ---" + APP_PID="$(adb shell pidof org.libremail.app 2>/dev/null | tr -d '\r')" || true + TEST_PID="$(adb shell pidof org.libremail.app.test 2>/dev/null | tr -d '\r')" || true + echo "app pid: ${APP_PID:-}" + echo "test pid: ${TEST_PID:-}" + echo "--- SIGQUIT (kill -3) thread dumps -> ART writes to logcat + /data/anr ---" + for pid in $APP_PID $TEST_PID; do + [ -n "$pid" ] && adb shell kill -3 "$pid" 2>&1 || true + done + sleep 5 + echo "--- /data/anr/* (SIGQUIT + ANR traces) ---" + adb shell 'cat /data/anr/* 2>/dev/null' 2>&1 || true + echo "--- dumpsys activity ---" + adb shell dumpsys activity 2>&1 || true + echo "--- dumpsys window ---" + adb shell dumpsys window 2>&1 || true + echo "--- logcat -d (tail 400 — includes the SIGQUIT thread dump) ---" + adb logcat -d 2>&1 | tail -400 || true + echo "--- emulator accel / kvm / mem / disk ---" + "$ANDROID_SDK_ROOT/emulator/emulator" -accel-check 2>&1 || true + ls -l /dev/kvm 2>&1 || true + free -h 2>&1 || true + df -h 2>&1 || true + } >> "$WEDGE" 2>&1 || true + echo "::warning::E2E API ${{ matrix.api-level }} WEDGED ($1) — see the wedge-diagnostics-api${{ matrix.api-level }} artifact" + } + status=0 + timeout -k 30s "$WEDGE_TIMEOUT" ./gradlew connectedDebugAndroidTest --stacktrace || status=$? + if [ "$status" -eq 124 ]; then capture_wedge "attempt 2 (retry)"; fi + exit "$status" # On any E2E failure (both boot attempts failed, a hung emulator, or an earlier setup/SDK # step), snapshot device + runner state to the step log AND a file for the artifact upload — @@ -591,6 +711,19 @@ jobs: ${{ runner.temp }}/diagnostics-api${{ matrix.api-level }}.txt if-no-files-found: warn + # Wedge-specific smoking gun (#404): only present when the wrapper `timeout` tripped (a hang) — + # written by capture_wedge inside the E2E run step(s), covering BOTH the first attempt and the + # retry. Separate from the #388 e2e-diagnostics artifact above (the general failure dump). + # `if-no-files-found: ignore` keeps the overwhelmingly-common healthy run quiet (no wedge => no + # file). Per-api-level name (upload-artifact@v7 rejects duplicate names). + - name: Upload wedge diagnostics + if: always() + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 + with: + name: wedge-diagnostics-api${{ matrix.api-level }} + path: ${{ runner.temp }}/wedge-diagnostics-api${{ matrix.api-level }}.txt + if-no-files-found: ignore + # API 37 (Android 17, preview) E2E. Its only system image is the nonstandard # android-37.0 / google_apis_ps16k (16 KB page size), which reactivecircus/android-emulator-runner # can't provision (it builds android-37 / google_apis, neither of which exists), so this job @@ -726,6 +859,9 @@ jobs: EMU_LOG="${RUNNER_TEMP:-/tmp}/emulator.log" LOGCAT_LOG="${RUNNER_TEMP:-/tmp}/logcat.txt" DIAG_LOG="${RUNNER_TEMP:-/tmp}/boot-diagnostics.txt" + # Wedge (hang) smoking-gun capture (#404) — see capture_wedge / run_shard below. + WEDGE_LOG="${RUNNER_TEMP:-/tmp}/wedge-diagnostics-api37-shard${{ matrix.shard }}.txt" + WEDGE_TIMEOUT=1200 GPU_MODE="swiftshader_indirect" # On a boot timeout, capture the full system state (accel/KVM/GPU/mem/disk/AVD config + @@ -792,22 +928,84 @@ jobs: [ "$booted" = "1" ] || { echo "::error::API 37 preview emulator failed to boot after 2 attempts"; exit 1; } adb shell input keyevent 82 || true + + # WEDGE (hang) smoking-gun capture (#404). On the wrapper `timeout` below (exit 124), grab + # the smoking gun WHILE this hand-provisioned emulator is still alive (it stays up until the + # "Shut down emulator" step): which test was running, SIGQUIT (kill -3) thread dumps of the + # app + instrumentation processes (ART -> logcat + /data/anr), activity/window state, and — + # the boot-race crux — whether the binder services are published. Every probe guarded so a + # missing tool / dead device can't abort it; appended so both attempts survive. `|| true` + # keeps it from tripping this step's `set -e`. + capture_wedge() { + { + echo "===================================================================" + echo "===== E2E WEDGE — API 37 preview shard ${{ matrix.shard }} — $1 =====" + echo "===== $(date -u +%FT%TZ) — after ${WEDGE_TIMEOUT}s wrapper timeout =====" + echo "===================================================================" + echo "--- snapshot: N/A — preview cold-boots (-no-snapshot); no AVD snapshot cache ---" + echo "--- running/last instrumented test (logcat TestRunner) ---" + grep -a TestRunner "$LOGCAT_LOG" 2>/dev/null | tail -25 || true + echo "--- getprop sys.boot_completed ---" + adb shell getprop sys.boot_completed 2>&1 || true + echo "--- getprop init.svc.* (per-service init state) ---" + adb shell getprop 2>&1 | grep -a init.svc || true + echo "--- service list (are binder services published?) ---" + adb shell service list 2>&1 || true + for svc in input window activity; do + echo "--- service check $svc ---" + adb shell service check "$svc" 2>&1 || true + done + echo "--- pids ---" + APP_PID="$(adb shell pidof org.libremail.app 2>/dev/null | tr -d '\r')" || true + TEST_PID="$(adb shell pidof org.libremail.app.test 2>/dev/null | tr -d '\r')" || true + echo "app pid: ${APP_PID:-}" + echo "test pid: ${TEST_PID:-}" + echo "--- SIGQUIT (kill -3) thread dumps -> ART writes to logcat + /data/anr ---" + for pid in $APP_PID $TEST_PID; do + [ -n "$pid" ] && adb shell kill -3 "$pid" 2>&1 || true + done + sleep 5 + echo "--- /data/anr/* (SIGQUIT + ANR traces) ---" + adb shell 'cat /data/anr/* 2>/dev/null' 2>&1 || true + echo "--- dumpsys activity ---" + adb shell dumpsys activity 2>&1 || true + echo "--- dumpsys window ---" + adb shell dumpsys window 2>&1 || true + echo "--- logcat -d (tail 400 — includes the SIGQUIT thread dump) ---" + adb logcat -d 2>&1 | tail -400 || true + echo "--- emulator accel / kvm / mem / disk ---" + "$ANDROID_SDK_ROOT/emulator/emulator" -accel-check 2>&1 || true + ls -l /dev/kvm 2>&1 || true + free -h 2>&1 || true + df -h 2>&1 || true + } >> "$WEDGE_LOG" 2>&1 || true + echo "::warning::E2E API 37 preview shard ${{ matrix.shard }} WEDGED ($1) — see the wedge-diagnostics-api37-preview-shard${{ matrix.shard }} artifact" + } + # Run only this matrix leg's shard. AndroidJUnitRunner hashes each test name into one of # numShards buckets and runs only shardIndex's bucket. The args flow through AGP's # -Pandroid.testInstrumentationRunnerArguments.* channel (the same one local_instrumented.py - # uses for .class=…) — no GMD, no orchestrator, no Gradle-side change. + # uses for .class=…) — no GMD, no orchestrator, no Gradle-side change. The gradle run is + # wrapped in the #404 wrapper `timeout`: a wedge trips it (exit 124) -> capture_wedge runs, + # then the shard returns 124 so the retry / gate still see a failure. `|| status=$?` makes + # the exit code survive this step's `set -e`; -k 30s SIGKILLs a gradle client that ignores + # SIGTERM. run_shard() { - ./gradlew connectedDebugAndroidTest --stacktrace \ + local status=0 + timeout -k 30s "$WEDGE_TIMEOUT" ./gradlew connectedDebugAndroidTest --stacktrace \ "-Pandroid.testInstrumentationRunnerArguments.numShards=${API37_NUM_SHARDS}" \ - "-Pandroid.testInstrumentationRunnerArguments.shardIndex=${{ matrix.shard }}" + "-Pandroid.testInstrumentationRunnerArguments.shardIndex=${{ matrix.shard }}" || status=$? + if [ "$status" -eq 124 ]; then capture_wedge "$1"; fi + return "$status" } # Retry this shard's test run ONCE on failure — retry parity with the stable `e2e` matrix # (which retries once, so a flaky test self-heals on API 29–36 but would otherwise wedge # the required gate on API 37, e.g. #370). Per-shard, so the retry re-runs only this shard's # ~T/N tests, not the whole suite. MITIGATION, NOT A FIX: a blanket retry also masks genuine # regressions, so the retried-but-passed case is flagged as a ::warning:: and the real fix - # stays test-level. See docs/perf/api37-e2e-sharding-spike.md. - run_shard || { echo "::warning::API 37 shard ${{ matrix.shard }} test run failed — retrying once"; run_shard; } + # stays test-level. See docs/perf/api37-e2e-sharding-spike.md. A wedge on EITHER attempt is + # captured (capture_wedge runs inside run_shard on exit 124). + run_shard "attempt 1" || { echo "::warning::API 37 shard ${{ matrix.shard }} test run failed — retrying once"; run_shard "attempt 2 (retry)"; } - name: Dump emulator log on failure if: failure() @@ -829,6 +1027,17 @@ jobs: ${{ runner.temp }}/boot-diagnostics.txt if-no-files-found: warn + # Wedge-specific smoking gun (#404): only present when the wrapper `timeout` tripped (a hang) + # on either shard attempt — separate from the boot-diagnostics artifact above. `if-no-files- + # found: ignore` keeps healthy runs quiet (no wedge => no file). Shard-unique name. + - name: Upload wedge diagnostics + if: always() + uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 + with: + name: wedge-diagnostics-api37-preview-shard${{ matrix.shard }} + path: ${{ runner.temp }}/wedge-diagnostics-api37-shard${{ matrix.shard }}.txt + if-no-files-found: ignore + - name: Shut down emulator if: always() run: adb emu kill || true