Skip to content

Commit 0dd89a7

Browse files
miss-islingtonmhsmith
miss-islington
and
mhsmith
authored
[3.13] gh-116622: Android logging fixes (GH-122698) (#122719)
gh-116622: Android logging fixes (GH-122698) Modifies the handling of stdout/stderr redirection on Android to accomodate the rate and buffer size limits imposed by Android's logging infrastructure. (cherry picked from commit b0c48b8) Co-authored-by: Malcolm Smith <smith@chaquo.com>
1 parent 69cf92f commit 0dd89a7

File tree

3 files changed

+213
-48
lines changed

3 files changed

+213
-48
lines changed

‎Lib/_android_support.py

+100-28
Original file line numberDiff line numberDiff line change
@@ -1,19 +1,20 @@
11
import io
22
import sys
3-
3+
from threading import RLock
4+
from time import sleep, time
45

56
# The maximum length of a log message in bytes, including the level marker and
6-
# tag, is defined as LOGGER_ENTRY_MAX_PAYLOAD in
7-
# platform/system/logging/liblog/include/log/log.h. As of API level 30, messages
8-
# longer than this will be be truncated by logcat. This limit has already been
9-
# reduced at least once in the history of Android (from 4076 to 4068 between API
10-
# level 23 and 26), so leave some headroom.
7+
# tag, is defined as LOGGER_ENTRY_MAX_PAYLOAD at
8+
# https://cs.android.com/android/platform/superproject/+/android-14.0.0_r1:system/logging/liblog/include/log/log.h;l=71.
9+
# Messages longer than this will be be truncated by logcat. This limit has already
10+
# been reduced at least once in the history of Android (from 4076 to 4068 between
11+
# API level 23 and 26), so leave some headroom.
1112
MAX_BYTES_PER_WRITE = 4000
1213

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

@@ -26,18 +27,22 @@ def init_streams(android_log_write, stdout_prio, stderr_prio):
2627
if sys.executable:
2728
return # Not embedded in an app.
2829

30+
global logcat
31+
logcat = Logcat(android_log_write)
32+
2933
sys.stdout = TextLogStream(
30-
android_log_write, stdout_prio, "python.stdout", errors=sys.stdout.errors)
34+
stdout_prio, "python.stdout", errors=sys.stdout.errors)
3135
sys.stderr = TextLogStream(
32-
android_log_write, stderr_prio, "python.stderr", errors=sys.stderr.errors)
36+
stderr_prio, "python.stderr", errors=sys.stderr.errors)
3337

3438

3539
class TextLogStream(io.TextIOWrapper):
36-
def __init__(self, android_log_write, prio, tag, **kwargs):
40+
def __init__(self, prio, tag, **kwargs):
3741
kwargs.setdefault("encoding", "UTF-8")
38-
kwargs.setdefault("line_buffering", True)
39-
super().__init__(BinaryLogStream(android_log_write, prio, tag), **kwargs)
40-
self._CHUNK_SIZE = MAX_BYTES_PER_WRITE
42+
super().__init__(BinaryLogStream(prio, tag), **kwargs)
43+
self._lock = RLock()
44+
self._pending_bytes = []
45+
self._pending_bytes_count = 0
4146

4247
def __repr__(self):
4348
return f"<TextLogStream {self.buffer.tag!r}>"
@@ -52,19 +57,48 @@ def write(self, s):
5257
s = str.__str__(s)
5358

5459
# We want to emit one log message per line wherever possible, so split
55-
# the string before sending it to the superclass. Note that
56-
# "".splitlines() == [], so nothing will be logged for an empty string.
57-
for line in s.splitlines(keepends=True):
58-
while line:
59-
super().write(line[:MAX_CHARS_PER_WRITE])
60-
line = line[MAX_CHARS_PER_WRITE:]
60+
# the string into lines first. Note that "".splitlines() == [], so
61+
# nothing will be logged for an empty string.
62+
with self._lock:
63+
for line in s.splitlines(keepends=True):
64+
while line:
65+
chunk = line[:MAX_CHARS_PER_WRITE]
66+
line = line[MAX_CHARS_PER_WRITE:]
67+
self._write_chunk(chunk)
6168

6269
return len(s)
6370

