Skip to content

gh-116622: Redirect stdout and stderr to system log when embedded in an Android app #118063

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 19 commits into from
Apr 30, 2024
Merged
Show file tree
Hide file tree
Changes from 7 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
88 changes: 88 additions & 0 deletions Lib/_android_support.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,88 @@
import io
import sys


# The maximum length of a log message in bytes, including the level marker and
# tag, is defined as LOGGER_ENTRY_MAX_PAYLOAD in
# platform/system/logging/liblog/include/log/log.h. As of API level 30, messages
# longer than this will be be truncated by logcat. This limit has already been
# reduced at least once in the history of Android (from 4076 to 4068 between API
# level 23 and 26), so leave some headroom.
MAX_BYTES_PER_WRITE = 4000

# UTF-8 uses a maximum of 4 bytes per character, so limiting text writes to this
# size ensures that TextIOWrapper can always avoid exceeding MAX_BYTES_PER_WRITE.
# However, if the actual number of bytes per character is smaller than that,
# then TextIOWrapper may still join multiple consecutive text writes into binary
# writes containing a larger number of characters.
MAX_CHARS_PER_WRITE = MAX_BYTES_PER_WRITE // 4


# When embedded in an app on current versions of Android, there's no easy way to
# monitor the C-level stdout and stderr. The testbed comes with a .c file to
# redirect them to the system log using a pipe, but that wouldn't be convenient
# or appropriate for all apps. So we redirect at the Python level instead.
def init_streams(android_log_write, stdout_prio, stderr_prio):
if sys.executable:
return # Not embedded in an app.

sys.stdout = TextLogStream(
android_log_write, stdout_prio, "python.stdout", errors=sys.stdout.errors)
sys.stderr = TextLogStream(
android_log_write, stderr_prio, "python.stderr", errors=sys.stderr.errors)


class TextLogStream(io.TextIOWrapper):
def __init__(self, android_log_write, prio, tag, **kwargs):
kwargs.setdefault("encoding", "UTF-8")
kwargs.setdefault("line_buffering", True)
super().__init__(BinaryLogStream(android_log_write, prio, tag), **kwargs)
self._CHUNK_SIZE = MAX_BYTES_PER_WRITE

def __repr__(self):
return f"<TextLogStream {self.buffer.tag!r}>"

def write(self, s):
if not isinstance(s, str):
raise TypeError(
f"write() argument must be str, not {type(s).__name__}")

# We want to emit one log message per line wherever possible, so split
# the string before sending it to the superclass. Note that
# "".splitlines() == [], so nothing will be logged for an empty string.
for line, line_keepends in zip(
s.splitlines(), s.splitlines(keepends=True)
):
# Simplify the later stages by translating all newlines into "\n".
if line != line_keepends:
line += "\n"
while line:
super().write(line[:MAX_CHARS_PER_WRITE])
line = line[MAX_CHARS_PER_WRITE:]

return len(s)


class BinaryLogStream(io.RawIOBase):
def __init__(self, android_log_write, prio, tag):
self.android_log_write = android_log_write
self.prio = prio
self.tag = tag

def __repr__(self):
return f"<BinaryLogStream {self.tag!r}>"

def writable(self):
return True

def write(self, b):
if hasattr(b, "__buffer__"):
b = bytes(b)
else:
raise TypeError(
f"write() argument must be bytes-like, not {type(b).__name__}")

# Writing an empty string to the stream should have no effect.
if b:
self.android_log_write(self.prio, self.tag, b)
return len(b)
269 changes: 269 additions & 0 deletions Lib/test/test_android.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,269 @@
import platform
import queue
import re
import subprocess
import sys
import unittest
from contextlib import contextmanager
from threading import Thread
from time import time


if sys.platform != "android":
raise unittest.SkipTest("Android-specific")

api_level = platform.android_ver().api_level


# Test redirection of stdout and stderr to the Android log.
@unittest.skipIf(
api_level < 23 and platform.machine() == "aarch64",
"SELinux blocks reading logs on older ARM64 emulators"
)
class TestAndroidOutput(unittest.TestCase):
maxDiff = None

def setUp(self):
self.logcat_process = subprocess.Popen(
["logcat", "-v", "tag"], stdout=subprocess.PIPE,
errors="backslashreplace"
)
self.logcat_queue = queue.Queue()

def logcat_thread():
for line in self.logcat_process.stdout:
self.logcat_queue.put(line.rstrip("\n"))
self.logcat_process.stdout.close()
Thread(target=logcat_thread).start()

from ctypes import CDLL, c_char_p, c_int
android_log_write = getattr(CDLL("liblog.so"), "__android_log_write")
android_log_write.argtypes = (c_int, c_char_p, c_char_p)
ANDROID_LOG_INFO = 4

# Separate tests using a marker line with a different tag.
tag, message = "python.test", f"{self.id()} {time()}"
android_log_write(
ANDROID_LOG_INFO, tag.encode("UTF-8"), message.encode("UTF-8"))
self.assert_log("I", tag, message, skip=True, timeout=5)

def assert_logs(self, level, tag, expected, **kwargs):
for line in expected:
self.assert_log(level, tag, line, **kwargs)

def assert_log(self, level, tag, expected, *, skip=False, timeout=0.5):
deadline = time() + timeout
while True:
try:
line = self.logcat_queue.get(timeout=(deadline - time()))
except queue.Empty:
self.fail(f"line not found: {expected!r}")
if match := re.fullmatch(fr"(.)/{tag}: (.*)", line):
try:
self.assertEqual(level, match[1])
self.assertEqual(expected, match[2])
break
except AssertionError:
if not skip:
raise

def tearDown(self):
self.logcat_process.terminate()
self.logcat_process.wait(0.1)

