Use Date/Time on Android Device for Fallback Logging

changes/1146.bugfix.rst

@@ -0,0 +1 @@
+The run command now ensures Android logging is shown when the datetime on the device is different from the host machine.

src/briefcase/integrations/android_sdk.py

@@ -1293,10 +1293,10 @@ def avd_name(self) -> str | None:
                     f"Unable to interrogate AVD name of device {self.device}"
                 ) from e
 
-    def has_booted(self):
+    def has_booted(self) -> bool:
         """Determine if the device has completed booting.
 
-        :returns True if it has booted; False otherwise.
+        :returns: True if it has booted; False otherwise.
         """
         try:
             # When the sys.boot_completed property of the device
@@ -1326,8 +1326,6 @@ def run(self, *arguments: SubprocessArgT, quiet: bool = False) -> str:
         # checking that they are valid, then parsing output to notice errors.
         # This keeps performance good in the success case.
         try:
-            # Capture `stderr` so that if the process exits with failure, the
-            # stderr data is in `e.output`.
             return self.tools.subprocess.check_output(
                 [
                     os.fsdecode(self.tools.android_sdk.adb_path),
@@ -1349,8 +1347,7 @@ def install_apk(self, apk_path: str | Path):
         """Install an APK file on an Android device.
 
         :param apk_path: The path of the Android APK file to install.
-
-        Returns `None` on success; raises an exception on failure.
+        :returns: `None` on success; raises an exception on failure.
         """
         try:
             self.run("install", "-r", apk_path)
@@ -1363,8 +1360,7 @@ def force_stop_app(self, package: str):
         """Force-stop an app, specified as a package name.
 
         :param package: The name of the Android package, e.g., com.username.myapp.
-
-        Returns `None` on success; raises an exception on failure.
+        :returns: `None` on success; raises an exception on failure.
         """
         # In my testing, `force-stop` exits with status code 0 (success) so long
         # as you pass a package name, even if the package does not exist, or the
@@ -1379,15 +1375,14 @@ def force_stop_app(self, package: str):
     def start_app(self, package: str, activity: str, passthrough: list[str]):
         """Start an app, specified as a package name & activity name.
 
-        :param package: The name of the Android package, e.g., com.username.myapp.
-        :param activity: The activity of the APK to start.
-        :param passthrough: Arguments to pass to the app.
-
-        Returns `None` on success; raises an exception on failure.
-
         If you have an APK file, and you are not sure of the package or activity
         name, you can find it using `aapt dump badging filename.apk` and looking
         for "package" and "launchable-activity" in the output.
+
+        :param package: The name of the Android package, e.g., com.username.myapp.
+        :param activity: The activity of the APK to start.
+        :param passthrough: Arguments to pass to the app.
+        :returns: `None` on success; raises an exception on failure.
         """
         try:
             # `am start` also accepts string array extras, but we pass the arguments as a
@@ -1429,7 +1424,7 @@ def start_app(self, package: str, activity: str, passthrough: list[str]):
                 f"Unable to start {package}/{activity} on {self.device}"
             ) from e
 
-    def logcat(self, pid: str):
+    def logcat(self, pid: str) -> subprocess.Popen:
         """Start following the adb log for the device.
 
         :param pid: The PID whose logs you want to display.
@@ -1519,4 +1514,18 @@ def kill(self):
         try:
             self.run("emu", "kill")
         except subprocess.CalledProcessError as e:
-            raise BriefcaseCommandError("Error starting ADB logcat.") from e
+            raise BriefcaseCommandError("Error stopping the Android emulator.") from e
+
+    def datetime(self) -> datetime:
+        """Obtain the device's current date/time.
+
+        This date/time is naive (i.e. not timezone aware) and in the device's "local"
+        time. Therefore, it may be quite different from the date/time for Briefcase and
+        caution should be used if comparing it to machine's "local" time.
+        """
+        datetime_format = "%Y-%m-%d %H:%M:%S"
+        try:
+            device_datetime = self.run("shell", "date", f"+'{datetime_format}'").strip()
+            return datetime.strptime(device_datetime, datetime_format)
+        except (ValueError, subprocess.CalledProcessError) as e:
+            raise BriefcaseCommandError("Error obtaining device date/time.") from e

src/briefcase/platforms/android/gradle.py

@@ -277,19 +277,13 @@ def run_app(
                 extra = f" (with {' '.join(extra_emulator_args)})"
             else:
                 extra = ""
-            self.logger.info(
-                f"Starting emulator {avd}{extra}...",
-                prefix=app.app_name,
-            )
+            self.logger.info(f"Starting emulator {avd}{extra}...", prefix=app.app_name)
             device, name = self.tools.android_sdk.start_emulator(
                 avd, extra_emulator_args
             )
 
         try:
-            if test_mode:
-                label = "test suite"
-            else:
-                label = "app"
+            label = "test suite" if test_mode else "app"
 
             self.logger.info(
                 f"Starting {label} on {name} (device ID {device})", prefix=app.app_name
@@ -313,29 +307,27 @@ def run_app(
 
             # To start the app, we launch `org.beeware.android.MainActivity`.
             with self.input.wait_bar(f"Launching {label}..."):
-                # Any log after this point must be associated with the new instance
-                start_time = datetime.datetime.now()
+                # capture the earliest time for device logging in case PID not found
+                device_start_time = adb.datetime()
+
                 adb.start_app(package, "org.beeware.android.MainActivity", passthrough)
-                pid = None
-                attempts = 0
-                delay = 0.01
 
                 # Try to get the PID for 5 seconds.
-                fail_time = start_time + datetime.timedelta(seconds=5)
+                pid = None
+                fail_time = datetime.datetime.now() + 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(delay)
-                    attempts += 1
+                        time.sleep(0.01)
 
             if pid:
                 self.logger.info(
                     "Following device log output (type CTRL-C to stop log)...",
                     prefix=app.app_name,
                 )
-                # Start the app in a way that lets us stream the logs
+                # Start adb's logcat in a way that lets us stream the logs
                 log_popen = adb.logcat(pid=pid)
 
                 # Stream the app logs.
@@ -352,13 +344,11 @@ def run_app(
             else:
                 self.logger.error("Unable to find PID for app", prefix=app.app_name)
                 self.logger.error("Logs for launch attempt follow...")
+                self.logger.error("=" * 75)
 
                 # Show the log from the start time of the app
-                self.logger.error("=" * 75)
+                adb.logcat_tail(since=device_start_time)
 
-                # 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}")
         finally:
             if shutdown_on_exit:

tests/integrations/android_sdk/ADB/test_avd_name.py

@@ -4,13 +4,11 @@
 import pytest
 
 from briefcase.exceptions import BriefcaseCommandError, InvalidDeviceError
-from briefcase.integrations.android_sdk import ADB
 
 
-def test_emulator(mock_tools, capsys):
+def test_emulator(adb, capsys):
     """Invoking `avd_name()` on an emulator returns the AVD."""
     # Mock out the adb response for an emulator
-    adb = ADB(mock_tools, "deafbeefcafe")
     adb.run = MagicMock(return_value="exampledevice\nOK\n")
 
     # Invoke avd_name
@@ -20,10 +18,9 @@ def test_emulator(mock_tools, capsys):
     adb.run.assert_called_once_with("emu", "avd", "name")
 
 
-def test_device(mock_tools, capsys):
+def test_device(adb, capsys):
     """Invoking `avd_name()` on a device returns None."""
     # Mock out the adb response for a physical device
-    adb = ADB(mock_tools, "deafbeefcafe")
     adb.run = MagicMock(
         side_effect=subprocess.CalledProcessError(returncode=1, cmd="emu avd name")
     )
@@ -35,10 +32,9 @@ def test_device(mock_tools, capsys):
     adb.run.assert_called_once_with("emu", "avd", "name")
 
 
-def test_adb_failure(mock_tools, capsys):
+def test_adb_failure(adb, capsys):
     """If `adb()` fails for a miscellaneous reason, an error is raised."""
     # Mock out the run command on an adb instance
-    adb = ADB(mock_tools, "exampleDevice")
     adb.run = MagicMock(
         side_effect=subprocess.CalledProcessError(returncode=69, cmd="emu avd name")
     )
@@ -51,10 +47,9 @@ def test_adb_failure(mock_tools, capsys):
     adb.run.assert_called_once_with("emu", "avd", "name")
 
 
-def test_invalid_device(mock_tools, capsys):
+def test_invalid_device(adb, capsys):
     """Invoking `avd_name()` on an invalid device raises an error."""
     # Mock out the run command on an adb instance
-    adb = ADB(mock_tools, "exampleDevice")
     adb.run = MagicMock(side_effect=InvalidDeviceError("device", "exampleDevice"))
 
     # Invoke install

tests/integrations/android_sdk/ADB/test_datetime.py

@@ -0,0 +1,48 @@
+import subprocess
+from datetime import datetime
+from unittest.mock import Mock
+
+import pytest
+
+from briefcase.exceptions import BriefcaseCommandError
+
+
+@pytest.mark.parametrize(
+    "device_output, expected_datetime",
+    [
+        ("2023-07-12 09:28:04", datetime(2023, 7, 12, 9, 28, 4)),
+        ("2023-07-12 09:28:04\n", datetime(2023, 7, 12, 9, 28, 4)),
+        ("2023-7-12 9:28:04", datetime(2023, 7, 12, 9, 28, 4)),
+        ("2023-12-2 14:28:04", datetime(2023, 12, 2, 14, 28, 4)),
+    ],
+)
+def test_datetime_success(adb, device_output, expected_datetime):
+    """adb.datetime() returns `datetime` for device."""
+    adb.run = Mock(return_value=device_output)
+
+    assert adb.datetime() == expected_datetime
+    adb.run.assert_called_once_with("shell", "date", "+'%Y-%m-%d %H:%M:%S'")
+
+
+def test_datetime_failure_call(adb):
+    """adb.datetime() fails in subprocess call."""
+    adb.run = Mock(
+        side_effect=subprocess.CalledProcessError(returncode=1, cmd="adb shell ...")
+    )
+
+    with pytest.raises(
+        BriefcaseCommandError,
+        match="Error obtaining device date/time.",
+    ):
+        adb.datetime()
+
+
+def test_datetime_failure_bad_value(adb):
+    """adb.datetime() fails in output conversion."""
+    adb.run = Mock(return_value="the date is jan 1 1970")
+
+    with pytest.raises(
+        BriefcaseCommandError,
+        match="Error obtaining device date/time.",
+    ):
+        adb.datetime()

tests/integrations/android_sdk/ADB/test_force_stop_app.py

@@ -4,13 +4,11 @@
 import pytest
 
 from briefcase.exceptions import BriefcaseCommandError, InvalidDeviceError
-from briefcase.integrations.android_sdk import ADB
 
 
-def test_force_stop_app(mock_tools, capsys):
+def test_force_stop_app(adb, capsys):
     """Invoking `force_stop_app()` calls `run()` with the appropriate parameters."""
     # Mock out the run command on an adb instance
-    adb = ADB(mock_tools, "exampleDevice")
     adb.run = MagicMock(return_value="example normal adb output")
 
     # Invoke force_stop_app
@@ -26,10 +24,9 @@ def test_force_stop_app(mock_tools, capsys):
     assert "normal adb output" not in capsys.readouterr()
 
 
-def test_force_top_fail(mock_tools, capsys):
+def test_force_top_fail(adb, capsys):
     """If `force_stop_app()` fails, an error is raised."""
     # Mock out the run command on an adb instance
-    adb = ADB(mock_tools, "exampleDevice")
     adb.run = MagicMock(
         side_effect=subprocess.CalledProcessError(returncode=69, cmd="force-stop")
     )
@@ -44,10 +41,9 @@ def test_force_top_fail(mock_tools, capsys):
     )
 
 
-def test_invalid_device(mock_tools, capsys):
+def test_invalid_device(adb, capsys):
     """Invoking `force_stop_app()` on an invalid device raises an error."""
     # Mock out the run command on an adb instance
-    adb = ADB(mock_tools, "exampleDevice")
     adb.run = MagicMock(side_effect=InvalidDeviceError("device", "exampleDevice"))
 
     # Invoke force_stop_app

tests/integrations/android_sdk/ADB/test_has_booted.py

@@ -4,13 +4,11 @@
 import pytest
 
 from briefcase.exceptions import BriefcaseCommandError, InvalidDeviceError
-from briefcase.integrations.android_sdk import ADB
 
 
-def test_booted(mock_tools, capsys):
+def test_booted(adb, capsys):
     """A booted device returns true."""
     # Mock out the adb response for an emulator
-    adb = ADB(mock_tools, "deafbeefcafe")
     adb.run = MagicMock(return_value="1\n")
 
     # Invoke avd_name
@@ -20,10 +18,9 @@ def test_booted(mock_tools, capsys):
     adb.run.assert_called_once_with("shell", "getprop", "sys.boot_completed")
 
 
-def test_not_booted(mock_tools, capsys):
+def test_not_booted(adb, capsys):
     """A non-booted device returns False."""
     # Mock out the adb response for an emulator
-    adb = ADB(mock_tools, "deafbeefcafe")
     adb.run = MagicMock(return_value="\n")
 
     # Invoke avd_name
@@ -33,10 +30,9 @@ def test_not_booted(mock_tools, capsys):
     adb.run.assert_called_once_with("shell", "getprop", "sys.boot_completed")
 
 
-def test_adb_failure(mock_tools, capsys):
+def test_adb_failure(adb, capsys):
     """If ADB fails, an error is raised."""
     # Mock out the adb response for an emulator
-    adb = ADB(mock_tools, "deafbeefcafe")
     adb.run = MagicMock(
         side_effect=subprocess.CalledProcessError(returncode=69, cmd="emu avd name")
     )
@@ -49,10 +45,9 @@ def test_adb_failure(mock_tools, capsys):
     adb.run.assert_called_once_with("shell", "getprop", "sys.boot_completed")
 
 
-def test_invalid_device(mock_tools, capsys):
+def test_invalid_device(adb, capsys):
     """If the device ID is invalid, an error is raised."""
     # Mock out the adb response for an emulator
-    adb = ADB(mock_tools, "not-a-device")
     adb.run = MagicMock(side_effect=InvalidDeviceError("device", "exampleDevice"))
 
     # Invoke avd_name

tests/integrations/android_sdk/ADB/test_install_apk.py

@@ -4,13 +4,11 @@
 import pytest
 
 from briefcase.exceptions import BriefcaseCommandError, InvalidDeviceError
-from briefcase.integrations.android_sdk import ADB
 
 
-def test_install_apk(mock_tools, capsys):
+def test_install_apk(adb, capsys):
     """Invoking `install_apk()` calls `run()` with the appropriate parameters."""
     # Mock out the run command on an adb instance
-    adb = ADB(mock_tools, "exampleDevice")
     adb.run = MagicMock(return_value="example normal adb output")
 
     # Invoke install
@@ -24,10 +22,9 @@ def test_install_apk(mock_tools, capsys):
     assert "normal adb output" not in capsys.readouterr()
 
 
-def test_install_failure(mock_tools, capsys):
+def test_install_failure(adb, capsys):
     """If `install_apk()` fails, an error is raised."""
     # Mock out the run command on an adb instance
-    adb = ADB(mock_tools, "exampleDevice")
     adb.run = MagicMock(
         side_effect=subprocess.CalledProcessError(returncode=2, cmd="install")
     )
@@ -40,10 +37,9 @@ def test_install_failure(mock_tools, capsys):
     adb.run.assert_called_once_with("install", "-r", "example.apk")
 
 
-def test_invalid_device(mock_tools, capsys):
+def test_invalid_device(adb, capsys):
     """Invoking `install_apk()` on an invalid device raises an error."""
     # Mock out the run command on an adb instance
-    adb = ADB(mock_tools, "exampleDevice")
     adb.run = MagicMock(side_effect=InvalidDeviceError("device", "exampleDevice"))
 
     # Invoke install