Improve transparency of stdout and stderr logging

Author: mhsmith

Android/android.py

@@ -15,6 +15,7 @@
 from asyncio import wait_for
 from contextlib import asynccontextmanager
 from datetime import datetime, timezone
+from enum import IntEnum, auto
 from glob import glob
 from os.path import abspath, basename, relpath
 from pathlib import Path
@@ -61,6 +62,19 @@
 hidden_output = []
 
 
+# Based on android/log.h in the NDK.
+class LogPriority(IntEnum):
+    UNKNOWN = 0
+    DEFAULT = auto()
+    VERBOSE = auto()
+    DEBUG = auto()
+    INFO = auto()
+    WARN = auto()
+    ERROR = auto()
+    FATAL = auto()
+    SILENT = auto()
+
+
 def log_verbose(context, line, stream=sys.stdout):
     if context.verbose:
         stream.write(line)
@@ -505,47 +519,47 @@ async def logcat_task(context, initial_devices):
     pid = await wait_for(find_pid(serial), startup_timeout)
 
     # `--pid` requires API level 24 or higher.
-    args = [adb, "-s", serial, "logcat", "--pid", pid,  "--format", "tag"]
+    #
+    # `--binary` mode is used in order to detect which messages end with a
+    # newline, which most of the other modes don't indicate (except `--format
+    # long`). For example, every time pytest runs a test, it prints a "." and
+    # flushes the stream. Each "." becomes a separate log message, but we should
+    # show them all on the same line.
+    args = [adb, "-s", serial, "logcat", "--pid", pid,  "--binary"]
     logcat_started = False
     async with async_process(
-        *args, stdout=subprocess.PIPE, stderr=subprocess.STDOUT,
+        *args, stdout=subprocess.PIPE, stderr=None
     ) as process:
-        while line := (await process.stdout.readline()).decode(*DECODE_ARGS):
-            if match := re.fullmatch(r"([A-Z])/(.*)", line, re.DOTALL):
+        while True:
+            try:
+                priority, tag, message = await read_logcat(process.stdout)
                 logcat_started = True
-                level, message = match.groups()
-            else:
-                # If the regex doesn't match, this is either a logcat startup
-                # error, or the second or subsequent line of a multi-line
-                # message. Python won't produce multi-line messages, but other
-                # components might.
-                level, message = None, line
+            except asyncio.IncompleteReadError:
+                break
 
             # Exclude high-volume messages which are rarely useful.
             if context.verbose < 2 and "from python test_syslog" in message:
                 continue
 
             # Put high-level messages on stderr so they're highlighted in the
             # buildbot logs. This will include Python's own stderr.
-            stream = (
-                sys.stderr
-                if level in ["W", "E", "F"]  # WARNING, ERROR, FATAL (aka ASSERT)
-                else sys.stdout
-            )
-
-            # To simplify automated processing of the output, e.g. a buildbot
-            # posting a failure notice on a GitHub PR, we strip the level and
-            # tag indicators from Python's stdout and stderr.
-            for prefix in ["python.stdout: ", "python.stderr: "]:
-                if message.startswith(prefix):
-                    global python_started
-                    python_started = True
-                    stream.write(message.removeprefix(prefix))
-                    break
+            stream = sys.stderr if priority > LogPriority.WARN else sys.stdout
+
+            # The app's stdout and stderr should be passed through transparently
+            # to our own corresponding streams.
+            if tag in ["python.stdout", "python.stderr"]:
+                global python_started
+                python_started = True
+                stream.write(message)
+                stream.flush()
             else:
                 # Non-Python messages add a lot of noise, but they may
-                # sometimes help explain a failure.
-                log_verbose(context, line, stream)
+                # sometimes help explain a failure. Format them in the same way
+                # as `logcat --format tag`.
+                formatted = f"{priority.name[0]}/{tag}: {message}"
+                if not formatted.endswith("\n"):
+                    formatted += "\n"
+                log_verbose(context, formatted, stream)
 
         # If the device disconnects while logcat is running, which always
         # happens in --managed mode, some versions of adb return non-zero.
@@ -556,6 +570,44 @@ async def logcat_task(context, initial_devices):
             raise CalledProcessError(status, args)
 
 
+# Read one binary log message from the given StreamReader. The message format is
+# described at https://android.stackexchange.com/a/74660. All supported versions
+# of Android use format version 2 or later.
+async def read_logcat(stream):
+    async def read_bytes(size):
+        return await stream.readexactly(size)
+
+    async def read_int(size):
+        return int.from_bytes(await read_bytes(size), "little")
+
+    payload_len = await read_int(2)
+    if payload_len < 2:
+        # 1 byte for priority, 1 byte for null terminator of tag.
+        raise ValueError(f"payload length {payload_len} is too short")
+
+    header_len = await read_int(2)
+    if header_len < 4:
+        raise ValueError(f"header length {header_len} is too short")
+    await read_bytes(header_len - 4)  # Ignore other header fields.
+
+    priority_int = await read_int(1)
+    try:
+        priority = LogPriority(priority_int)
+    except ValueError:
+        priority = LogPriority.UNKNOWN
+
+    payload_fields = (await read_bytes(payload_len - 1)).split(b"\0")
+    if len(payload_fields) < 2:
+        raise ValueError(
+            f"payload {payload!r} does not contain at least 2 "
+            f"null-separated fields"
+        )
+    tag, message, *_ = [
+        field.decode(*DECODE_ARGS) for field in payload_fields
+    ]
+    return priority, tag, message
+
+
 def stop_app(serial):
     run([adb, "-s", serial, "shell", "am", "force-stop", APP_ID], log=False)
 

