For ResponseMetrics middleware, improve view tag and add tests

privaterelay/middleware.py

@@ -1,7 +1,10 @@
+import re
 import time
+from collections.abc import Callable
 from datetime import UTC, datetime
 
 from django.conf import settings
+from django.http import HttpRequest, HttpResponse
 from django.shortcuts import redirect
 
 import markus
@@ -51,24 +54,22 @@ def __call__(self, request):
         return response
 
 
-def _get_metric_view_name(request):
-    if request.resolver_match:
-        view = request.resolver_match.func
-        return f"{view.__module__}.{view.__name__}"
-    return "<unknown_view>"
+class ResponseMetrics:
 
+    re_dockerflow = re.compile(r"/__(version|heartbeat|lbheartbeat)__/?$")
 
-class ResponseMetrics:
-    def __init__(self, get_response):
+    def __init__(self, get_response: Callable[[HttpRequest], HttpResponse]) -> None:
         self.get_response = get_response
+        self.middleware = RelayStaticFilesMiddleware()
+
+    def __call__(self, request: HttpRequest) -> HttpResponse:
+        if not settings.STATSD_ENABLED:
+            return self.get_response(request)
 
-    def __call__(self, request):
         start_time = time.time()
         response = self.get_response(request)
         delta = time.time() - start_time
-
-        view_name = _get_metric_view_name(request)
-
+        view_name = self._get_metric_view_name(request)
         metrics.timing(
             "response",
             value=delta * 1000.0,
@@ -78,9 +79,21 @@ def __call__(self, request):
                 f"method:{request.method}",
             ],
         )
-
         return response
 
+    def _get_metric_view_name(self, request: HttpRequest) -> str:
+        if request.resolver_match:
+            view = request.resolver_match.func
+            if hasattr(view, "view_class"):
+                # Wrapped with rest_framework.decorators.api_view
+                return f"{view.__module__}.{view.view_class.__name__}"
+            return f"{view.__module__}.{view.__name__}"
+        if match := self.re_dockerflow.match(request.path_info):
+            return f"dockerflow.django.views.{match[1]}"
+        if self.middleware.is_staticfile(request.path_info):
+            return "<static_file>"
+        return "<unknown_view>"
+
 
 class StoreFirstVisit:
     def __init__(self, get_response):
@@ -120,3 +133,16 @@ def immutable_file_test(self, path, url):
             return True
         else:
             return super().immutable_file_test(path, url)
+
+    def is_staticfile(self, path_info: str) -> bool:
+        """
+        Returns True if this file is served by the middleware.
+
+        This uses the logic from whitenoise.middleware.WhiteNoiseMiddleware.__call__:
+        https://github.com/evansd/whitenoise/blob/220a98894495d407424e80d85d49227a5cf97e1b/src/whitenoise/middleware.py#L117-L124
+        """
+        if self.autorefresh:
+            static_file = self.find_file(path_info)
+        else:
+            static_file = self.files.get(path_info)
+        return static_file is not None

privaterelay/settings.py

@@ -349,16 +349,7 @@
     ]
 
 
-# statsd middleware has to be first to catch errors in everything else
-def _get_initial_middleware() -> list[str]:
-    if STATSD_ENABLED:
-        return [
-            "privaterelay.middleware.ResponseMetrics",
-        ]
-    return []
-
-
-MIDDLEWARE = _get_initial_middleware()
+MIDDLEWARE = ["privaterelay.middleware.ResponseMetrics"]
 
 if USE_SILK:
     MIDDLEWARE.append("silk.middleware.SilkyMiddleware")

privaterelay/tests/middleware_tests.py

