Repository: beeware/briefcase

Issue:
Fast-failing Android app hangs at "Launching app..."
If an Android app fails extremely quickly, Briefcase will hang at the `Launching app...` waitbar.

**To Reproduce**
Steps to reproduce the behavior:
1. Create a Hello World Toga app.
2. Modify pyproject.toml to *not* have `toga-android` as a requirement.
3. Build and run the app on Android

The app will build and attempt to start, but will hang at the `Launching app...` waitbar.

If you hit CTRL-C and start the app a second time, you get the stack trace that indicates that `import toga` failed.

**Expected behavior**

The `Launching app...` waitbar shouldn't hang. Ideally, you'd get the partial log to highlight the problem; but at the very least it should indicate that the launch failed.

**Environment:**
 - Operating System: macOS
 - Python version: All
 - Software versions:
   - Briefcase: 0.3.11+
   - Toga: 0.3.0dev39+

**Additional context**

I found this when running a Briefcase app that was using Toga installed from a source checkout; for some reason, the wheels were built, but they didn't appear in the `app` folder. Not sure why that was happening; I'm still investigating that problem.


Discussion:

Patch:
diff --git a/changes/936.bugfix.rst b/changes/936.bugfix.rst
new file mode 100644
index 00000000..61210436
--- /dev/null
+++ b/changes/936.bugfix.rst
@@ -0,0 +1,1 @@
+An Android application that successfully starts, but fails quickly, no longer stalls the launch process.
diff --git a/src/briefcase/integrations/android_sdk.py b/src/briefcase/integrations/android_sdk.py
index faa4f6e8..ae2ae266 100644
--- a/src/briefcase/integrations/android_sdk.py
+++ b/src/briefcase/integrations/android_sdk.py
@@ -1144,14 +1144,19 @@ class ADB:
                 f"Unable to determine if emulator {self.device} has booted."
             ) from e
 
-    def run(self, *arguments):
+    def run(self, *arguments, quiet=False):
         """Run a command on a device using Android debug bridge, `adb`. The
         device name is mandatory to ensure clarity in the case of multiple
         attached devices.
 
         :param arguments: List of strings to pass to `adb` as arguments.
-
-        Returns `adb` output on success; raises an exception on failure.
+        :param quiet: Should the invocation of this command be silent, and
+            *not* appear in the logs? This should almost always be False;
+            however, for some calls (most notably, calls that are called
+            frequently to evaluate the status of another process), logging can
+            be turned off so that log output isn't corrupted by thousands of
+            polling calls.
+        :returns: `adb` output on success; raises an exception on failure.
         """
         # The ADB integration operates on the basis of running commands before
         # checking that they are valid, then parsing output to notice errors.
@@ -1170,6 +1175,7 @@ class ADB:
                     for arg in arguments
                 ],
                 stderr=subprocess.STDOUT,
+                quiet=quiet,
             )
         except subprocess.CalledProcessError as e:
             if any(DEVICE_NOT_FOUND.match(line) for line in e.output.split("\n")):
@@ -1253,7 +1259,34 @@ Activity class not found while starting app.
             ) from e
 
     def logcat(self, pid):
-        """Start tailing the adb log for the device."""
+        """Start following the adb log for the device.
+
+        :param pid: The PID whose logs you want to display.
+        :returns: A Popen object for the logcat call
+        """
+        return self.tools.subprocess.Popen(
+            [
+                os.fsdecode(self.tools.android_sdk.adb_path),
+                "-s",
+                self.device,
+                "logcat",
+                "--pid",  # This option is available since API level 24.
+                pid,
+            ]
+            # Filter out some noisy and useless tags.
+            + [f"{tag}:S" for tag in ["EGL_emulation"]],
+            env=self.tools.android_sdk.env,
+            stdout=subprocess.PIPE,
+            stderr=subprocess.STDOUT,
+            bufsize=1,
+        )
+
+    def logcat_tail(self, since=None):
+        """Show the tail of the logs for Python-like apps, starting from a
+        given timestamp.
+
+        :param since: The start time from which logs should be displayed
+        """
         try:
             self.tools.subprocess.run(
                 [
@@ -1261,30 +1294,49 @@ Activity class not found while starting app.
                     "-s",
                     self.device,
                     "logcat",
-                    "--pid",  # This option is available since API level 24.
-                    pid,
-                ]
-                # Filter out some noisy and useless tags.
-                + [f"{tag}:S" for tag in ["EGL_emulation"]],
+                    "-t",
+                    since.strftime("%m-%d %H:%M:%S.000000"),
+                    "-s",
+                    # This is a collection of log labels that should catch
+                    # most Python app output.
+                    "MainActivity:*",
+                    "stdio:*",
+                    "python.stdout:*",
+                    "AndroidRuntime:*",
+                ],
                 env=self.tools.android_sdk.env,
                 check=True,
             )
         except subprocess.CalledProcessError as e:
-            # If the user sends CTRL+C:
-            #  - on Windows, adb returns 0xC000013A (STATUS_CONTROL_C_EXIT)
-            #  - on Linux/macOS, adb returns -2.
-            # Exit normally since the user was instructed to use CTRL+C.
-            if e.returncode not in {-2, 0xC000013A}:
-                raise BriefcaseCommandError("Error starting ADB logcat.") from e
-
-    def pidof(self, package):
-        """Return the PID of the given app as a string, or None if it isn't
-        running."""
+            raise BriefcaseCommandError("Error starting ADB logcat.") from e
+
+    def pidof(self, package, **kwargs):
+        """Obtain the PID of a running app by package name.
+
+        :param package: The package ID for the application (e.g.,
+            ``org.beeware.tutorial``)
+        :returns: The PID of the given app as a string, or None if it isn't
+        running.
+        """
         # The pidof command is available since API level 24. The level 23 emulator image also
         # includes it, but it doesn't work correctly (it returns all processes).
         try:
             # Exit status is unreliable: some devices (e.g. Nexus 4) return 0 even when no
             # process was found.
-            return self.run("shell", "pidof", "-s", package).strip() or None
+            return self.run("shell", "pidof", "-s", package, **kwargs).strip() or None
         except subprocess.CalledProcessError:
             return None
+
+    def pid_exists(self, pid, **kwargs):
+        """Confirm if the PID exists on the emulator.
+
+        :param pid: The PID to check
+        :returns: True if the PID exists, False if it doesn't.
+        """
+        # Look for the existence of /proc/<PID> on the device filesystem.
+        # If that file exists, so does the process.
+        try:
+            self.run("shell", "test", "-e", f"/proc/{pid}", **kwargs)
+            return True
+        except subprocess.CalledProcessError:
+            return False
diff --git a/src/briefcase/integrations/subprocess.py b/src/briefcase/integrations/subprocess.py
index 7e470ded..4252cba1 100644
--- a/src/briefcase/integrations/subprocess.py
+++ b/src/briefcase/integrations/subprocess.py
@@ -444,7 +444,7 @@ class Subprocess:
         return subprocess.CompletedProcess(args, return_code, stderr=stderr)
 
     @ensure_console_is_safe
-    def check_output(self, args, **kwargs):
+    def check_output(self, args, quiet=False, **kwargs):
         """A wrapper for subprocess.check_output()
 
         The behavior of this method is identical to
@@ -454,22 +454,32 @@ class Subprocess:
            environment.
          - The `text` argument is defaulted to True so all output
            is returned as strings instead of bytes.
+
+        :param quiet: Should the invocation of this command be silent, and
+            *not* appear in the logs? This should almost always be False;
+            however, for some calls (most notably, calls that are called
+            frequently to evaluate the status of another process), logging can
+            be turned off so that log output isn't corrupted by thousands of
+            polling calls.
         """
-        self._log_command(args)
-        self._log_cwd(kwargs.get("cwd"))
-        self._log_environment(kwargs.get("env"))
+        if not quiet:
+            self._log_command(args)
+            self._log_cwd(kwargs.get("cwd"))
+            self._log_environment(kwargs.get("env"))
 
         try:
             cmd_output = self._subprocess.check_output(
                 [str(arg) for arg in args], **self.final_kwargs(**kwargs)
             )
         except subprocess.CalledProcessError as e:
-            self._log_output(e.output, e.stderr)
-            self._log_return_code(e.returncode)
+            if not quiet:
+                self._log_output(e.output, e.stderr)
+                self._log_return_code(e.returncode)
             raise
 
-        self._log_output(cmd_output)
-        self._log_return_code(0)
+        if not quiet:
+            self._log_output(cmd_output)
+            self._log_return_code(0)
         return cmd_output
 
     def parse_output(self, output_parser, args, **kwargs):
diff --git a/src/briefcase/platforms/android/gradle.py b/src/briefcase/platforms/android/gradle.py
index 5104c5a9..b3997533 100644
--- a/src/briefcase/platforms/android/gradle.py
+++ b/src/briefcase/platforms/android/gradle.py
@@ -1,3 +1,4 @@
+import datetime
 import re
 import subprocess
 import time
@@ -229,22 +230,55 @@ class GradleRunCommand(GradleMixin, RunCommand):
 
         # To start the app, we launch `org.beeware.android.MainActivity`.
         with self.input.wait_bar("Launching app..."):
+            # Any log after this point must be associated with the new instance
+            start_time = datetime.datetime.now()
             adb.start_app(package, "org.beeware.android.MainActivity")
             pid = None
-            while not pid:
-                pid = adb.pidof(package)
+            attempts = 0
+            delay = 0.01
+
+            # Try to get the PID for 5 seconds.
+            fail_time = start_time + datetime.timedelta(seconds=5)
+            while not pid and datetime.datetime.now() < fail_time:
+                # Try to get the PID; run in quiet mode because we may
+                # need to do this a lot in the next 5 seconds.
+                pid = adb.pidof(package, quiet=True)
                 if not pid:
-                    time.sleep(0.5)
+                    time.sleep(delay)
+                attempts += 1
 
-        try:
-            self.logger.info(
-                "Following device log output (type CTRL-C to stop log)...",
-                prefix=app.app_name,
-            )
-            self.logger.info("=" * 75)
-            adb.logcat(pid)
-        except KeyboardInterrupt:
-            pass  # catch CTRL-C to exit normally
+        if pid:
+            try:
+                self.logger.info(
+                    "Following device log output (type CTRL-C to stop log)...",
+                    prefix=app.app_name,
+                )
+                self.logger.info("=" * 75)
+                log_popen = adb.logcat(pid=pid)
+
+                self.tools.subprocess.stream_output(
+                    "log stream",
+                    log_popen,
+                    # Check for the PID in quiet mode so logs aren't corrupted.
+                    stop_func=lambda: not adb.pid_exists(pid=pid, quiet=True),
+                )
+
+            except KeyboardInterrupt:
+                pass  # catch CTRL-C to exit normally
+            finally:
+                self.tools.subprocess.cleanup("log stream", log_popen)
+
+        else:
+            self.logger.error("Unable to find PID for app", prefix=app.app_name)
+            self.logger.error("Logs for launch attempt follow...")
+
+            # Show the log from the start time of the app
+            self.logger.error("=" * 75)
+
+            # Pad by a few seconds because the android emulator's clock and the
+            # local system clock may not be perfectly aligned.
+            adb.logcat_tail(since=start_time - datetime.timedelta(seconds=10))
+            raise BriefcaseCommandError(f"Problem starting app {app.app_name!r}")
 
 
 class GradlePackageCommand(GradleMixin, PackageCommand):


Test patch:
diff --git a/tests/integrations/android_sdk/ADB/test_logcat.py b/tests/integrations/android_sdk/ADB/test_logcat.py
index 7151f503..6eeb6a55 100644
--- a/tests/integrations/android_sdk/ADB/test_logcat.py
+++ b/tests/integrations/android_sdk/ADB/test_logcat.py
@@ -1,23 +1,24 @@
 import os
 import subprocess
-from unittest.mock import MagicMock
+from unittest import mock
 
-import pytest
-
-from briefcase.exceptions import BriefcaseCommandError
 from briefcase.integrations.android_sdk import ADB
 
 
 def test_logcat(mock_tools):
-    """Invoking `logcat()` calls `run()` with the appropriate parameters."""
+    """Invoking `logcat()` calls `Popen()` with the appropriate parameters."""
     # Mock out the run command on an adb instance
     adb = ADB(mock_tools, "exampleDevice")
 
+    # Mock the result of calling Popen so we can compare against this return value
+    popen = mock.MagicMock()
+    mock_tools.subprocess.Popen.return_value = popen
+
     # Invoke logcat
-    adb.logcat("1234")
+    result = adb.logcat("1234")
 
     # Validate call parameters.
