Log Wikimedia API request metrics

add_links/api.py

@@ -1,3 +1,5 @@
+import os
+from pathlib import Path
 import re
 import sys
 import typing
@@ -8,6 +10,7 @@ from simplejson.scanner import JSONDecodeError
 
 from .language import get_current_language
 from .util import is_disambig
+from .wikimedia_api_logging import WikimediaApiLogConfig, logged_request
 
 StrDict = dict[str, typing.Any]
 
@@ -15,6 +18,15 @@ ua = (
     "find-link/2.2 "
     + "(https://github.com/EdwardBetts/find_link; contact: edward@4angle.com)"
 )
+wikimedia_log_config = WikimediaApiLogConfig(
+    tool="missinglink",
+    log_path=Path(
+        os.environ.get(
+            "MISSINGLINK_WIKIMEDIA_API_LOG", "/var/log/missinglink/wikimedia-api.jsonl"
+        )
+    ),
+    user_agent=ua,
+)
 re_disambig = re.compile(r"^(.*) \((.*)\)$")
 
 
@@ -73,23 +85,22 @@ webpage_error = (
 )
 
 
-def _get_active_session() -> requests.sessions.Session:
-    """Return OAuth session if one is available in Flask context, else plain session."""
+def _get_active_session() -> tuple[requests.sessions.Session, str]:
+    """Return active session and auth mode."""
     try:
         from flask import g
         if hasattr(g, "oauth_session") and g.oauth_session is not None:
-            return g.oauth_session  # type: ignore[return-value]
+            return g.oauth_session, "oauth"  # type: ignore[return-value]
     except RuntimeError:
         pass
     print("WARNING: using unauthenticated session", file=sys.stderr)
-    return get_session()
+    return get_session(), "anon"
 
 
 def api_get(params: StrDict) -> StrDict:
     """Make call to Wikipedia API."""
-    s = _get_active_session()
-
-    r = s.get(get_query_url(), params=params)
+    s, _auth = _get_active_session()
+    r = logged_request(s, wikimedia_log_config, "GET", get_query_url(), params=params)
     try:
         ret: StrDict = r.json()
     except JSONDecodeError:
@@ -287,8 +298,8 @@ def call_get_diff(title: str, section_num: int, section_text: str) -> str:
         "rvdifftotext": section_text.strip(),
     }
 
-    s = _get_active_session()
-    r = s.post(get_query_url(), data=data)
+    s, _auth = _get_active_session()
+    r = logged_request(s, wikimedia_log_config, "POST", get_query_url(), data=data)
     try:
         ret = r.json()
     except JSONDecodeError:

add_links/mediawiki_api_old.py

@@ -4,6 +4,9 @@ from typing import Any
 
 import requests
 
+from .api import wikimedia_log_config
+from .wikimedia_api_logging import logged_request
+
 wiki_hostname = "en.wikipedia.org"
 wiki_api_php = f"https://{wiki_hostname}/w/api.php"
 user_agent = "dab-mechanic/0.1"
@@ -27,8 +30,10 @@ def parse_page(enwiki: str) -> dict[str, Any]:
 
 def get(params: dict[str, str | int]) -> dict[str, Any]:
     """Make GET request to mediawiki API."""
-    data: dict[str, Any] = requests.get(
-        wiki_api_php, headers={"User-Agent": user_agent}, params=params
+    session = requests.Session()
+    session.headers = {"User-Agent": user_agent}
+    data: dict[str, Any] = logged_request(
+        session, wikimedia_log_config, "GET", wiki_api_php, params=params
     ).json()
     return data
 

add_links/mediawiki_oauth.py

@@ -9,7 +9,8 @@ import requests
 from flask import current_app, session
 from requests_oauthlib import OAuth1Session
 
-from .api import ua
+from .api import ua, wikimedia_log_config
+from .wikimedia_api_logging import logged_request
 
 wiki_hostname = "en.wikipedia.org"
 api_url = f"https://{wiki_hostname}/w/api.php"
@@ -44,7 +45,15 @@ def api_post_request(params: dict[str, str | int], timeout: int = 4) -> requests
     )
     oauth.headers.update({"User-Agent": ua})
     proxies = get_edit_proxy()
