github: Export statsd metrics about API requests and token usage

We will need to monitored token usage when scheduling recurring fetches
of extrinsic metadata.

Metrics on API requests and sleep time themselves are just an extra
that may be handy in the future.

swh/core/github/pytest_plugin.py

@@ -56,6 +56,7 @@ def ratelimit_reset() -> Optional[int]:
 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 @@ def github_ratelimit_callback(
 
     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 <IP>.",
@@ -94,6 +96,7 @@ def github_repo(i: int) -> Dict[str, Union[int, str]]:
 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 @@ def github_response_callback(
         # 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 requests_ratelimited(
     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)

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_anonymous_session():
 )
 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 @@ def test_github_session_ratelimit_once_recovery(
         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 @@ def test_github_session_ratelimit_once_recovery(
     # 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_authenticated_credentials(
 )
 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 @@ def test_github_session_ratelimit_reset_sleep(
         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 @@ def test_github_session_ratelimit_reset_sleep(
                 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",
+    }

swh/core/github/utils.py

@@ -19,6 +19,8 @@ from tenacity import (
     wait_exponential,
 )
 
+from ..statsd import Statsd
+
 GITHUB_PATTERN = re.compile(
     r"(//|git://|git@|git//|https?://|ssh://|.*@)github.com[/:](?P<user_repo>.*)"
 )
@@ -99,6 +101,11 @@ class GitHubSession:
             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 @@ class GitHubSession:
         ),
     )
     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 @@ class GitHubSession:
                         # 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 @@ class GitHubSession:
                 "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]:

swh/core/statsd.py

@@ -223,7 +223,7 @@ class Statsd(object):
                 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