fix(ci): Android e2e flakes, shell Terminated sent before output (#3672)

* fix(ci): Android e2e flakes, shell `Terminated` sent before output

- close "isn't responding" system dialogs before each spec and hide error dialogs on the CI emulator:
  a launcher ANR dialog takes input focus from the app, and Android then denies clipboard reads
- retry switching to the webview context until it succeeds instead of running the spec in the
  native context when the first switch fails with "No such context found"
- save the focused window, a screenshot and logcat when an Android test fails
- shell: wait for the pipe readers to finish before emitting `Terminated`; the readers took their
  read lock on their own thread, so a child exiting quickly could have `close` emitted before
  its output

* Apply suggestion from @lucasfernog

.changes/shell-terminated-after-output.md

@@ -0,0 +1,6 @@
+---
+shell: patch
+shell-js: patch
+---
+
+Fix `Command::spawn` (and the JavaScript `Command` API) sometimes emitting the `Terminated` (`close`) event before the child's `stdout`/`stderr` output when the process exits quickly.

.github/workflows/test-api-e2e-mobile.yml

@@ -159,7 +159,13 @@ jobs:
           profile: pixel_6
           emulator-options: -no-window -gpu swiftshader_indirect -noaudio -no-boot-anim -camera-back none
           disable-animations: true
-          script: E2E_SKIP_BUILD=1 E2E_SPEC_RETRIES=1 pnpm test:api-e2e:android
+          # The slow emulator regularly has the launcher hit an ANR, and the "isn't responding"
+          # dialog takes input focus from the app under test (failing focus-gated APIs such as
+          # clipboard reads). With error dialogs hidden the system kills the unresponsive process
+          # instead; one that is already up is closed before each spec (see wdio.mobile.ts).
+          script: |
+            adb shell settings put global hide_error_dialogs 1
+            E2E_SKIP_BUILD=1 E2E_SPEC_RETRIES=1 pnpm test:api-e2e:android
 
       - name: upload appium logs
         if: failure()

packages/api-e2e/wdio.mobile.ts

@@ -197,6 +197,9 @@ export function mobileConfig(platform: MobilePlatform): WebdriverIO.Config {
         // because Appium may only have booted the emulator with the first
         // session.
         adbReverse(FIXTURE_SERVER_PORT)
+        // Still in the native context here, where UiAutomator2 sees system
+        // windows.
+        await dismissAnrDialogs(browser)
       }
 
       let webview: string | undefined
@@ -216,7 +219,20 @@ export function mobileConfig(platform: MobilePlatform): WebdriverIO.Config {
             ?? (platform === 'ios'
               ? contexts.find((name) => name.startsWith('WEBVIEW_'))
               : undefined)
-          return webview !== undefined
+          if (webview === undefined) {
+            return false
+          }
+          try {
+            await browser.switchAppiumContext(webview)
+            return true
+          } catch {
+            // On Android the context is listed as soon as the WebView's
+            // devtools socket exists, but switching to it fails with "No such
+            // context found" until the page is attachable. The suite would
+            // otherwise carry on in the native context, where every script
+            // fails with "Method has not yet been implemented".
+            return false
+          }
         },
         {
           // Covers a cold app start plus, on Android, the on-demand chromedriver
@@ -227,7 +243,6 @@ export function mobileConfig(platform: MobilePlatform): WebdriverIO.Config {
             'no WEBVIEW context appeared — is the app a debug build (webview debugging enabled)?'
         }
       )
-      await browser.switchAppiumContext(webview!)
       // The specs run the page through `executeAsync`, and the XCUITest driver
       // starts with a script timeout of 0 (every async script times out at
       // once) rather than the 30s the other drivers default to.
@@ -255,6 +270,16 @@ export function mobileConfig(platform: MobilePlatform): WebdriverIO.Config {
       )
     },
 