-    mock_tools.subprocess.run.assert_called_once_with(
+    mock_tools.subprocess.Popen.assert_called_once_with(
         [
             os.fsdecode(mock_tools.android_sdk.adb_path),
             "-s",
@@ -28,39 +29,10 @@ def test_logcat(mock_tools):
             "EGL_emulation:S",
         ],
         env=mock_tools.android_sdk.env,
-        check=True,
-    )
-
-
-def test_adb_failure(mock_tools):
-    """If adb logcat fails, the error is caught."""
-    # Mock out the run command on an adb instance
-    adb = ADB(mock_tools, "exampleDevice")
-    mock_tools.subprocess.run = MagicMock(
-        side_effect=subprocess.CalledProcessError(returncode=1, cmd="adb logcat")
-    )
-
-    with pytest.raises(BriefcaseCommandError):
-        adb.logcat("1234")
-
-
-@pytest.mark.parametrize(
-    "return_code",
-    (
-        0xC000013A,  # Windows: STATUS_CONTROL_C_EXIT in hex
-        3221225786,  # Windows: STATUS_CONTROL_C_EXIT in dec
-        -2,  # Linux/macOS
-    ),
-)
-def test_adb_ctrl_c(mock_tools, return_code):
-    """When the user sends CTRL+C, exit normally."""
-    # Mock out the run command on an adb instance
-    adb = ADB(mock_tools, "exampleDevice")
-    mock_tools.subprocess.run = MagicMock(
-        side_effect=subprocess.CalledProcessError(
-            returncode=return_code, cmd="adb logcat"
-        )
+        stdout=subprocess.PIPE,
+        stderr=subprocess.STDOUT,
+        bufsize=1,
     )
 
-    # does not raise BriefcaseCommandError
-    adb.logcat("1234")
+    # The Popen object is returned
+    assert result == popen
diff --git a/tests/integrations/android_sdk/ADB/test_logcat_tail.py b/tests/integrations/android_sdk/ADB/test_logcat_tail.py
new file mode 100644
index 00000000..402dcaeb
--- /dev/null
+++ b/tests/integrations/android_sdk/ADB/test_logcat_tail.py
@@ -0,0 +1,50 @@
+import os
+import subprocess
+from datetime import datetime
+from unittest.mock import MagicMock
+
+import pytest
+
+from briefcase.exceptions import BriefcaseCommandError
+from briefcase.integrations.android_sdk import ADB
+
+
+def test_logcat_tail(mock_tools):
+    """Invoking `logcat_tail()` calls `run()` with the appropriate
+    parameters."""
+    # Mock out the run command on an adb instance
+    adb = ADB(mock_tools, "exampleDevice")
+
+    # Invoke logcat_tail with a specific timestamp
+    adb.logcat_tail(since=datetime(2022, 11, 10, 9, 8, 7))
+
+    # Validate call parameters.
+    mock_tools.subprocess.run.assert_called_once_with(
+        [
+            os.fsdecode(mock_tools.android_sdk.adb_path),
+            "-s",
+            "exampleDevice",
+            "logcat",
+            "-t",
+            "11-10 09:08:07.000000",
+            "-s",
+            "MainActivity:*",
+            "stdio:*",
+            "python.stdout:*",
+            "AndroidRuntime:*",
+        ],
+        env=mock_tools.android_sdk.env,
+        check=True,
+    )
+
+
+def test_adb_failure(mock_tools):
+    """If adb logcat fails, the error is caught."""
+    # Mock out the run command on an adb instance
+    adb = ADB(mock_tools, "exampleDevice")
+    mock_tools.subprocess.run = MagicMock(
+        side_effect=subprocess.CalledProcessError(returncode=1, cmd="adb logcat")
+    )
+
+    with pytest.raises(BriefcaseCommandError):
+        adb.logcat_tail(since=datetime(2022, 11, 10, 9, 8, 7))
diff --git a/tests/integrations/android_sdk/ADB/test_pid_exists.py b/tests/integrations/android_sdk/ADB/test_pid_exists.py
new file mode 100644
index 00000000..c484a1d2
--- /dev/null
+++ b/tests/integrations/android_sdk/ADB/test_pid_exists.py
@@ -0,0 +1,28 @@
+import subprocess
+from unittest.mock import Mock
+
+from briefcase.integrations.android_sdk import ADB
+
+
+def test_pid_exists_succeed(mock_tools):
+    "adb.pid_exists() can be called on an process that exists."
+    adb = ADB(mock_tools, "exampleDevice")
+    adb.run = Mock(return_value="")
+    assert adb.pid_exists("1234")
+    adb.run.assert_called_once_with("shell", "test", "-e", "/proc/1234")
+
+
+def test_pid_exists_quiet(mock_tools):
+    "adb.pid_exists() can be called in quiet mode on an process that exists."
+    adb = ADB(mock_tools, "exampleDevice")
+    adb.run = Mock(return_value="")
+    assert adb.pid_exists("1234", quiet=True)
+    adb.run.assert_called_once_with("shell", "test", "-e", "/proc/1234", quiet=True)
+
+
+def test_pid_does_not_exist(mock_tools):
+    "If adb.pid_exists() returns a status code of 1, it is interpreted as the process not existing."
+    adb = ADB(mock_tools, "exampleDevice")
+    adb.run = Mock(side_effect=subprocess.CalledProcessError(returncode=1, cmd="test"))
+    assert not adb.pid_exists("9999") is None
+    adb.run.assert_called_once_with("shell", "test", "-e", "/proc/9999")
diff --git a/tests/integrations/android_sdk/ADB/test_pidof.py b/tests/integrations/android_sdk/ADB/test_pidof.py
index 788f1675..3ed84610 100644
--- a/tests/integrations/android_sdk/ADB/test_pidof.py
+++ b/tests/integrations/android_sdk/ADB/test_pidof.py
@@ -5,19 +5,32 @@ from briefcase.integrations.android_sdk import ADB
 
 
 def test_pidof_succeed(mock_tools):
+    "adb.pidof() can be called on an process that exists."
     adb = ADB(mock_tools, "exampleDevice")
     adb.run = Mock(return_value="5678\n")
     assert adb.pidof("com.example") == "5678"
     adb.run.assert_called_once_with("shell", "pidof", "-s", "com.example")
 
 
+def test_pidof_quiet(mock_tools):
+    "adb.pidof() can be called in quiet mode on an process that exists."
+    adb = ADB(mock_tools, "exampleDevice")
+    adb.run = Mock(return_value="5678\n")
+    assert adb.pidof("com.example", quiet=True) == "5678"
+    adb.run.assert_called_once_with("shell", "pidof", "-s", "com.example", quiet=True)
+
+
 def test_pidof_fail_exit_0(mock_tools):
+    "If adb.pidof() returns a PID of 0, it is interpreted as the process not existing."
     adb = ADB(mock_tools, "exampleDevice")
     adb.run = Mock(return_value="")
     assert adb.pidof("com.example") is None
+    adb.run.assert_called_once_with("shell", "pidof", "-s", "com.example")
 
 
 def test_pidof_fail_exit_1(mock_tools):
+    "If adb.pidof() fails, it is interpreted as the process not existing."
     adb = ADB(mock_tools, "exampleDevice")
     adb.run = Mock(side_effect=subprocess.CalledProcessError(1, "adb shell"))
     assert adb.pidof("com.example") is None
+    adb.run.assert_called_once_with("shell", "pidof", "-s", "com.example")
diff --git a/tests/integrations/android_sdk/ADB/test_command.py b/tests/integrations/android_sdk/ADB/test_run.py
similarity index 74%
rename from tests/integrations/android_sdk/ADB/test_command.py
rename to tests/integrations/android_sdk/ADB/test_run.py
index f6c246c6..edc6b565 100644
--- a/tests/integrations/android_sdk/ADB/test_command.py
+++ b/tests/integrations/android_sdk/ADB/test_run.py
@@ -10,7 +10,7 @@ from briefcase.integrations.android_sdk import ADB
 
 
 def test_simple_command(mock_tools, tmp_path):
-    """ADB.command() invokes adb with the provided arguments."""
+    """ADB.run() invokes adb with the provided arguments."""
     # Create an ADB instance and invoke command()
     adb = ADB(mock_tools, "exampleDevice")
 
@@ -31,6 +31,33 @@ def test_simple_command(mock_tools, tmp_path):
             "command",
         ],
         stderr=subprocess.STDOUT,
