Skip to content

gh-116622: Mock the passage of time in Android logcat rate limit tests #124015

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.

Sign up for GitHub

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 2 commits into from
Sep 13, 2024
Merged

gh-116622: Mock the passage of time in Android logcat rate limit tests #124015

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
e4cb124
Mock the passage of time in Android logcat rate limit tests
mhsmith Sep 12, 2024
b2bf343
Merge branch 'main' into android-rate-limit
freakboy3742 Sep 13, 2024
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
5 changes: 4 additions & 1 deletion Lib/_android_support.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -165,7 +165,10 @@ def write(self, prio, tag, message):
now = time()
self._bucket_level += (
(now - self._prev_write_time) * MAX_BYTES_PER_SECOND)
self._bucket_level = min(self._bucket_level, BUCKET_SIZE)

# If the bucket level is still below zero, the clock must have gone
# backwards, so reset it to zero and continue.
self._bucket_level = max(0, min(self._bucket_level, BUCKET_SIZE))
self._prev_write_time = now

self._bucket_level -= PER_MESSAGE_OVERHEAD + len(tag) + len(message)
Expand Down
32 changes: 26 additions & 6 deletions Lib/test/test_android.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,7 @@
from contextlib import ExitStack, contextmanager
from threading import Thread
from test.support import LOOPBACK_TIMEOUT
from time import sleep, time
from time import time
from unittest.mock import patch


Expand Down Expand Up @@ -42,7 +42,8 @@ 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()
self.logcat_thread = Thread(target=logcat_thread)
self.logcat_thread.start()

from ctypes import CDLL, c_char_p, c_int
android_log_write = getattr(CDLL("liblog.so"), "__android_log_write")
Expand Down Expand Up @@ -78,6 +79,7 @@ def assert_log(self, level, tag, expected, *, skip=False, timeout=0.5):
def tearDown(self):
self.logcat_process.terminate()
self.logcat_process.wait(LOOPBACK_TIMEOUT)
self.logcat_thread.join(LOOPBACK_TIMEOUT)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This fixes an unrelated warning I saw while running the tests repeatedly with -F:

Warning -- threading._dangling was modified by test_android
Warning --   Before: {<weakref at 0x7c15b68e00; to 'threading._MainThread' at 0x7c18f5fcb0>}
Warning --   After:  {<weakref at 0x7c186e3ce0; to 'threading._MainThread' at 0x7c18f5fcb0>, <weakref at 0x7c1870ef20; to 'threading.Thread' at 0x7c183faa50>}


@contextmanager
def unbuffered(self, stream):
Expand Down Expand Up @@ -369,6 +371,8 @@ def write(b, lines=None, *, write_len=None):
):
stream.write(obj)


class TestAndroidRateLimit(unittest.TestCase):
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This test doesn't read its own output, so it doesn't need the @skipIf or the setUp from the other class.

def test_rate_limit(self):
# https://cs.android.com/android/platform/superproject/+/android-14.0.0_r1:system/logging/liblog/include/log/log_read.h;l=39
PER_MESSAGE_OVERHEAD = 28
Expand All @@ -387,6 +391,19 @@ def test_rate_limit(self):
1024 - PER_MESSAGE_OVERHEAD - len(tag) - len(message.format(0))
) + "\n"

# To avoid depending on the performance of the test device, we mock the
# passage of time.
mock_now = time()

def mock_time():
# Avoid division by zero by simulating a small delay.
mock_sleep(0.0001)
return mock_now

def mock_sleep(duration):
nonlocal mock_now
mock_now += duration

# See _android_support.py. The default values of these parameters work
# well across a wide range of devices, but we'll use smaller values to
# ensure a quick and reliable test that doesn't flood the log too much.
Expand All @@ -395,21 +412,24 @@ def test_rate_limit(self):
with (
patch("_android_support.MAX_BYTES_PER_SECOND", MAX_KB_PER_SECOND * 1024),
patch("_android_support.BUCKET_SIZE", BUCKET_KB * 1024),
patch("_android_support.sleep", mock_sleep),
patch("_android_support.time", mock_time),
):
# Make sure the token bucket is full.
sleep(BUCKET_KB / MAX_KB_PER_SECOND)
stream.write("Initial message to reset _prev_write_time")
mock_sleep(BUCKET_KB / MAX_KB_PER_SECOND)
line_num = 0

# Write BUCKET_KB messages, and return the rate at which they were
# accepted in KB per second.
def write_bucketful():
nonlocal line_num
start = time()
start = mock_time()
max_line_num = line_num + BUCKET_KB
while line_num < max_line_num:
stream.write(message.format(line_num))
line_num += 1
return BUCKET_KB / (time() - start)
return BUCKET_KB / (mock_time() - start)

# The first bucketful should be written with minimal delay. The
# factor of 2 here is not arbitrary: it verifies that the system can
Expand All @@ -427,5 +447,5 @@ def write_bucketful():
)

# Once the token bucket refills, we should go back to full speed.
sleep(BUCKET_KB / MAX_KB_PER_SECOND)
mock_sleep(BUCKET_KB / MAX_KB_PER_SECOND)
self.assertGreater(write_bucketful(), MAX_KB_PER_SECOND * 2)
Loading