@@ -0,0 +1,147 @@
+"""Tests for Relay middlewares used in API and other server requests."""
+
+from django.test import Client
+
+import pytest
+from markus.testing import MetricsMock
+from pytest_django.fixtures import SettingsWrapper
+
+
+@pytest.fixture
+def response_metrics_settings(settings: SettingsWrapper) -> SettingsWrapper:
+    """Setup settings for ResponseMetrics tests."""
+    # Use some middleware in the declared order
+    use_middleware = {
+        "privaterelay.middleware.ResponseMetrics",
+        "privaterelay.middleware.RelayStaticFilesMiddleware",
+        "dockerflow.django.middleware.DockerflowMiddleware",
+    }
+    settings.MIDDLEWARE = [mw for mw in settings.MIDDLEWARE if mw in use_middleware]
+    settings.STATSD_ENABLED = True
+    return settings
+
+
+def test_response_metrics_django_view(
+    client: Client, response_metrics_settings: SettingsWrapper
+) -> None:
+    """Django views emit the expected metric."""
+    with MetricsMock() as mm:
+        response = client.get("/metrics-event")
+    assert response.status_code == 405
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=["status:405", "view:privaterelay.views.metrics_event", "method:GET"],
+    )
+
+
+@pytest.mark.django_db
+def test_response_metrics_dockerflow_heartbeat(
+    client: Client, response_metrics_settings: SettingsWrapper
+) -> None:
+    """The Dockerflow __heartbeat__ endpoint emits the expected metric."""
+    with MetricsMock() as mm:
+        response = client.get("/__heartbeat__")
+    # __heartbeat__ runs some security and connection tests
+    # In some environments, a critical error results in a 500
+    # In others, a warning or better results in a 200
+    assert response.status_code in [200, 500]
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=[
+            f"status:{response.status_code}",
+            "view:dockerflow.django.views.heartbeat",
+            "method:GET",
+        ],
+    )
+
+
+@pytest.mark.parametrize("viewname", ["version", "lbheartbeat"])
+def test_response_metrics_other_dockerflow_view(
+    client: Client, response_metrics_settings: SettingsWrapper, viewname: str
+) -> None:
+    """The other Dockerflow views emit the expected metrics."""
+    with MetricsMock() as mm:
+        response = client.get(f"/__{viewname}__")
+    assert response.status_code == 200
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=[
+            "status:200",
+            f"view:dockerflow.django.views.{viewname}",
+            "method:GET",
+        ],
+    )
+
+
+@pytest.mark.django_db
+def test_response_metrics_api_viewset(
+    client: Client, response_metrics_settings: SettingsWrapper
+) -> None:
+    """API viewsets emit the expected metrics."""
+    with MetricsMock() as mm:
+        response = client.get("/api/v1/users/")
+    assert response.status_code == 401
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=["status:401", "view:api.views.privaterelay.UserViewSet", "method:GET"],
+    )
+
+
+@pytest.mark.django_db
+def test_response_metrics_api_view(
+    client: Client, response_metrics_settings: SettingsWrapper
+) -> None:
+    """API functions wrapped in @api_view emit the expected metrics."""
+    with MetricsMock() as mm:
+        response = client.get("/api/v1/runtime_data")
+    assert response.status_code == 200
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=["status:200", "view:api.views.privaterelay.runtime_data", "method:GET"],
+    )
+
+
+def test_response_metrics_frontend_path(
+    client: Client, response_metrics_settings: SettingsWrapper
+) -> None:
+    """Frontend views emit the expected metrics."""
+    with MetricsMock() as mm:
+        response = client.get("/faq/")
+    # The file is found if the frontend build was done, the DEBUG setting,
+    #  if files were collected, etc.
+    assert response.status_code in [200, 404]
+    # Metrics are only emitted if found.
+    if response.status_code == 200:
+        mm.assert_timing_once(
+            "fx.private.relay.response",
+            tags=["status:200", "view:<static_file>", "method:GET"],
+        )
+
+
+@pytest.mark.django_db
+def test_response_metrics_frontend_file(
+    client: Client, response_metrics_settings: SettingsWrapper
+) -> None:
+    """Frontend files emit the expected metrics."""
+    with MetricsMock() as mm:
+        response = client.get("/favicon.svg")
+    # The file is found if the frontend build was done, the DEBUG setting,
+    #  if files were collected, etc.
+    assert response.status_code in [200, 404]
+    # Metrics are only emitted if found.
+    if response.status_code == 200:
+        mm.assert_timing_once(
+            "fx.private.relay.response",
+            tags=["status:200", "view:<static_file>", "method:GET"],
+        )
+
+
+def test_response_metrics_disabled(
+    client: Client, response_metrics_settings: SettingsWrapper
+) -> None:
+    """ResponseMetrics does not emit metrics when metrics are disabled."""
+    response_metrics_settings.STATSD_ENABLED = False
+    with MetricsMock() as mm:
+        response = client.get("/metrics-event")
+    assert response.status_code == 405
+    assert not mm.get_records()