Android/testbed/app/build.gradle.kts

@@ -94,10 +94,13 @@ android {
         }
 
         // This controls the API level of the maxVersion managed emulator, which is used
-        // by CI and cibuildwheel. 34 takes up too much disk space (#142289), 35 has
-        // issues connecting to the internet (#142387), and 36 and later are not
-        // available as aosp_atd images yet.
-        targetSdk = 33
+        // by CI and cibuildwheel.
+        //  * 33 has excessive buffering in the logcat client
+        //    (https://cs.android.com/android/_/android/platform/system/logging/+/d340721894f223327339010df59b0ac514308826).
+        //  * 34 consumes too much disk space on GitHub Actions (#142289).
+        //  * 35 has issues connecting to the internet (#142387).
+        //  * 36 and later are not available as aosp_atd images yet.
+        targetSdk = 32
 
         versionCode = 1
         versionName = "1.0"

Lib/_android_support.py

@@ -168,6 +168,13 @@ def write(self, prio, tag, message):
         # message.
         message = message.replace(b"\x00", b"\xc0\x80")
 
+        # On API level 30 and higher, Logcat will strip any number of leading
+        # newlines. This is visible in all `logcat` modes, even --binary. Work
+        # around this by adding a leading space, which shouldn't make any
+        # difference to the log's usability.
+        if message.startswith(b"\n"):
+            message = b" " + message
+
         with self._lock:
             now = time()
             self._bucket_level += (

Lib/test/test_android.py

@@ -1,5 +1,4 @@
 import io
-import platform
 import queue
 import re
 import subprocess
@@ -17,8 +16,6 @@
 if sys.platform != "android":
     raise unittest.SkipTest("Android-specific")
 
-api_level = platform.android_ver().api_level
-
 # (name, level, fileno)
 STREAM_INFO = [("stdout", "I", 1), ("stderr", "W", 2)]
 
@@ -179,14 +176,18 @@ def write(s, lines=None, *, write_len=None):
 
                 # Multi-line messages. Avoid identical consecutive lines, as
                 # they may activate "chatty" filtering and break the tests.
-                write("\nx", [""])
+                #
+                # Additional spaces will appear in the output where necessary to
+                # protect leading newlines.
+                write("\nx", [" "])
                 write("\na\n", ["x", "a"])
-                write("\n", [""])
+                write("\n", [" "])
+                write("\n\n", [" ", " "])
                 write("b\n", ["b"])
-                write("c\n\n", ["c", ""])
+                write("c\n\n", ["c", " "])
                 write("d\ne", ["d"])
                 write("xx", [])
-                write("f\n\ng", ["exxf", ""])
+                write("f\n\ng", ["exxf", " "])
                 write("\n", ["g"])
 
                 # Since this is a line-based logging system, line buffering
@@ -197,15 +198,16 @@ def write(s, lines=None, *, write_len=None):
                 # However, buffering can be turned off completely if you want a
                 # flush after every write.
                 with self.reconfigure(stream, write_through=True):
-                    write("\nx", ["", "x"])
-                    write("\na\n", ["", "a"])
-                    write("\n", [""])
+                    write("\nx", [" ", "x"])
+                    write("\na\n", [" ", "a"])
+                    write("\n", [" "])
+                    write("\n\n", [" ", " "])
                     write("b\n", ["b"])
-                    write("c\n\n", ["c", ""])
+                    write("c\n\n", ["c", " "])
                     write("d\ne", ["d", "e"])
                     write("xx", ["xx"])
-                    write("f\n\ng", ["f", "", "g"])
-                    write("\n", [""])
+                    write("f\n\ng", ["f", " ", "g"])
+                    write("\n", [" "])
 
                 # "\r\n" should be translated into "\n".
                 write("hello\r\n", ["hello"])
@@ -325,19 +327,16 @@ def write(b, lines=None, *, write_len=None):
                 # currently use `logcat -v tag`, which shows each line as if it
                 # was a separate log entry, but strips a single trailing
                 # newline.
-                #
-                # On newer versions of Android, all three of the above tools (or
-                # maybe Logcat itself) will also strip any number of leading
-                # newlines.
-                write(b"\nx", ["", "x"] if api_level < 30 else ["x"])
-                write(b"\na\n", ["", "a"] if api_level < 30 else ["a"])
-                write(b"\n", [""])
+                write(b"\nx", [" ", "x"])
+                write(b"\na\n", [" ", "a"])
+                write(b"\n", [" "])
+                write(b"\n\n", [" ", ""])
                 write(b"b\n", ["b"])
                 write(b"c\n\n", ["c", ""])
                 write(b"d\ne", ["d", "e"])
                 write(b"xx", ["xx"])
                 write(b"f\n\ng", ["f", "", "g"])
-                write(b"\n", [""])
+                write(b"\n", [" "])
 
                 # "\r\n" should be translated into "\n".
                 write(b"hello\r\n", ["hello"])