test: refactor integration and unit tests for the LoggingMiddleware

merino/middleware/logging.py

@@ -24,12 +24,12 @@ class LoggingMiddleware:
     """An ASGI middleware for logging."""
 
     def __init__(self, app: ASGIApp) -> None:
-        """Initilize."""
+        """Initialize."""
         self.app = app
 
     async def __call__(self, scope: Scope, receive: Receive, send: Send):
         """Log requests."""
-        if scope["type"] != "http":  # pragma: no cover
+        if scope["type"] != "http":
             await self.app(scope, receive, send)
             return
 

pyproject.toml

@@ -84,6 +84,7 @@ types-PyYAML = "^6.0.11"
 types-requests = "^2.28.10"
 types-geoip2 = "^3.0.0"
 scalene = "^1.5.13"
+pytest-freezegun = "^0.4.2"
 
 [build-system]
 requires = ["poetry-core>=1.0.0"]

tests/integration/api/test_heartbeat.py

@@ -2,14 +2,8 @@
 # License, v. 2.0. If a copy of the MPL was not distributed with this
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
-import logging
-
 import pytest
 from fastapi.testclient import TestClient
-from pytest import LogCaptureFixture
-from pytest_mock import MockerFixture
-
-from tests.types import FilterCaplogFixture
 
 
 @pytest.mark.parametrize("endpoint", ["__heartbeat__", "__lbheartbeat__"])
@@ -18,27 +12,3 @@ def test_heartbeats(client: TestClient, endpoint: str) -> None:
     response = client.get(f"/{endpoint}")
 
     assert response.status_code == 200
-
-
-def test_non_suggest_request_logs_contain_required_info(
-    mocker: MockerFixture,
-    caplog: LogCaptureFixture,
-    filter_caplog: FilterCaplogFixture,
-    client: TestClient,
-) -> None:
-    caplog.set_level(logging.INFO)
-
-    # Use a valid IP to avoid the geolocation errors/logs
-    mock_client = mocker.patch("fastapi.Request.client")
-    mock_client.host = "127.0.0.1"
-
-    client.get("/__heartbeat__")
-
-    records = filter_caplog(caplog.records, "request.summary")
-    assert len(records) == 1
-
-    record = records[0]
-    assert record.name == "request.summary"
-    assert "country" not in record.__dict__["args"]
-    assert "session_id" not in record.__dict__["args"]
-    assert record.__dict__["path"] == "/__heartbeat__"

tests/integration/api/v1/providers/test_providers.py

@@ -1,16 +1,21 @@
 # This Source Code Form is subject to the terms of the Mozilla Public
 # License, v. 2.0. If a copy of the MPL was not distributed with this
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
+import logging
+from logging import LogRecord
+from typing import Any
 
 import pytest
 from fastapi.testclient import TestClient
+from pytest import LogCaptureFixture
 
 from merino.providers import BaseProvider
 from tests.integration.api.v1.fake_providers import (
     HiddenProvider,
     NonsponsoredProvider,
     SponsoredProvider,
 )