-    return oauth.post(api_url, data=params, timeout=timeout, proxies=proxies)
+    return logged_request(
+        oauth,
+        wikimedia_log_config,
+        "POST",
+        api_url,
+        data=params,
+        timeout=timeout,
+        proxies=proxies,
+    )
 
 
 def raw_request(params: typing.Mapping[str, str | int]) -> requests.Response:
@@ -63,8 +72,13 @@ def raw_request(params: typing.Mapping[str, str | int]) -> requests.Response:
     )
     oauth.headers.update({"User-Agent": ua})
     proxies = get_edit_proxy()
-    return oauth.get(
-        api_url + "?" + urllib.parse.urlencode(params), timeout=4, proxies=proxies
+    return logged_request(
+        oauth,
+        wikimedia_log_config,
+        "GET",
+        api_url + "?" + urllib.parse.urlencode(params),
+        timeout=4,
+        proxies=proxies,
     )
 
 

add_links/wikimedia_api_logging.py

@@ -0,0 +1,222 @@
+"""JSONL logging helpers for Wikimedia API request metrics."""
+
+import json
+import logging
+import os
+import socket
+import time
+from collections.abc import Mapping
+from dataclasses import dataclass
+from datetime import UTC, datetime
+from pathlib import Path
+from types import TracebackType
+from urllib.parse import parse_qs, urlparse
+
+import requests
+
+
+@dataclass(frozen=True)
+class WikimediaApiLogConfig:
+    """Configuration for Wikimedia API request logging."""
+
+    tool: str
+    log_path: Path
+    user_agent: str
+
+
+@dataclass(frozen=True)
+class WikimediaApiRequestMetric:
+    """Details of one Wikimedia API request."""
+
+    tool: str
+    url: str
+    method: str
+    status_code: int | None
+    elapsed_ms: int
+    user_agent: str
+    request_params: Mapping[str, object] | None = None
+    error: str | None = None
+
+
+_logger_cache: dict[Path, logging.Logger] = {}
+
+
+def setup_wikimedia_api_logger(log_path: Path) -> logging.Logger:
+    """Create a JSONL logger for Wikimedia API request metrics."""
+    if log_path in _logger_cache:
+        return _logger_cache[log_path]
+
+    logger_name = f"wikimedia_api_metrics.{log_path}"
+    logger = logging.getLogger(logger_name)
+    logger.setLevel(logging.INFO)
+    logger.propagate = False
+
+    if not logger.handlers:
+        try:
+            log_path.parent.mkdir(parents=True, exist_ok=True)
+            handler: logging.Handler = logging.FileHandler(log_path)
+        except OSError:
+            handler = logging.NullHandler()
+        handler.setFormatter(logging.Formatter("%(message)s"))
+        logger.addHandler(handler)
+
+    _logger_cache[log_path] = logger
+    return logger
+
+
+def get_mediawiki_action(
+    url: str, request_params: Mapping[str, object] | None = None
+) -> str | None:
+    """Extract the MediaWiki API action from params or a URL, if present."""
+    if request_params is not None:
+        action = request_params.get("action")
+        if isinstance(action, str):
+            return action
+
+    parsed = urlparse(url)
+    query = parse_qs(parsed.query)
+    values = query.get("action")
+
+    if not values:
+        return None
+
+    return values[0]
+
+
+def get_flask_request_context() -> tuple[str | None, str | None]:
+    """Return Flask endpoint and browser URL when running in a request."""
+    try:
+        from flask import has_request_context, request
+
+        if not has_request_context():
+            return None, None
+        return request.endpoint, request.url
+    except RuntimeError:
+        return None, None
+
+
+def build_log_record(metric: WikimediaApiRequestMetric) -> dict[str, object]:
+    """Build a JSON-serialisable log record for one API request."""
+    parsed = urlparse(metric.url)
+    flask_endpoint, flask_url = get_flask_request_context()
+
+    record: dict[str, object] = {
+        "ts": datetime.now(UTC).isoformat(),
+        "tool": metric.tool,
+        "host": socket.gethostname(),
+        "pid": os.getpid(),
+        "method": metric.method,
+        "api_host": parsed.netloc,
+        "path": parsed.path,
+        "action": get_mediawiki_action(metric.url, metric.request_params),
+        "status_code": metric.status_code,
+        "elapsed_ms": metric.elapsed_ms,
+        "user_agent": metric.user_agent,
+        "flask_endpoint": flask_endpoint,
+        "flask_url": flask_url,
+    }
+
+    if metric.error is not None:
+        record["error"] = metric.error
+
+    return record
+
+
+def log_wikimedia_api_request(
+    logger: logging.Logger,
+    metric: WikimediaApiRequestMetric,
+) -> None:
+    """Write one Wikimedia API request metric as a JSONL log line."""
+    record = build_log_record(metric)
+    logger.info(json.dumps(record, separators=(",", ":"), sort_keys=True))
+
+
+class WikimediaRequestTimer:
+    """Context manager for timing and logging a Wikimedia API request."""
+
+    def __init__(
+        self,
+        config: WikimediaApiLogConfig,
+        method: str,
+        url: str,
+        request_params: Mapping[str, object] | None = None,
+    ) -> None:
+        self.config = config
+        self.method = method
+        self.url = url
+        self.request_params = request_params
+        self.started = 0.0
+        self.logger = setup_wikimedia_api_logger(config.log_path)
+
+    def __enter__(self) -> "WikimediaRequestTimer":
+        """Start timing a request."""
+        self.started = time.monotonic()
+        return self
+
+    def __exit__(
+        self,
+        exc_type: type[BaseException] | None,
+        exc: BaseException | None,
+        traceback: TracebackType | None,
+    ) -> bool:
+        """Log failed requests when an exception escapes."""
+        if exc is None:
+            return False
+
+        elapsed_ms = int((time.monotonic() - self.started) * 1000)
+
+        log_wikimedia_api_request(
+            self.logger,
+            WikimediaApiRequestMetric(
+                tool=self.config.tool,
+                url=self.url,
+                method=self.method,
+                status_code=None,
+                elapsed_ms=elapsed_ms,
+                user_agent=self.config.user_agent,
+                request_params=self.request_params,
+                error=type(exc).__name__,
+            ),
+        )
+
+        return False
+
+    def log_response(self, status_code: int, final_url: str | None = None) -> None:
+        """Log a completed request."""
+        elapsed_ms = int((time.monotonic() - self.started) * 1000)
+
+        log_wikimedia_api_request(
+            self.logger,
+            WikimediaApiRequestMetric(
+                tool=self.config.tool,
+                url=final_url or self.url,
+                method=self.method,
+                status_code=status_code,
+                elapsed_ms=elapsed_ms,
+                user_agent=self.config.user_agent,
+                request_params=self.request_params,
+            ),
+        )
+
+
+def logged_request(
+    session: requests.sessions.Session,
+    config: WikimediaApiLogConfig,
+    method: str,
+    url: str,
+    **kwargs: object,
+) -> requests.Response:
+    """Make a Wikimedia API request and log one JSONL metric line."""
+    request_params = kwargs.get("params") or kwargs.get("data")
+    if not isinstance(request_params, Mapping):
+        request_params = None
+
+    with WikimediaRequestTimer(
+        config, method.upper(), url, request_params=request_params
+    ) as timer:
+        response = getattr(session, method.lower())(url, **kwargs)
+        final_url = getattr(response, "url", None)
+        timer.log_response(
+            response.status_code, final_url if isinstance(final_url, str) else None
+        )
+        return response

test_api.py

@@ -19,7 +19,7 @@ class ApiGetTests(unittest.TestCase):
         session = Mock()
         session.get.return_value = response
 
-        with patch("add_links.api._get_active_session", return_value=session):
+        with patch("add_links.api._get_active_session", return_value=(session, "anon")):
             with self.assertRaises(api.MediawikiError) as ctx:
                 api.api_get({"action": "query"})