@contextmanager
def unbuffered(self, stream):
stream.reconfigure(write_through=True)
try:
yield
finally:
stream.reconfigure(write_through=False)

def test_str(self):
for stream_name, level in [("stdout", "I"), ("stderr", "W")]:
with self.subTest(stream=stream_name):
stream = getattr(sys, stream_name)
tag = f"python.{stream_name}"
self.assertEqual(f"<TextLogStream '{tag}'>", repr(stream))

self.assertTrue(stream.writable())
self.assertFalse(stream.readable())
self.assertEqual("UTF-8", stream.encoding)
self.assertTrue(stream.line_buffering)
self.assertFalse(stream.write_through)

# stderr is backslashreplace by default; stdout is configured
# that way by libregrtest.main.
self.assertEqual("backslashreplace", stream.errors)

def write(s, lines=None):
self.assertEqual(len(s), stream.write(s))
if lines is None:
lines = [s]
self.assert_logs(level, tag, lines)

# Single-line messages,
with self.unbuffered(stream):
write("", [])

write("a")
write("Hello")
write("Hello world")
write(" ")
write(" ")

# Non-ASCII text
write("ol\u00e9") # Spanish
write("\u4e2d\u6587") # Chinese

# Non-BMP emoji
write("\U0001f600")

# Null characters will truncate a message.
write("\u0000", [] if api_level < 24 else [""])
write("a\u0000", ["a"])
write("\u0000b", [] if api_level < 24 else [""])
write("a\u0000b", ["a"])

# Multi-line messages. Avoid identical consecutive lines, as
# they may activate "chatty" filtering and break the tests.
write("\nx", [""])
write("\na\n", ["x", "a"])
write("\n", [""])
write("b\n", ["b"])
write("c\n\n", ["c", ""])
write("d\ne", ["d"])
write("xx", [])
write("f\n\ng", ["exxf", ""])
write("\n", ["g"])

with self.unbuffered(stream):
write("\nx", ["", "x"])
write("\na\n", ["", "a"])
write("\n", [""])
write("b\n", ["b"])
write("c\n\n", ["c", ""])
write("d\ne", ["d", "e"])
write("xx", ["xx"])
write("f\n\ng", ["f", "", "g"])
write("\n", [""])

# "\r\n" should be translated into "\n".
write("hello\r\n", ["hello"])
write("hello\r\nworld\r\n", ["hello", "world"])
write("\r\n", [""])

for obj in [b"", b"hello", None, 42]:
with self.subTest(obj=obj):
with self.assertRaisesRegex(
TypeError,
fr"write\(\) argument must be str, not "
fr"{type(obj).__name__}"
):
stream.write(obj)

# Manual flushing is supported.
write("hello", [])
stream.flush()
self.assert_log(level, tag, "hello")
write("hello", [])
write("world", [])
stream.flush()
self.assert_log(level, tag, "helloworld")

# Long lines are split into blocks of 1000 *characters*, but
# TextIOWrapper should then join them back together as much as
# possible without exceeding 4000 UTF-8 *bytes*.
#
# ASCII (1 byte per character)
write(("foobar" * 700) + "\n",
[("foobar" * 666) + "foob", # 4000 bytes
"ar" + ("foobar" * 33)]) # 200 bytes

# "Full-width" digits 0-9 (3 bytes per character)
s = "\uff10\uff11\uff12\uff13\uff14\uff15\uff16\uff17\uff18\uff19"
write((s * 150) + "\n",
[s * 100, # 3000 bytes
s * 50]) # 1500 bytes

s = "0123456789"
write(s * 200, [])
write(s * 150, [])
write(s * 51, [s * 350]) # 3500 bytes
write("\n", [s * 51]) # 510 bytes

def test_bytes(self):
for stream_name, level in [("stdout", "I"), ("stderr", "W")]:
with self.subTest(stream=stream_name):
stream = getattr(sys, stream_name).buffer
tag = f"python.{stream_name}"
self.assertEqual(f"<BinaryLogStream '{tag}'>", repr(stream))
self.assertTrue(stream.writable())
self.assertFalse(stream.readable())

def write(b, lines=None):
self.assertEqual(len(b), stream.write(b))
if lines is None:
lines = [b.decode()]
self.assert_logs(level, tag, lines)

# Single-line messages,
write(b"", [])

write(b"a")
write(b"Hello")
write(b"Hello world")
write(b" ")
write(b" ")

# Non-ASCII text
write(b"ol\xc3\xa9") # Spanish
write(b"\xe4\xb8\xad\xe6\x96\x87") # Chinese

# Non-BMP emoji
write(b"\xf0\x9f\x98\x80")

# Null characters will truncate a message.
write(b"\x00", [] if api_level < 24 else [""])
write(b"a\x00", ["a"])
write(b"\x00b", [] if api_level < 24 else [""])
write(b"a\x00b", ["a"])

# Invalid UTF-8
write(b"\xff", [r"\xff"])
write(b"a\xff", [r"a\xff"])
write(b"\xffb", [r"\xffb"])
write(b"a\xffb", [r"a\xffb"])

# Log entries containing newlines are shown differently by
# `logcat -v tag`, `logcat -v long`, and Android Studio. We
# 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"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", [""])

# "\r\n" should be translated into "\n".
write(b"hello\r\n", ["hello"])
write(b"hello\r\nworld\r\n", ["hello", "world"])
write(b"\r\n", [""])

for obj in ["", "hello", None, 42]:
with self.subTest(obj=obj):
with self.assertRaisesRegex(
TypeError,
fr"write\(\) argument must be bytes-like, not "
fr"{type(obj).__name__}"
):
stream.write(obj)
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Redirect stdout and stderr to system log when embedded in an Android app.
Loading
Loading