+    // On Android, a failure is often down to the device rather than the app
+    // (e.g. a system dialog holding input focus), which the webview-side
+    // error alone does not show. Save what the device looked like next to the
+    // Appium log, which CI uploads on failure.
+    afterTest: (test, _context, { passed }) => {
+      if (platform === 'android' && !passed) {
+        androidDiagnostics(`${test.parent} ${test.title}`)
+      }
+    },
+
     onComplete: () => {
       closeFixtureServer()
     }
@@ -313,18 +338,22 @@ function androidBuildEnv(): NodeJS.ProcessEnv {
 
 /** `adb` from the Android SDK, else whatever is on `PATH`. */
 function adb(args: string[]): SpawnSyncReturns<string> {
+  return spawnSync(adbBinary(), [...adbDeviceArgs(), ...args], {
+    encoding: 'utf8',
+    timeout: 20_000,
+    maxBuffer: 64 * 1024 * 1024
+  })
+}
+
+function adbBinary(): string {
   const sdk = process.env.ANDROID_HOME ?? process.env.ANDROID_SDK_ROOT
-  const binary = sdk ? path.join(sdk, 'platform-tools', 'adb') : 'adb'
+  return sdk ? path.join(sdk, 'platform-tools', 'adb') : 'adb'
-  return spawnSync(
+}
-    binary,
+
-    [
+function adbDeviceArgs(): string[] {
-      ...(process.env.E2E_ANDROID_DEVICE
+  return process.env.E2E_ANDROID_DEVICE
-        ? ['-s', process.env.E2E_ANDROID_DEVICE]
+    ? ['-s', process.env.E2E_ANDROID_DEVICE]
-        : []),
+    : []
-      ...args
-    ],
-    { encoding: 'utf8', timeout: 20_000 }
-  )
 }
 
 function adbReverse(port: number): void {
@@ -336,6 +365,63 @@ function adbReverse(port: number): void {
   }
 }
 
+/**
+ * Closes any "<app> isn't responding" dialog. On a slow emulator the launcher
+ * or System UI regularly hits an ANR, and the dialog that follows holds input
+ * focus over the app under test until someone answers it, failing anything
+ * that needs focus (Android denies clipboard reads to apps without it) for
+ * the rest of the run, retries included. "Close app" kills the unresponsive
+ * process, so it does not come straight back like "Wait" could.
+ */
+async function dismissAnrDialogs(browser: WebdriverIO.Browser): Promise<void> {
+  // More than one process can be stuck (e.g. launcher and System UI).
+  for (let attempt = 0; attempt < 5; attempt++) {
+    const close = browser.$('id=android:id/aerr_close')
+    if (!(await close.isExisting())) {
+      return
+    }
+    console.warn('[android] closing an "isn\'t responding" system dialog')
+    await close.click()
+    await browser.pause(500)
+  }
+}
+
+/**
+ * Writes the focused window, a screenshot and the recent logcat for a failed
+ * test to `logs/android-diagnostics/`.
+ */
+function androidDiagnostics(name: string): void {
+  const dir = path.join(dirname, 'logs', 'android-diagnostics')
+  const base = path.join(
+    dir,
+    `${new Date().toISOString().replace(/[:.]/g, '-')}-${name.replace(/[^\w-]+/g, '_').slice(0, 80)}`
+  )
+  fs.mkdirSync(dir, { recursive: true })
+
+  const focus = adb(['shell', 'dumpsys', 'window'])
+  const focusLines = (focus.stdout ?? '')
+    .split('\n')
+    .filter((line) => /mCurrentFocus|mFocusedApp|mFocusedWindow/.test(line))
+    .map((line) => line.trim())
+  console.warn(`[android diagnostics] ${name}\n  ${focusLines.join('\n  ')}`)
+  // eslint-disable-next-line security/detect-non-literal-fs-filename
+  fs.writeFileSync(`${base}.window.txt`, focus.stdout ?? '')
+
+  const screenshot = spawnSync(
+    adbBinary(),
+    [...adbDeviceArgs(), 'exec-out', 'screencap', '-p'],
+    { timeout: 20_000 }
+  )
+  if (screenshot.status === 0) {
+    // eslint-disable-next-line security/detect-non-literal-fs-filename
+    fs.writeFileSync(`${base}.png`, screenshot.stdout)
+  }
+
+  const logcat = adb(['logcat', '-d', '-t', '20000'])
+  // eslint-disable-next-line security/detect-non-literal-fs-filename
+  fs.writeFileSync(`${base}.logcat.txt`, logcat.stdout ?? '')
+}
+
 function androidCapabilities(app: string): WebdriverIO.Capabilities {
   return {
     platformName: 'Android',

plugins/shell/src/process/mod.rs

@@ -7,8 +7,8 @@ use std::{
     io::{BufRead, BufReader, Write},
     path::{Path, PathBuf},
     process::{Command as StdCommand, Stdio},
-    sync::{Arc, RwLock},
+    sync::Arc,
-    thread::spawn,
+    thread::{JoinHandle, spawn},
 };
 
 #[cfg(unix)]
@@ -315,42 +315,29 @@ impl Command {
         let shared_child = SharedChild::spawn(&mut command)?;
         let child = Arc::new(shared_child);
         let child_ = child.clone();
-        let guard = Arc::new(RwLock::new(()));
-
         let (tx, rx) = channel(1);
 
-        spawn_pipe_reader(
+        let stdout_thread = spawn_pipe_reader(tx.clone(), stdout_reader, CommandEvent::Stdout, raw);
-            tx.clone(),
+        let stderr_thread = spawn_pipe_reader(tx.clone(), stderr_reader, CommandEvent::Stderr, raw);
-            guard.clone(),
-            stdout_reader,
-            CommandEvent::Stdout,
-            raw,
-        );
-        spawn_pipe_reader(
-            tx.clone(),
-            guard.clone(),
-            stderr_reader,
-            CommandEvent::Stderr,
-            raw,
-        );
 
         spawn(move || {
-            let _ = match child_.wait() {
+            let status = child_.wait();
-                Ok(status) => {
+            // `Terminated` must be the last event: wait for the readers to drain the pipes,
-                    let _l = guard.write().unwrap();
+            // since a short-lived child can exit before they have read anything.
-                    block_on_task(async move {
+            let _ = stdout_thread.join();
-                        tx.send(CommandEvent::Terminated(TerminatedPayload {
+            let _ = stderr_thread.join();
-                            code: status.code(),
+            let _ = match status {
-                            #[cfg(windows)]
+                Ok(status) => block_on_task(async move {
-                            signal: None,
+                    tx.send(CommandEvent::Terminated(TerminatedPayload {
-                            #[cfg(unix)]
+                        code: status.code(),
-                            signal: status.signal(),
+                        #[cfg(windows)]
-                        }))
+                        signal: None,
-                        .await
+                        #[cfg(unix)]
-                    })
+                        signal: status.signal(),
-                }
+                    }))
+                    .await
+                }),
                 Err(e) => {
-                    let _l = guard.write().unwrap();
                     block_on_task(async move { tx.send(CommandEvent::Error(e.to_string())).await })
                 }
             };
@@ -489,13 +476,11 @@ fn read_line<F: Fn(Vec<u8>) -> CommandEvent + Send + Copy + 'static>(
 
 fn spawn_pipe_reader<F: Fn(Vec<u8>) -> CommandEvent + Send + Copy + 'static>(
     tx: Sender<CommandEvent>,
-    guard: Arc<RwLock<()>>,
     pipe_reader: PipeReader,
     wrapper: F,
     raw_out: bool,
-) {
+) -> JoinHandle<()> {
     spawn(move || {
-        let _lock = guard.read().unwrap();
         let reader = BufReader::new(pipe_reader);
 
         if raw_out {
@@ -503,7 +488,7 @@ fn spawn_pipe_reader<F: Fn(Vec<u8>) -> CommandEvent + Send + Copy + 'static>(
         } else {
             read_line(reader, tx, wrapper);
         }
-    });
+    })
 }
 
 // tests for the commands functions.