privaterelay/tests/views_tests.py

@@ -376,7 +376,10 @@ def test_fxa_rp_events_password_change(
     with MetricsMock() as mm:
         response = client.get("/fxa-rp-events", HTTP_AUTHORIZATION=auth_header)
 
-    assert mm.get_records() == []
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=["status:200", "view:privaterelay.views.fxa_rp_events", "method:GET"],
+    )
     assert caplog.record_tuples == [
         ("request.summary", logging.INFO, ""),
     ]
@@ -403,7 +406,10 @@ def test_fxa_rp_events_password_change_slight_future_iat(
     with MetricsMock() as mm:
         response = client.get("/fxa-rp-events", HTTP_AUTHORIZATION=auth_header)
 
-    assert mm.get_records() == []
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=["status:200", "view:privaterelay.views.fxa_rp_events", "method:GET"],
+    )
     assert caplog.record_tuples == [
         ("request.summary", logging.INFO, ""),
     ]
@@ -434,7 +440,10 @@ def test_fxa_rp_events_password_change_far_future_iat(
     with MetricsMock() as mm, pytest.raises(jwt.ImmatureSignatureError):
         client.get("/fxa-rp-events", HTTP_AUTHORIZATION=auth_header)
 
-    assert mm.get_records() == []
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=["status:500", "view:privaterelay.views.fxa_rp_events", "method:GET"],
+    )
     assert caplog.record_tuples == [
         ("eventsinfo", logging.WARNING, "fxa_rp_event.future_iat"),
         ("request.summary", logging.ERROR, "The token is not yet valid (iat)"),
@@ -462,7 +471,10 @@ def test_fxa_rp_events_profile_change(
     with MetricsMock() as mm:
         response = client.get("/fxa-rp-events", HTTP_AUTHORIZATION=auth_header)
 
-    assert mm.get_records() == []
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=["status:200", "view:privaterelay.views.fxa_rp_events", "method:GET"],
+    )
     assert caplog.record_tuples == [
         ("eventsinfo", logging.INFO, "fxa_rp_event"),
         ("request.summary", logging.INFO, ""),
@@ -500,7 +512,10 @@ def test_fxa_rp_events_subscription_change(
 
     with MetricsMock() as mm:
         response = client.get("/fxa-rp-events", HTTP_AUTHORIZATION=auth_header)
-    assert mm.get_records() == []
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=["status:200", "view:privaterelay.views.fxa_rp_events", "method:GET"],
+    )
     assert caplog.record_tuples == [
         ("eventsinfo", logging.INFO, "fxa_rp_event"),
         ("request.summary", logging.INFO, ""),
@@ -538,7 +553,10 @@ def test_fxa_rp_events_delete_user(
 
     with MetricsMock() as mm:
         response = client.get("/fxa-rp-events", HTTP_AUTHORIZATION=auth_header)
-    assert mm.get_records() == []
+    mm.assert_timing_once(
+        "fx.private.relay.response",
+        tags=["status:200", "view:privaterelay.views.fxa_rp_events", "method:GET"],
+    )
     assert caplog.record_tuples == [
         ("eventsinfo", logging.INFO, "fxa_rp_event"),
         ("request.summary", logging.INFO, ""),