71+
# The size and behavior of TextIOWrapper's buffer is not part of its public
72+
# API, so we handle buffering ourselves to avoid truncation.
73+
def _write_chunk(self, s):
74+
b = s.encode(self.encoding, self.errors)
75+
if self._pending_bytes_count + len(b) > MAX_BYTES_PER_WRITE:
76+
self.flush()
77+
78+
self._pending_bytes.append(b)
79+
self._pending_bytes_count += len(b)
80+
if (
81+
self.write_through
82+
or b.endswith(b"\n")
83+
or self._pending_bytes_count > MAX_BYTES_PER_WRITE
84+
):
85+
self.flush()
86+
87+
def flush(self):
88+
with self._lock:
89+
self.buffer.write(b"".join(self._pending_bytes))
90+
self._pending_bytes.clear()
91+
self._pending_bytes_count = 0
92+
93+
# Since this is a line-based logging system, line buffering cannot be turned
94+
# off, i.e. a newline always causes a flush.
95+
@property
96+
def line_buffering(self):
97+
return True
98+
6499

65100
class BinaryLogStream(io.RawIOBase):
66-
def __init__(self, android_log_write, prio, tag):
67-
self.android_log_write = android_log_write
101+
def __init__(self, prio, tag):
68102
self.prio = prio
69103
self.tag = tag
70104

@@ -85,10 +119,48 @@ def write(self, b):
85119

86120
# Writing an empty string to the stream should have no effect.
87121
if b:
88-
# Encode null bytes using "modified UTF-8" to avoid truncating the
89-
# message. This should not affect the return value, as the caller
90-
# may be expecting it to match the length of the input.
91-
self.android_log_write(self.prio, self.tag,
92-
b.replace(b"\x00", b"\xc0\x80"))
93-
122+
logcat.write(self.prio, self.tag, b)
94123
return len(b)
124+
125+
126+
# When a large volume of data is written to logcat at once, e.g. when a test
127+
# module fails in --verbose3 mode, there's a risk of overflowing logcat's own
128+
# buffer and losing messages. We avoid this by imposing a rate limit using the
129+
# token bucket algorithm, based on a conservative estimate of how fast `adb
130+
# logcat` can consume data.
131+
MAX_BYTES_PER_SECOND = 1024 * 1024
132+
133+
# The logcat buffer size of a device can be determined by running `logcat -g`.
134+
# We set the token bucket size to half of the buffer size of our current minimum
135+
# API level, because other things on the system will be producing messages as
136+
# well.
137+
BUCKET_SIZE = 128 * 1024
138+
139+
# https://cs.android.com/android/platform/superproject/+/android-14.0.0_r1:system/logging/liblog/include/log/log_read.h;l=39
140+
PER_MESSAGE_OVERHEAD = 28
141+
142+
143+
class Logcat:
144+
def __init__(self, android_log_write):
145+
self.android_log_write = android_log_write
146+
self._lock = RLock()
147+
self._bucket_level = 0
148+
self._prev_write_time = time()
149+
150+
def write(self, prio, tag, message):
151+
# Encode null bytes using "modified UTF-8" to avoid them truncating the
152+
# message.
153+
message = message.replace(b"\x00", b"\xc0\x80")
154+
155+
with self._lock:
156+
now = time()
157+
self._bucket_level += (
158+
(now - self._prev_write_time) * MAX_BYTES_PER_SECOND)
159+
self._bucket_level = min(self._bucket_level, BUCKET_SIZE)
160+
self._prev_write_time = now
161+
162+
self._bucket_level -= PER_MESSAGE_OVERHEAD + len(tag) + len(message)
163+
if self._bucket_level < 0:
164+
sleep(-self._bucket_level / MAX_BYTES_PER_SECOND)
165+
166+
self.android_log_write(prio, tag, message)

‎Lib/test/test_android.py

+112-20
Original file line numberDiff line numberDiff line change
@@ -1,14 +1,17 @@
1+
import io
12
import platform
23
import queue
34
import re
45
import subprocess
56
import sys
67
import unittest
8+
from _android_support import TextLogStream
79
from array import array
8-
from contextlib import contextmanager
10+
from contextlib import ExitStack, contextmanager
911
from threading import Thread
1012
from test.support import LOOPBACK_TIMEOUT
11-
from time import time
13+
from time import sleep, time
14+
from unittest.mock import patch
1215