+from tests.types import FilterCaplogFixture
 
 
 @pytest.mark.parametrize(
@@ -75,3 +80,59 @@ def test_providers(
 
     assert response.status_code == 200
     assert response.json() == expected_response
+
+
+@pytest.mark.freeze_time("1998-03-31")
+@pytest.mark.parametrize("providers", [{}])
+def test_providers_request_logs(
+    caplog: LogCaptureFixture,
+    filter_caplog: FilterCaplogFixture,
+    client: TestClient,
+) -> None:
+    """
+    Tests that the logs for the 'providers' endpoint contain the required extra data
+    """
+    caplog.set_level(logging.INFO)
+
+    expected_log_data: dict[str, Any] = {
+        "name": "request.summary",
+        "agent": (
+            "Mozilla/5.0 (Macintosh; Intel Mac OS X 11.2; rv:85.0)"
+            " Gecko/20100101 Firefox/103.0"
+        ),
+        "path": "/api/v1/providers",
+        "method": "GET",
+        "lang": "en-US",
+        "querystring": {},
+        "errno": 0,
+        "code": 200,
+        "time": "1998-03-31T00:00:00",
+    }
+
+    client.get(
+        "/api/v1/providers",
+        headers={
+            "accept-language": "en-US",
+            "User-Agent": (
+                "Mozilla/5.0 (Macintosh; Intel Mac OS X 11.2; rv:85.0) "
+                "Gecko/20100101 Firefox/103.0"
+            ),
+        },
+    )
+
+    records: list[LogRecord] = filter_caplog(caplog.records, "request.summary")
+    assert len(records) == 1
+
+    record: LogRecord = records[0]
+    log_data: dict[str, Any] = {
+        "name": record.name,
+        "agent": record.__dict__["agent"],
+        "path": record.__dict__["path"],
+        "method": record.__dict__["method"],
+        "lang": record.__dict__["lang"],
+        "querystring": record.__dict__["querystring"],
+        "errno": record.__dict__["errno"],
+        "code": record.__dict__["code"],
+        "time": record.__dict__["time"],
+    }
+    assert log_data == expected_log_data

tests/integration/api/v1/suggest/test_suggest.py

@@ -5,6 +5,7 @@
 """Integration tests for the Merino v1 suggest API endpoint."""
 
 import logging
+from typing import Any
 
 import pytest
 from fastapi.testclient import TestClient
@@ -80,61 +81,88 @@ def test_client_variants(client: TestClient) -> None:
     assert result["client_variants"] == ["foo", "bar"]
 
 
-def test_suggest_request_logs_contain_required_info(
+@pytest.mark.freeze_time("1998-03-31")
+def test_suggest_request_logs(
     mocker: MockerFixture,
     caplog: LogCaptureFixture,
     filter_caplog: FilterCaplogFixture,
     client: TestClient,
 ) -> None:
-
+    """Tests that the logs for the 'suggest' endpoint contain the required extra data"""
     caplog.set_level(logging.INFO)
 
     # The IP address is taken from `GeoLite2-City-Test.mmdb`
     mock_client = mocker.patch("fastapi.Request.client")
     mock_client.host = "216.160.83.56"
 
-    query = "nope"
-    sid = "deadbeef-0000-1111-2222-333344445555"
-    seq = 0
-    client_variants = "foo,bar"
-    providers = "pro,vider"
-    root_path = "/api/v1/suggest"
-    headers = {
-        "User-Agent": (
-            "Mozilla/5.0 (Macintosh; Intel Mac OS X 11.2;"
-            " rv:85.0) Gecko/20100101 Firefox/103.0"
-        )
+    expected_log_data: dict[str, Any] = {
+        "name": "web.suggest.request",
+        "sensitive": True,
+        "path": "/api/v1/suggest",
+        "method": "GET",
+        "query": "nope",
+        "errno": 0,
+        "code": 200,
+        "time": "1998-03-31T00:00:00",
+        "rid": "1b11844c52b34c33a6ad54b7bc2eb7c7",
+        "session_id": "deadbeef-0000-1111-2222-333344445555",
+        "sequence_no": 0,
+        "country": "US",
+        "region": "WA",
+        "city": "Milton",
+        "dma": 819,
+        "client_variants": "foo,bar",
+        "requested_providers": "pro,vider",
+        "browser": "Firefox(103.0)",
+        "os_family": "macos",
+        "form_factor": "desktop",
     }
+
     client.get(
-        f"{root_path}?q={query}&sid={sid}&seq={seq}"
-        f"&client_variants={client_variants}&providers={providers}",
-        headers=headers,
+        f"{expected_log_data['path']}?q={expected_log_data['query']}"
+        f"&sid={expected_log_data['session_id']}"
+        f"&seq={expected_log_data['sequence_no']}"
+        f"&client_variants={expected_log_data['client_variants']}"
+        f"&providers={expected_log_data['requested_providers']}",
+        headers={
+            "User-Agent": (
+                "Mozilla/5.0 (Macintosh; Intel Mac OS X 11.2; rv:85.0) "
+                "Gecko/20100101 Firefox/103.0"
+            ),
+            "x-request-id": "1b11844c52b34c33a6ad54b7bc2eb7c7",
+        },
     )
 
     records = filter_caplog(caplog.records, "web.suggest.request")
-
     assert len(records) == 1
 
     record = records[0]
+    log_data: dict[str, Any] = {
+        "name": record.name,
+        "sensitive": record.__dict__["sensitive"],
+        "path": record.__dict__["path"],
+        "method": record.__dict__["method"],
+        "query": record.__dict__["query"],
+        "errno": record.__dict__["errno"],
+        "code": record.__dict__["code"],
+        "time": record.__dict__["time"],
+        "rid": record.__dict__["rid"],
+        "session_id": record.__dict__["session_id"],
+        "sequence_no": record.__dict__["sequence_no"],
+        "country": record.__dict__["country"],
+        "region": record.__dict__["region"],
+        "city": record.__dict__["city"],
+        "dma": record.__dict__["dma"],
+        "client_variants": record.__dict__["client_variants"],
+        "requested_providers": record.__dict__["requested_providers"],
+        "browser": record.__dict__["browser"],
+        "os_family": record.__dict__["os_family"],
+        "form_factor": record.__dict__["form_factor"],
+    }
+    assert log_data == expected_log_data
+
 
-    assert record.name == "web.suggest.request"
-    assert record.__dict__["sensitive"] is True
-    assert record.__dict__["path"] == root_path
-    assert record.__dict__["session_id"] == sid
-    assert record.__dict__["sequence_no"] == seq
-    assert record.__dict__["query"] == query
-    assert record.__dict__["client_variants"] == client_variants
-    assert record.__dict__["requested_providers"] == providers
-    assert record.__dict__["browser"] == "Firefox(103.0)"
-    assert record.__dict__["os_family"] == "macos"
-    assert record.__dict__["form_factor"] == "desktop"
-    assert record.__dict__["country"] == "US"
-    assert record.__dict__["region"] == "WA"
-    assert record.__dict__["city"] == "Milton"
-    assert record.__dict__["dma"] == 819
-
-
-def test_geolocation_with_invalid_ip(
+def test_suggest_with_invalid_geolocation_ip(
     mocker: MockerFixture,
     caplog: LogCaptureFixture,
     filter_caplog: FilterCaplogFixture,