+        quiet=False,
+    )
+
+
+def test_quiet_command(mock_tools, tmp_path):
+    """ADB.run() can be invoked in quiet mode."""
+    # Create an ADB instance and invoke command()
+    adb = ADB(mock_tools, "exampleDevice")
+
+    adb.run("example", "command", quiet=True)
+
+    # Check that adb was invoked with the expected commands
+    mock_tools.subprocess.check_output.assert_called_once_with(
+        [
+            os.fsdecode(
+                tmp_path
+                / "sdk"
+                / "platform-tools"
+                / f"adb{'.exe' if sys.platform == 'win32' else ''}"
+            ),
+            "-s",
+            "exampleDevice",
+            "example",
+            "command",
+        ],
+        stderr=subprocess.STDOUT,
+        quiet=True,
     )
 
 
@@ -46,7 +73,7 @@ def test_simple_command(mock_tools, tmp_path):
     ],
 )
 def test_error_handling(mock_tools, tmp_path, name, exception):
-    """ADB.command() can parse errors returned by adb."""
+    """ADB.run() can parse errors returned by adb."""
     # Set up a mock command with a subprocess module that has with sample data loaded.
     adb_samples = Path(__file__).parent / "adb_errors"
     with (adb_samples / (name + ".out")).open("r") as adb_output_file:
@@ -81,4 +108,5 @@ def test_error_handling(mock_tools, tmp_path, name, exception):
             "command",
         ],
         stderr=subprocess.STDOUT,
+        quiet=False,
     )
diff --git a/tests/integrations/subprocess/test_Subprocess__check_output.py b/tests/integrations/subprocess/test_Subprocess__check_output.py
index 98e5d9ea..cc5307da 100644
--- a/tests/integrations/subprocess/test_Subprocess__check_output.py
+++ b/tests/integrations/subprocess/test_Subprocess__check_output.py
@@ -190,6 +190,34 @@ def test_debug_call_with_env(mock_sub, capsys, tmp_path):
     assert capsys.readouterr().out == expected_output
 
 
+def test_debug_call_with_quiet(mock_sub, capsys, tmp_path):
+    """If quiet mode is on, calls aren't logged, even if verbosity is turned
+    up."""
+    mock_sub.tools.logger.verbosity = 2
+
+    env = {"NewVar": "NewVarValue"}
+    mock_sub.check_output(
+        ["hello", "world"],
+        env=env,
+        cwd=tmp_path / "cwd",
+        quiet=True,
+    )
+
+    merged_env = mock_sub.tools.os.environ.copy()
+    merged_env.update(env)
+
+    mock_sub._subprocess.check_output.assert_called_with(
+        ["hello", "world"],
+        env=merged_env,
+        cwd=os.fsdecode(tmp_path / "cwd"),
+        text=True,
+        encoding=ANY,
+    )
+
+    # No output
+    assert capsys.readouterr().out == ""
+
+
 def test_calledprocesserror_exception_logging(mock_sub, capsys):
     """If command errors, ensure command output is printed."""
     mock_sub.tools.logger.verbosity = 2
