diff --git a/swh/core/github/pytest_plugin.py b/swh/core/github/pytest_plugin.py --- a/swh/core/github/pytest_plugin.py +++ b/swh/core/github/pytest_plugin.py @@ -56,6 +56,7 @@ def github_ratelimit_callback( request: requests_mock.request._RequestObjectProxy, context: requests_mock.response._Context, + remaining_requests: int, ratelimit_reset: Optional[int], ) -> Dict[str, str]: """Return a rate-limited GitHub API response.""" @@ -69,6 +70,7 @@ if ratelimit_reset is not None: context.headers["X-Ratelimit-Reset"] = str(ratelimit_reset) + context.headers["X-Ratelimit-Remaining"] = str(remaining_requests) return { "message": "API rate limit exceeded for .", @@ -94,6 +96,7 @@ def github_response_callback( request: requests_mock.request._RequestObjectProxy, context: requests_mock.response._Context, + remaining_requests: int, page_size: int = 1000, origin_count: int = 10000, ) -> List[Dict[str, Union[str, int]]]: @@ -116,12 +119,13 @@ # header to the response next_url = f"{HTTP_GITHUB_API_URL}?per_page={page_size}&since={next_page}" context.headers["Link"] = f"<{next_url}>; rel=next" + context.headers["X-Ratelimit-Remaining"] = str(remaining_requests) return [github_repo(i) for i in range(since + 1, min(next_page, origin_count) + 1)] @pytest.fixture() -def requests_ratelimited( +def github_requests_ratelimited( num_before_ratelimit: int, num_ratelimit: Optional[int], ratelimit_reset: Optional[int], @@ -151,13 +155,27 @@ def response_callback(request, context): nonlocal current_request current_request += 1 - if num_before_ratelimit < current_request and ( - num_ratelimit is None - or current_request < num_before_ratelimit + num_ratelimit + 1 + if num_before_ratelimit >= current_request: + # case 1: not yet rate-limited + return github_response_callback( + request, context, (num_before_ratelimit or 1000) - current_request + ) + elif ( + num_ratelimit is not None + and current_request >= num_before_ratelimit + num_ratelimit + 1 ): - return github_ratelimit_callback(request, context, ratelimit_reset) + # case 3: no longer rate-limited + return github_response_callback( + request, context, (num_before_ratelimit + 1000) - current_request + ) else: - return github_response_callback(request, context) + # case 2: being rate-limited + return github_ratelimit_callback( + request, + context, + max(0, (num_before_ratelimit or 1000) - current_request), + ratelimit_reset, + ) with requests_mock.Mocker() as mock: mock.get(HTTP_GITHUB_API_URL, json=response_callback) diff --git a/swh/core/github/tests/test_github_utils.py b/swh/core/github/tests/test_github_utils.py --- a/swh/core/github/tests/test_github_utils.py +++ b/swh/core/github/tests/test_github_utils.py @@ -3,7 +3,9 @@ # License: GNU General Public License version 3, or any later version # See top-level LICENSE file for more information +import itertools import logging +from unittest.mock import call import pytest @@ -123,7 +125,8 @@ ) def test_github_session_ratelimit_once_recovery( caplog, - requests_ratelimited, + mocker, + github_requests_ratelimited, num_ratelimit, monkeypatch_sleep_calls, github_credentials, @@ -135,6 +138,8 @@ user_agent="GitHub Session Test", credentials=github_credentials ) + statsd_report = mocker.patch.object(github_session.statsd, "_report") + res = github_session.request(f"{HTTP_GITHUB_API_URL}?per_page=1000&since=10") assert res.status_code == 200 @@ -149,6 +154,25 @@ # check that we slept for one second between our token uses assert monkeypatch_sleep_calls == [1] + username0 = github_session.credentials[0]["username"] + username1 = github_session.credentials[1]["username"] + tags0 = {"username": username0, "http_status": 429} + tags1 = {"username": username1, "http_status": 200} + assert [c for c in statsd_report.mock_calls] == [ + call("requests_total", "c", 1, {"username": username0}, 1), + call("responses_total", "c", 1, tags0, 1), + call("remaining_requests", "g", 999, {"username": username0}, 1), + call("rate_limited_responses_total", "c", 1, {"username": username0}, 1), + call("sleep", "c", 1, None, 1), + call("requests_total", "c", 1, {"username": username1}, 1), + call("responses_total", "c", 1, tags1, 1), + call("remaining_requests", "g", 998, {"username": username1}, 1), + ] + assert github_session.statsd.constant_tags == { + "api_type": "github", + "api_instance": "github", + } + def test_github_session_authenticated_credentials( caplog, github_credentials, all_tokens @@ -179,7 +203,8 @@ ) def test_github_session_ratelimit_reset_sleep( caplog, - requests_ratelimited, + mocker, + github_requests_ratelimited, monkeypatch_sleep_calls, num_before_ratelimit, num_ratelimit, @@ -193,6 +218,8 @@ user_agent="GitHub Session Test", credentials=github_credentials ) + statsd_report = mocker.patch.object(github_session.statsd, "_report") + for _ in range(num_ratelimit): github_session.request(f"{HTTP_GITHUB_API_URL}?per_page=1000&since=10") @@ -209,3 +236,126 @@ break assert found_exhaustion_message is True + + username0 = github_session.credentials[0]["username"] + + def ok_request_calls(user, remaining): + return [ + call("requests_total", "c", 1, {"username": user}, 1), + call("responses_total", "c", 1, {"username": user, "http_status": 200}, 1), + call("remaining_requests", "g", remaining, {"username": user}, 1), + ] + + def ratelimited_request_calls(user): + return [ + call("requests_total", "c", 1, {"username": user}, 1), + call("responses_total", "c", 1, {"username": user, "http_status": 429}, 1), + call("remaining_requests", "g", 0, {"username": user}, 1), + call("reset_seconds", "g", ratelimit_reset, {"username": user}, 1), + call("rate_limited_responses_total", "c", 1, {"username": user}, 1), + call("sleep", "c", 1, None, 1), + ] + + expected_calls_groups = ( + # Successful requests + [ok_request_calls(username0, n - 1) for n in range(num_before_ratelimit, 0, -1)] + # Then rate-limited failures, cycling through tokens + + [ + ratelimited_request_calls( + github_session.credentials[n % len(github_credentials)]["username"] + ) + for n in range(num_ratelimit) + ] + # And finally, a long sleep and the successful request + + [ + [call("sleep", "c", ratelimit_reset + 1, None, 1)], + ok_request_calls( + github_session.credentials[num_ratelimit % len(github_credentials)][ + "username" + ], + 1000 - num_ratelimit - 1, + ), + ] + ) + expected_calls = list(itertools.chain.from_iterable(expected_calls_groups)) + assert [c for c in statsd_report.mock_calls] == expected_calls + assert github_session.statsd.constant_tags == { + "api_type": "github", + "api_instance": "github", + } + + +# Same as before, but with no credentials +@pytest.mark.parametrize( + "num_before_ratelimit, num_ratelimit, ratelimit_reset", + [(5, 6, 123456)], +) +def test_github_session_ratelimit_reset_sleep_anonymous( + caplog, + mocker, + github_requests_ratelimited, + monkeypatch_sleep_calls, + num_before_ratelimit, + num_ratelimit, + ratelimit_reset, +): + """GitHubSession should handle rate-limit with authentication tokens.""" + caplog.set_level(logging.DEBUG, "swh.core.github.utils") + + github_session = GitHubSession(user_agent="GitHub Session Test") + + statsd_report = mocker.patch.object(github_session.statsd, "_report") + + for _ in range(num_ratelimit): + github_session.request(f"{HTTP_GITHUB_API_URL}?per_page=1000&since=10") + + # No credentials, so we immediately sleep for a long time + expected_sleep_calls = [ratelimit_reset + 1] * num_ratelimit + assert monkeypatch_sleep_calls == expected_sleep_calls + + found_exhaustion_message = False + for record in caplog.records: + if record.levelname == "INFO": + if "Rate limits exhausted for all tokens" in record.message: + found_exhaustion_message = True + break + + assert found_exhaustion_message is True + + user = "anonymous" + + def ok_request_calls(remaining): + return [ + call("requests_total", "c", 1, {"username": user}, 1), + call("responses_total", "c", 1, {"username": user, "http_status": 200}, 1), + call("remaining_requests", "g", remaining, {"username": user}, 1), + ] + + def ratelimited_request_calls(): + return [ + call("requests_total", "c", 1, {"username": user}, 1), + call("responses_total", "c", 1, {"username": user, "http_status": 403}, 1), + call("remaining_requests", "g", 0, {"username": user}, 1), + call("reset_seconds", "g", ratelimit_reset, {"username": user}, 1), + call("rate_limited_responses_total", "c", 1, {"username": user}, 1), + call("sleep", "c", ratelimit_reset + 1, None, 1), + ] + + expected_calls_groups = ( + # Successful requests + [ok_request_calls(n - 1) for n in range(num_before_ratelimit, 0, -1)] + # Then rate-limited failures, each with a long sleep + + [ratelimited_request_calls() for n in range(num_ratelimit)] + # And finally, the successful request + + [ + ok_request_calls( + 1000 - num_ratelimit - 1, + ), + ] + ) + expected_calls = list(itertools.chain.from_iterable(expected_calls_groups)) + assert [c for c in statsd_report.mock_calls] == expected_calls + assert github_session.statsd.constant_tags == { + "api_type": "github", + "api_instance": "github", + } diff --git a/swh/core/github/utils.py b/swh/core/github/utils.py --- a/swh/core/github/utils.py +++ b/swh/core/github/utils.py @@ -19,6 +19,8 @@ wait_exponential, ) +from ..statsd import Statsd + GITHUB_PATTERN = re.compile( r"(//|git://|git@|git//|https?://|ssh://|.*@)github.com[/:](?P.*)" ) @@ -99,6 +101,11 @@ random.shuffle(creds) self.credentials = creds + self.statsd = Statsd( + namespace="swh_outbound_api", + constant_tags={"api_type": "github", "api_instance": "github"}, + ) + self.session = requests.Session() self.session.headers.update( @@ -147,14 +154,48 @@ ), ) def _request(self, url: str) -> requests.Response: + # When anonymous, rate-limits are per-IP; but we cannot necessarily + # get the IP/hostname here as we may be containerized. Instead, we rely on + # statsd-exporter adding the hostname in the 'instance' tag. + tags = {"username": self.current_user or "anonymous"} + + self.statsd.increment("requests_total", tags=tags) + response = self.session.get(url) + # self.session.get(url) raises in case of non-HTTP error (DNS, TCP, TLS, ...), + # so responses_total may differ from requests_total. + self.statsd.increment( + "responses_total", tags={**tags, "http_status": response.status_code} + ) + + try: + ratelimit_remaining = int(response.headers["x-ratelimit-remaining"]) + except (KeyError, ValueError): + logger.warning( + "Invalid x-ratelimit-remaining header from GitHub: %r", + response.headers.get("x-ratelimit-remaining"), + ) + else: + self.statsd.gauge("remaining_requests", ratelimit_remaining, tags=tags) + + try: + reset_seconds = int(response.headers["x-ratelimit-reset"]) - time.time() + except (KeyError, ValueError): + logger.warning( + "Invalid x-ratelimit-reset header from GitHub: %r", + response.headers.get("x-ratelimit-reset"), + ) + else: + self.statsd.gauge("reset_seconds", reset_seconds, tags=tags) + if ( # GitHub returns inconsistent status codes between unauthenticated # rate limit and authenticated rate limits. Handle both. response.status_code == 429 or (self.anonymous and response.status_code == 403) ): + self.statsd.increment("rate_limited_responses_total", tags=tags) raise RateLimited(response) return response @@ -191,6 +232,7 @@ # Use next token in line self.set_next_session_token() # Wait one second to avoid triggering GitHub's abuse rate limits + self.statsd.increment("sleep", 1) time.sleep(1) # All tokens have been rate-limited. What do we do? @@ -207,6 +249,7 @@ "Rate limits exhausted for all tokens. Sleeping for %f seconds.", sleep_time, ) + self.statsd.increment("sleep", sleep_time) time.sleep(sleep_time) def get_canonical_url(self, url: str) -> Optional[str]: diff --git a/swh/core/statsd.py b/swh/core/statsd.py --- a/swh/core/statsd.py +++ b/swh/core/statsd.py @@ -223,7 +223,7 @@ continue if ":" not in tag: warnings.warn( - "STATSD_TAGS needs to be in key:value format, " "%s invalid" % tag, + f"STATSD_TAGS needs to be in 'key:value' format, not {tag!r}", UserWarning, ) continue