|
| 1 | +import io |
| 2 | +import sys |
| 3 | +from threading import RLock |
| 4 | +from time import sleep, time |
| 5 | + |
| 6 | +# The maximum length of a log message in bytes, including the level marker and |
| 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 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. |
| 12 | +MAX_BYTES_PER_WRITE = 4000 |
| 13 | + |
| 14 | +# UTF-8 uses a maximum of 4 bytes per character, so limiting text writes to this |
| 15 | +# size ensures that we can always avoid exceeding MAX_BYTES_PER_WRITE. |
| 16 | +# However, if the actual number of bytes per character is smaller than that, |
| 17 | +# then we may still join multiple consecutive text writes into binary |
| 18 | +# writes containing a larger number of characters. |
| 19 | +MAX_CHARS_PER_WRITE = MAX_BYTES_PER_WRITE // 4 |
| 20 | + |
| 21 | + |
| 22 | +# When embedded in an app on current versions of Android, there's no easy way to |
| 23 | +# monitor the C-level stdout and stderr. The testbed comes with a .c file to |
| 24 | +# redirect them to the system log using a pipe, but that wouldn't be convenient |
| 25 | +# or appropriate for all apps. So we redirect at the Python level instead. |
| 26 | +def init_streams(android_log_write, stdout_prio, stderr_prio): |
| 27 | + if sys.executable: |
| 28 | + return # Not embedded in an app. |
| 29 | + |
| 30 | + global logcat |
| 31 | + logcat = Logcat(android_log_write) |
| 32 | + |
| 33 | + sys.stdout = TextLogStream( |
| 34 | + stdout_prio, "python.stdout", sys.stdout.fileno()) |
| 35 | + sys.stderr = TextLogStream( |
| 36 | + stderr_prio, "python.stderr", sys.stderr.fileno()) |
| 37 | + |
| 38 | + |
| 39 | +class TextLogStream(io.TextIOWrapper): |
| 40 | + def __init__(self, prio, tag, fileno=None, **kwargs): |
| 41 | + # The default is surrogateescape for stdout and backslashreplace for |
| 42 | + # stderr, but in the context of an Android log, readability is more |
| 43 | + # important than reversibility. |
| 44 | + kwargs.setdefault("encoding", "UTF-8") |
| 45 | + kwargs.setdefault("errors", "backslashreplace") |
| 46 | + |
| 47 | + super().__init__(BinaryLogStream(prio, tag, fileno), **kwargs) |
| 48 | + self._lock = RLock() |
| 49 | + self._pending_bytes = [] |
| 50 | + self._pending_bytes_count = 0 |
| 51 | + |
| 52 | + def __repr__(self): |
| 53 | + return f"<TextLogStream {self.buffer.tag!r}>" |
| 54 | + |
| 55 | + def write(self, s): |
| 56 | + if not isinstance(s, str): |
| 57 | + raise TypeError( |
| 58 | + f"write() argument must be str, not {type(s).__name__}") |
| 59 | + |
| 60 | + # In case `s` is a str subclass that writes itself to stdout or stderr |
| 61 | + # when we call its methods, convert it to an actual str. |
| 62 | + s = str.__str__(s) |
| 63 | + |
| 64 | + # We want to emit one log message per line wherever possible, so split |
| 65 | + # the string into lines first. Note that "".splitlines() == [], so |
| 66 | + # nothing will be logged for an empty string. |
| 67 | + with self._lock: |
| 68 | + for line in s.splitlines(keepends=True): |
| 69 | + while line: |
| 70 | + chunk = line[:MAX_CHARS_PER_WRITE] |
| 71 | + line = line[MAX_CHARS_PER_WRITE:] |
| 72 | + self._write_chunk(chunk) |
| 73 | + |
| 74 | + return len(s) |
| 75 | + |
| 76 | + # The size and behavior of TextIOWrapper's buffer is not part of its public |
| 77 | + # API, so we handle buffering ourselves to avoid truncation. |
| 78 | + def _write_chunk(self, s): |
| 79 | + b = s.encode(self.encoding, self.errors) |
| 80 | + if self._pending_bytes_count + len(b) > MAX_BYTES_PER_WRITE: |
| 81 | + self.flush() |
| 82 | + |
| 83 | + self._pending_bytes.append(b) |
| 84 | + self._pending_bytes_count += len(b) |
| 85 | + if ( |
| 86 | + self.write_through |
| 87 | + or b.endswith(b"\n") |
| 88 | + or self._pending_bytes_count > MAX_BYTES_PER_WRITE |
| 89 | + ): |
| 90 | + self.flush() |
| 91 | + |
| 92 | + def flush(self): |
| 93 | + with self._lock: |
| 94 | + self.buffer.write(b"".join(self._pending_bytes)) |
| 95 | + self._pending_bytes.clear() |
| 96 | + self._pending_bytes_count = 0 |
| 97 | + |
| 98 | + # Since this is a line-based logging system, line buffering cannot be turned |
| 99 | + # off, i.e. a newline always causes a flush. |
| 100 | + @property |
| 101 | + def line_buffering(self): |
| 102 | + return True |
| 103 | + |
| 104 | + |
| 105 | +class BinaryLogStream(io.RawIOBase): |
| 106 | + def __init__(self, prio, tag, fileno=None): |
| 107 | + self.prio = prio |
| 108 | + self.tag = tag |
| 109 | + self._fileno = fileno |
| 110 | + |
| 111 | + def __repr__(self): |
| 112 | + return f"<BinaryLogStream {self.tag!r}>" |
| 113 | + |
| 114 | + def writable(self): |
| 115 | + return True |
| 116 | + |
| 117 | + def write(self, b): |
| 118 | + if type(b) is not bytes: |
| 119 | + try: |
| 120 | + b = bytes(memoryview(b)) |
| 121 | + except TypeError: |
| 122 | + raise TypeError( |
| 123 | + f"write() argument must be bytes-like, not {type(b).__name__}" |
| 124 | + ) from None |
| 125 | + |
| 126 | + # Writing an empty string to the stream should have no effect. |
| 127 | + if b: |
| 128 | + logcat.write(self.prio, self.tag, b) |
| 129 | + return len(b) |
| 130 | + |
| 131 | + # This is needed by the test suite --timeout option, which uses faulthandler. |
| 132 | + def fileno(self): |
| 133 | + if self._fileno is None: |
| 134 | + raise io.UnsupportedOperation("fileno") |
| 135 | + return self._fileno |
| 136 | + |
| 137 | + |
| 138 | +# When a large volume of data is written to logcat at once, e.g. when a test |
| 139 | +# module fails in --verbose3 mode, there's a risk of overflowing logcat's own |
| 140 | +# buffer and losing messages. We avoid this by imposing a rate limit using the |
| 141 | +# token bucket algorithm, based on a conservative estimate of how fast `adb |
| 142 | +# logcat` can consume data. |
| 143 | +MAX_BYTES_PER_SECOND = 1024 * 1024 |
| 144 | + |
| 145 | +# The logcat buffer size of a device can be determined by running `logcat -g`. |
| 146 | +# We set the token bucket size to half of the buffer size of our current minimum |
| 147 | +# API level, because other things on the system will be producing messages as |
| 148 | +# well. |
| 149 | +BUCKET_SIZE = 128 * 1024 |
| 150 | + |
| 151 | +# https://cs.android.com/android/platform/superproject/+/android-14.0.0_r1:system/logging/liblog/include/log/log_read.h;l=39 |
| 152 | +PER_MESSAGE_OVERHEAD = 28 |
| 153 | + |
| 154 | + |
| 155 | +class Logcat: |
| 156 | + def __init__(self, android_log_write): |
| 157 | + self.android_log_write = android_log_write |
| 158 | + self._lock = RLock() |
| 159 | + self._bucket_level = 0 |
| 160 | + self._prev_write_time = time() |
| 161 | + |
| 162 | + def write(self, prio, tag, message): |
| 163 | + # Encode null bytes using "modified UTF-8" to avoid them truncating the |
| 164 | + # message. |
| 165 | + message = message.replace(b"\x00", b"\xc0\x80") |
| 166 | + |
| 167 | + with self._lock: |
| 168 | + now = time() |
| 169 | + self._bucket_level += ( |
| 170 | + (now - self._prev_write_time) * MAX_BYTES_PER_SECOND) |
| 171 | + |
| 172 | + # If the bucket level is still below zero, the clock must have gone |
| 173 | + # backwards, so reset it to zero and continue. |
| 174 | + self._bucket_level = max(0, min(self._bucket_level, BUCKET_SIZE)) |
| 175 | + self._prev_write_time = now |
| 176 | + |
| 177 | + self._bucket_level -= PER_MESSAGE_OVERHEAD + len(tag) + len(message) |
| 178 | + if self._bucket_level < 0: |
| 179 | + sleep(-self._bucket_level / MAX_BYTES_PER_SECOND) |
| 180 | + |
| 181 | + self.android_log_write(prio, tag, message) |
0 commit comments