@@ -223,6 +251,25 @@ def test_calledprocesserror_exception_logging(mock_sub, capsys):
     assert capsys.readouterr().out == expected_output
 
 
+def test_calledprocesserror_exception_quiet(mock_sub, capsys):
+    """If command errors in quiet mode, no command output is printed."""
+    mock_sub.tools.logger.verbosity = 2
+
+    called_process_error = CalledProcessError(
+        returncode=-1,
+        cmd="hello world",
+        output="output line 1\noutput line 2",
+        stderr="error line 1\nerror line 2",
+    )
+    mock_sub._subprocess.check_output.side_effect = called_process_error
+
+    with pytest.raises(CalledProcessError):
+        mock_sub.check_output(["hello", "world"], quiet=True)
+
+    # No ouput in quiet mode
+    assert capsys.readouterr().out == ""
+
+
 def test_calledprocesserror_exception_logging_no_cmd_output(mock_sub, capsys):
     """If command errors, and there is no command output, errors are still
     printed."""
diff --git a/tests/platforms/android/gradle/test_run.py b/tests/platforms/android/gradle/test_run.py
index 96ada255..b744e829 100644
--- a/tests/platforms/android/gradle/test_run.py
+++ b/tests/platforms/android/gradle/test_run.py
@@ -1,3 +1,4 @@
+import datetime
 import os
 import platform
 import subprocess
@@ -5,12 +6,13 @@ import sys
 import time
 from os.path import normpath
 from pathlib import Path
-from unittest.mock import MagicMock, call
+from unittest import mock
 
 import pytest
 import requests
 
 from briefcase.console import Console, Log
+from briefcase.exceptions import BriefcaseCommandError
 from briefcase.integrations.android_sdk import ADB, AndroidSDK
 from briefcase.integrations.java import JDK
 from briefcase.integrations.subprocess import Subprocess
@@ -19,7 +21,7 @@ from briefcase.platforms.android.gradle import GradleRunCommand
 
 @pytest.fixture
 def jdk():
-    jdk = MagicMock()
+    jdk = mock.MagicMock()
     jdk.java_home = Path("/path/to/java")
     return jdk
 
@@ -32,21 +34,21 @@ def run_command(tmp_path, first_app_config, jdk):
         base_path=tmp_path / "base_path",
         data_path=tmp_path / "briefcase",
     )
-    command.tools.mock_adb = MagicMock(spec_set=ADB)
-    command.tools.mock_adb.pidof = MagicMock(return_value="777")
-    command.tools.java = MagicMock(spec=JDK)
+    command.tools.mock_adb = mock.MagicMock(spec_set=ADB)
+    command.tools.mock_adb.pidof = mock.MagicMock(return_value="777")
+    command.tools.java = mock.MagicMock(spec=JDK)
     command.tools.java.java_home = "/path/to/java"
     command.tools.android_sdk = AndroidSDK(
         command.tools,
         root_path=Path("/path/to/android_sdk"),
     )
-    command.tools.android_sdk.adb = MagicMock(return_value=command.tools.mock_adb)
+    command.tools.android_sdk.adb = mock.MagicMock(return_value=command.tools.mock_adb)
 
-    command.tools.os = MagicMock(spec_set=os)
+    command.tools.os = mock.MagicMock(spec_set=os)
     command.tools.os.environ = {}
-    command.tools.requests = MagicMock(spec_set=requests)
-    command.tools.subprocess = MagicMock(spec_set=Subprocess)
-    command.tools.sys = MagicMock(spec_set=sys)
+    command.tools.requests = mock.MagicMock(spec_set=requests)
+    command.tools.subprocess = mock.MagicMock(spec_set=Subprocess)
+    command.tools.sys = mock.MagicMock(spec_set=sys)
 
     command.base_path.mkdir(parents=True)
     return command
@@ -79,9 +81,21 @@ def test_device_option(run_command):
 def test_run_existing_device(run_command, first_app_config):
     """An app can be run on an existing device."""
     # Set up device selection to return a running physical device.
-    run_command.tools.android_sdk.select_target_device = MagicMock(
+    run_command.tools.android_sdk.select_target_device = mock.MagicMock(
         return_value=("exampleDevice", "ExampleDevice", None)
     )
+
+    # Set up the log streamer to return a known stream
+    log_popen = mock.MagicMock()
+    run_command.tools.mock_adb.logcat.return_value = log_popen
+
+    # To satisfy coverage, the stop function must be invoked at least once
+    # when invoking stream_output.
+    def mock_stream_output(label, popen_process, stop_func):
+        stop_func()
+
+    run_command.tools.subprocess.stream_output.side_effect = mock_stream_output
+
     # Set up app config to have a `-` in the `bundle`, to ensure it gets
     # normalized into a `_` via `package_name`.
     first_app_config.bundle = "com.ex-ample"
@@ -111,40 +125,102 @@ def test_run_existing_device(run_command, first_app_config):
     )
 
     run_command.tools.mock_adb.pidof.assert_called_once_with(
-        f"{first_app_config.package_name}.{first_app_config.module_name}"
+        f"{first_app_config.package_name}.{first_app_config.module_name}",
+        quiet=True,
+    )
+    run_command.tools.mock_adb.logcat.assert_called_once_with(pid="777")
+
+    run_command.tools.subprocess.stream_output.assert_called_once_with(
+        "log stream", log_popen, stop_func=mock.ANY
     )