1316

1417
if sys.platform != "android":
@@ -81,18 +84,39 @@ def unbuffered(self, stream):
8184
finally:
8285
stream.reconfigure(write_through=False)
8386

87+
# In --verbose3 mode, sys.stdout and sys.stderr are captured, so we can't
88+
# test them directly. Detect this mode and use some temporary streams with
89+
# the same properties.
90+
def stream_context(self, stream_name, level):
91+
# https://developer.android.com/ndk/reference/group/logging
92+
prio = {"I": 4, "W": 5}[level]
93+
94+
stack = ExitStack()
95+
stack.enter_context(self.subTest(stream_name))
96+
stream = getattr(sys, stream_name)
97+
if isinstance(stream, io.StringIO):
98+
stack.enter_context(
99+
patch(
100+
f"sys.{stream_name}",
101+
TextLogStream(
102+
prio, f"python.{stream_name}", errors="backslashreplace"
103+
),
104+
)
105+
)
106+
return stack
107+
84108
def test_str(self):
85109
for stream_name, level in [("stdout", "I"), ("stderr", "W")]:
86-
with self.subTest(stream=stream_name):
110+
with self.stream_context(stream_name, level):
87111
stream = getattr(sys, stream_name)
88112
tag = f"python.{stream_name}"
89113
self.assertEqual(f"<TextLogStream '{tag}'>", repr(stream))
90114

91-
self.assertTrue(stream.writable())
92-
self.assertFalse(stream.readable())
115+
self.assertIs(stream.writable(), True)
116+
self.assertIs(stream.readable(), False)
93117
self.assertEqual("UTF-8", stream.encoding)
94-
self.assertTrue(stream.line_buffering)
95-
self.assertFalse(stream.write_through)
118+
self.assertIs(stream.line_buffering, True)
119+
self.assertIs(stream.write_through, False)
96120

97121
# stderr is backslashreplace by default; stdout is configured
98122
# that way by libregrtest.main.
@@ -147,6 +171,13 @@ def write(s, lines=None, *, write_len=None):
147171
write("f\n\ng", ["exxf", ""])
148172
write("\n", ["g"])
149173

174+
# Since this is a line-based logging system, line buffering
175+
# cannot be turned off, i.e. a newline always causes a flush.
176+
stream.reconfigure(line_buffering=False)
177+
self.assertIs(stream.line_buffering, True)
178+
179+
# However, buffering can be turned off completely if you want a
180+
# flush after every write.
150181
with self.unbuffered(stream):
151182
write("\nx", ["", "x"])
152183
write("\na\n", ["", "a"])
@@ -209,30 +240,30 @@ def __str__(self):
209240
# (MAX_BYTES_PER_WRITE).
210241
#
211242
# ASCII (1 byte per character)
212-
write(("foobar" * 700) + "\n",
213-
[("foobar" * 666) + "foob", # 4000 bytes
214-
"ar" + ("foobar" * 33)]) # 200 bytes
243+
write(("foobar" * 700) + "\n", # 4200 bytes in
244+
[("foobar" * 666) + "foob", # 4000 bytes out
245+
"ar" + ("foobar" * 33)]) # 200 bytes out
215246

216247
# "Full-width" digits 0-9 (3 bytes per character)
217248
s = "\uff10\uff11\uff12\uff13\uff14\uff15\uff16\uff17\uff18\uff19"
218-
write((s * 150) + "\n",
219-
[s * 100, # 3000 bytes
220-
s * 50]) # 1500 bytes
249+
write((s * 150) + "\n", # 4500 bytes in
250+
[s * 100, # 3000 bytes out
251+
s * 50]) # 1500 bytes out
221252

222253
s = "0123456789"
223-
write(s * 200, [])
224-
write(s * 150, [])
225-
write(s * 51, [s * 350]) # 3500 bytes
226-
write("\n", [s * 51]) # 510 bytes
254+
write(s * 200, []) # 2000 bytes in
255+
write(s * 150, []) # 1500 bytes in
256+
write(s * 51, [s * 350]) # 510 bytes in, 3500 bytes out
257+
write("\n", [s * 51]) # 0 bytes in, 510 bytes out
227258

228259
def test_bytes(self):
229260
for stream_name, level in [("stdout", "I"), ("stderr", "W")]:
230-
with self.subTest(stream=stream_name):
261+
with self.stream_context(stream_name, level):
231262
stream = getattr(sys, stream_name).buffer
232263
tag = f"python.{stream_name}"
233264
self.assertEqual(f"<BinaryLogStream '{tag}'>", repr(stream))
234-
self.assertTrue(stream.writable())
235-
self.assertFalse(stream.readable())
265+
self.assertIs(stream.writable(), True)
266+
self.assertIs(stream.readable(), False)
236267

237268
def write(b, lines=None, *, write_len=None):
238269
if write_len is None:
@@ -330,3 +361,64 @@ def write(b, lines=None, *, write_len=None):
330361
fr"{type(obj).__name__}"
331362
):
332363
stream.write(obj)
364+
365+
def test_rate_limit(self):
366+
# https://cs.android.com/android/platform/superproject/+/android-14.0.0_r1:system/logging/liblog/include/log/log_read.h;l=39
367+
PER_MESSAGE_OVERHEAD = 28
368+
369+
# https://developer.android.com/ndk/reference/group/logging
370+
ANDROID_LOG_DEBUG = 3
371+
372+
# To avoid flooding the test script output, use a different tag rather
373+
# than stdout or stderr.
374+
tag = "python.rate_limit"
375+
stream = TextLogStream(ANDROID_LOG_DEBUG, tag)
376+
377+
# Make a test message which consumes 1 KB of the logcat buffer.
378+
message = "Line {:03d} "
379+
message += "." * (
380+
1024 - PER_MESSAGE_OVERHEAD - len(tag) - len(message.format(0))
381+
) + "\n"
382+
383+
# See _android_support.py. The default values of these parameters work
384+
# well across a wide range of devices, but we'll use smaller values to
385+
# ensure a quick and reliable test that doesn't flood the log too much.
386+
MAX_KB_PER_SECOND = 100
387+
BUCKET_KB = 10
388+
with (
389+
patch("_android_support.MAX_BYTES_PER_SECOND", MAX_KB_PER_SECOND * 1024),
390+
patch("_android_support.BUCKET_SIZE", BUCKET_KB * 1024),
391+
):
392+
# Make sure the token bucket is full.
393+
sleep(BUCKET_KB / MAX_KB_PER_SECOND)
394+
line_num = 0
395+
396+
# Write BUCKET_KB messages, and return the rate at which they were
397+
# accepted in KB per second.
398+
def write_bucketful():
399+
nonlocal line_num
400+
start = time()
401+
max_line_num = line_num + BUCKET_KB
402+
while line_num < max_line_num:
403+
stream.write(message.format(line_num))
404+
line_num += 1
405+
return BUCKET_KB / (time() - start)
406+
407+
# The first bucketful should be written with minimal delay. The
408+
# factor of 2 here is not arbitrary: it verifies that the system can
409+
# write fast enough to empty the bucket within two bucketfuls, which
410+
# the next part of the test depends on.
411+
self.assertGreater(write_bucketful(), MAX_KB_PER_SECOND * 2)
412+
413+
# Write another bucketful to empty the token bucket completely.
414+
write_bucketful()
415+
416+
# The next bucketful should be written at the rate limit.
417+
self.assertAlmostEqual(
418+
write_bucketful(), MAX_KB_PER_SECOND,
419+
delta=MAX_KB_PER_SECOND * 0.1
420+
)
421+
422+
# Once the token bucket refills, we should go back to full speed.
423+
sleep(BUCKET_KB / MAX_KB_PER_SECOND)
424+
self.assertGreater(write_bucketful(), MAX_KB_PER_SECOND * 2)

‎Misc/NEWS.d/next/Core and Builtins/2024-08-05-19-04-06.gh-issue-116622.3LWUzE.rst

+1
Original file line numberDiff line numberDiff line change
@@ -0,0 +1 @@
1+
Fix Android stdout and stderr messages being truncated or lost.

0 commit comments

Comments
 (0)