-    run_command.tools.mock_adb.logcat.assert_called_once_with("777")
 
 
 def test_run_slow_start(run_command, first_app_config, monkeypatch):
-    run_command.tools.android_sdk.select_target_device = MagicMock(
+    """If the app is slow to start, multiple calls to pidof will be made."""
+    run_command.tools.android_sdk.select_target_device = mock.MagicMock(
         return_value=("exampleDevice", "ExampleDevice", None)
     )
+
+    # Set up the log streamer to return a known stream
+    log_popen = mock.MagicMock()
+    run_command.tools.mock_adb.logcat.return_value = log_popen
+
+    # Mock the pidof call taking 3 attempts to return
     run_command.tools.mock_adb.pidof.side_effect = [None, None, "888"]
-    monkeypatch.setattr(time, "sleep", MagicMock())
+    monkeypatch.setattr(time, "sleep", mock.MagicMock())
 
     run_command.run_app(first_app_config, device_or_avd="exampleDevice")
 
     assert (
         run_command.tools.mock_adb.pidof.mock_calls
-        == [call("com.example.first_app")] * 3
+        == [mock.call("com.example.first_app", quiet=True)] * 3
+    )
+    assert time.sleep.mock_calls == [mock.call(0.01)] * 2
+    run_command.tools.mock_adb.logcat.assert_called_once_with(pid="888")
+
+    run_command.tools.subprocess.stream_output.assert_called_once_with(
+        "log stream", log_popen, stop_func=mock.ANY
+    )
+
+
+def test_run_crash_at_start(run_command, first_app_config, monkeypatch):
+    """If the app crashes before a PID can be read, a log dump is shown."""
+    run_command.tools.android_sdk.select_target_device = mock.MagicMock(
+        return_value=("exampleDevice", "ExampleDevice", None)
+    )
+
+    # Mock the pidof call failing multiple times before a timeout.
+    run_command.tools.mock_adb.pidof.side_effect = [None] * 5
+    monkeypatch.setattr(time, "sleep", mock.MagicMock())
+
+    # It's the eternal september...
+    start_datetime = datetime.datetime(2022, 9, 8, 7, 6, 42)
+    mock_datetime = mock.MagicMock(spec=datetime.datetime)
+    # Mock datetime.now() at +0s, +0.5s, +1.5s,... +5.5s
+    mock_datetime.now.side_effect = [
+        start_datetime + datetime.timedelta(seconds=delay)
+        for delay in [0] + [x + 0.5 for x in range(0, 6)]
+    ]
+    monkeypatch.setattr(datetime, "datetime", mock_datetime)
+
+    with pytest.raises(
+        BriefcaseCommandError, match=r"Problem starting app 'first-app'"
+    ):
+        run_command.run_app(first_app_config, device_or_avd="exampleDevice")
+
+    assert (
+        run_command.tools.mock_adb.pidof.mock_calls
+        == [mock.call("com.example.first_app", quiet=True)] * 5
+    )
+    assert time.sleep.mock_calls == [mock.call(0.01)] * 5
+
+    # The PID was never found, so logs can't be streamed
+    run_command.tools.mock_adb.logcat.assert_not_called()
+
+    # But we will get a log dump from logcat_tail
+    run_command.tools.mock_adb.logcat_tail.assert_called_once_with(
+        since=start_datetime - datetime.timedelta(seconds=10)
     )
-    assert time.sleep.mock_calls == [call(0.5)] * 2
-    run_command.tools.mock_adb.logcat.assert_called_once_with("888")
 
 
 def test_run_created_emulator(run_command, first_app_config):
     """The user can choose to run on a newly created emulator."""
     # Set up device selection to return a completely new emulator
-    run_command.tools.android_sdk.select_target_device = MagicMock(
+    run_command.tools.android_sdk.select_target_device = mock.MagicMock(
         return_value=(None, None, None)
     )
-    run_command.tools.android_sdk.create_emulator = MagicMock(return_value="newDevice")
-    run_command.tools.android_sdk.verify_avd = MagicMock()
-    run_command.tools.android_sdk.start_emulator = MagicMock(
+    run_command.tools.android_sdk.create_emulator = mock.MagicMock(
+        return_value="newDevice"
+    )
+    run_command.tools.android_sdk.verify_avd = mock.MagicMock()
+    run_command.tools.android_sdk.start_emulator = mock.MagicMock(
         return_value=("emulator-3742", "New Device")
     )
 
+    # Set up the log streamer to return a known stream
+    log_popen = mock.MagicMock()
+    run_command.tools.mock_adb.logcat.return_value = log_popen
+
     # Invoke run_app
     run_command.run_app(first_app_config)
 
@@ -174,23 +250,31 @@ def test_run_created_emulator(run_command, first_app_config):
         "org.beeware.android.MainActivity",
     )
 
-    run_command.tools.mock_adb.logcat.assert_called_once_with("777")
+    run_command.tools.mock_adb.logcat.assert_called_once_with(pid="777")
+
+    run_command.tools.subprocess.stream_output.assert_called_once_with(
+        "log stream", log_popen, stop_func=mock.ANY
+    )
 
 
 def test_run_idle_device(run_command, first_app_config):
     """The user can choose to run on an idle device."""
     # Set up device selection to return a new device that has an AVD,
     # but not a device ID.
-    run_command.tools.android_sdk.select_target_device = MagicMock(
+    run_command.tools.android_sdk.select_target_device = mock.MagicMock(
         return_value=(None, "Idle Device", "idleDevice")
     )
 
-    run_command.tools.android_sdk.create_emulator = MagicMock()
-    run_command.tools.android_sdk.verify_avd = MagicMock()
-    run_command.tools.android_sdk.start_emulator = MagicMock(
+    run_command.tools.android_sdk.create_emulator = mock.MagicMock()
+    run_command.tools.android_sdk.verify_avd = mock.MagicMock()
+    run_command.tools.android_sdk.start_emulator = mock.MagicMock(
         return_value=("emulator-3742", "Idle Device")
     )
 
+    # Set up the log streamer to return a known stream
+    log_popen = mock.MagicMock()
+    run_command.tools.mock_adb.logcat.return_value = log_popen
+
     # Invoke run_app
     run_command.run_app(first_app_config)
 
@@ -219,23 +303,41 @@ def test_run_idle_device(run_command, first_app_config):
         "org.beeware.android.MainActivity",
     )
 
-    run_command.tools.mock_adb.logcat.assert_called_once_with("777")
+    run_command.tools.mock_adb.logcat.assert_called_once_with(pid="777")
+
+    run_command.tools.subprocess.stream_output.assert_called_once_with(
+        "log stream", log_popen, stop_func=mock.ANY
+    )
 
 
 def test_run_ctrl_c(run_command, first_app_config, capsys):
     """When CTRL-C is sent during logcat, Briefcase exits normally."""
     # Set up device selection to return a running physical device.
-    run_command.tools.android_sdk.select_target_device = MagicMock(
+    run_command.tools.android_sdk.select_target_device = mock.MagicMock(
         return_value=("exampleDevice", "ExampleDevice", None)
     )
 
-    run_command.tools.mock_adb.logcat.side_effect = KeyboardInterrupt
+    # Set up the log streamer to return a known stream
+    log_popen = mock.MagicMock()
+    run_command.tools.mock_adb.logcat.return_value = log_popen
+
+    # Mock the effect of CTRL-C being hit while streaming
+    run_command.tools.subprocess.stream_output.side_effect = KeyboardInterrupt
 
     # Invoke run_app (and KeyboardInterrupt does not surface)
     run_command.run_app(first_app_config, device_or_avd="exampleDevice")
 
     # logcat is called and raised KeyboardInterrupt
-    run_command.tools.mock_adb.logcat.assert_called_once_with("777")
+    run_command.tools.mock_adb.logcat.assert_called_once_with(pid="777")
+
+    run_command.tools.subprocess.stream_output.assert_called_once_with(
+        "log stream", log_popen, stop_func=mock.ANY
+    )
+
+    # An attempt was made to clean up the log stream
+    run_command.tools.subprocess.cleanup.assert_called_once_with(
+        "log stream", log_popen
+    )
 
     # Shows the try block for KeyboardInterrupt was entered
     assert capsys.readouterr().out.endswith(
@@ -246,9 +348,9 @@ def test_run_ctrl_c(run_command, first_app_config, capsys):
 
 def test_log_file_extra(run_command, monkeypatch):
     """Android commands register a log file extra to list SDK packages."""
-    verify = MagicMock(return_value=run_command.tools.android_sdk)
+    verify = mock.MagicMock(return_value=run_command.tools.android_sdk)
     monkeypatch.setattr(AndroidSDK, "verify", verify)
-    monkeypatch.setattr(AndroidSDK, "verify_emulator", MagicMock())
+    monkeypatch.setattr(AndroidSDK, "verify_emulator", mock.MagicMock())
 
     # Even if one command triggers another, the sdkmanager should only be run once.
     run_command.update_command.verify_tools()