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/unit/middleware/conftest.py

@@ -4,6 +4,8 @@
 
 """Module for test fixtures for the middleware unit test directory."""
 
+from typing import Any
+
 import pytest
 from pytest_mock import MockerFixture
 from starlette.types import Receive, Scope, Send
@@ -17,12 +19,12 @@ def fixture_scope() -> Scope:
 
 
 @pytest.fixture(name="receive_mock")
-def fixture_receive_mock(mocker: MockerFixture) -> Receive:
+def fixture_receive_mock(mocker: MockerFixture) -> Any:
     """Create a Receive mock object for test"""
-    return mocker.Mock()
+    return mocker.AsyncMock(spec=Receive)
 
 
 @pytest.fixture(name="send_mock")
-def fixture_send_mock(mocker: MockerFixture) -> Send:
+def fixture_send_mock(mocker: MockerFixture) -> Any:
     """Create a Send mock object for test"""
-    return mocker.Mock()
+    return mocker.AsyncMock(spec=Send)

tests/unit/middleware/test_logging.py

@@ -0,0 +1,237 @@
+# 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/.
+
+"""Unit tests for the middleware logging module."""
+
+import logging
+from logging import LogRecord
+from typing import Any, Callable
+
+import pytest
+from pytest import LogCaptureFixture
+from pytest_mock import MockerFixture
+from starlette.types import ASGIApp, Message, Receive, Scope, Send
+
+from merino.middleware import ScopeKey
+from merino.middleware.geolocation import Location
+from merino.middleware.logging import LoggingMiddleware
+from merino.middleware.user_agent import UserAgent
+from tests.types import FilterCaplogFixture
+
+
+@pytest.fixture(name="logging_middleware")
+def fixture_logging_middleware(mocker: MockerFixture) -> LoggingMiddleware:
+    """Creates a LoggerMiddleware object for test"""
+    asgiapp_mock = mocker.AsyncMock(spec=ASGIApp)
+    return LoggingMiddleware(asgiapp_mock)
+
+
+@pytest.fixture(name="extract_send_wrapper")
+def fixture_extract_send_wrapper() -> Callable[[LoggingMiddleware], Send]:
+    """
+    Return a function that will extract the logging middleware send_wrapper from
+    the asgiapp_mock.
+    """
+
+    def extract_send_wrapper(logging_middleware: LoggingMiddleware) -> Send:
+        """Extract the logging middleware send_wrapper from the asgiapp_mock"""
+        asgiapp_mock: Any = logging_middleware.app
+
+        # The logging middleware will create a send_wrapper and should make a single
+        # call on the asgiapp mock object. The send_wrapper should be stored as the
+        # third call argument. The send_wrapper function is the test target.
+        assert (
+            asgiapp_mock.call_count == 1
+        ), "The `asgiapp_mock` had an unexpected call count"
+        assert (
+            len(asgiapp_mock.call_args.args) == 3
+        ), "The number of call arguments is unexpected"
+
+        send_wrapper: Send = asgiapp_mock.call_args.args[2]
+        return send_wrapper
+
+    return extract_send_wrapper
+
+
+@pytest.mark.asyncio
+@pytest.mark.freeze_time("1998-03-31")
+@pytest.mark.parametrize(
+    "query,expected_sid,expected_client_variants,expected_providers,expected_seq",
+    [
+        (
+            b"q=nope&sid=9aadf682-2f7a-4ad1-9976-dc30b60451d8",
+            "9aadf682-2f7a-4ad1-9976-dc30b60451d8",
+            "",
+            "",
+            None,
+        ),
+        (b"q=nope&client_variants=foo,bar", None, "foo,bar", "", None),
+        (b"q=nope&providers=testprovider", None, "", "testprovider", None),
+        (b"q=nope&seq=0", None, "", "", 0),
+    ],
+    ids=["query_sid", "query_client_variants", "query_providers", "query_seq"],
+)
+async def test_logging_suggest_log_data(
+    caplog: LogCaptureFixture,
+    filter_caplog: FilterCaplogFixture,
+    logging_middleware: LoggingMiddleware,
+    extract_send_wrapper: Callable[[LoggingMiddleware], Send],
+    scope: Scope,
+    receive_mock: Receive,
+    send_mock: Send,
+    query: bytes,
+    expected_sid: str | None,
+    expected_client_variants: str,
+    expected_providers: str,
+    expected_seq: int | None,
+) -> None:
+    caplog.set_level(logging.INFO)
+    location: Location = Location(
+        country="US", region="WA", city="Milton", dma=819, postal_code="98354"
+    )
+    user_agent: UserAgent = UserAgent(
+        browser="Firefox(103.0)", os_family="macos", form_factor="desktop"
+    )
+    expected_log_data: dict[str, Any] = {
+        "sensitive": True,
+        "path": "/api/v1/suggest",
+        "method": "GET",
+        "query": "nope",
+        "errno": 0,
+        "code": "200",
+        "time": "1998-03-31T00:00:00",
+        "rid": "1b11844c52b34c33a6ad54b7bc2eb7c7",
+        "session_id": expected_sid,
+        "sequence_no": expected_seq,
+        "country": location.country,
+        "region": location.region,
+        "city": location.city,
+        "dma": location.dma,
+        "client_variants": expected_client_variants,
+        "requested_providers": expected_providers,
+        "browser": user_agent.browser,
+        "os_family": user_agent.os_family,
+        "form_factor": user_agent.form_factor,
+    }
+    scope.update(
+        {
+            "headers": [],
+            "method": "GET",
+            "path": "/api/v1/suggest",
+            "query_string": query,
+            ScopeKey.GEOLOCATION: location,
+            ScopeKey.USER_AGENT: user_agent,
+        }
+    )
+    message: Message = {
+        "type": "http.response.start",
+        "status": "200",
+        "headers": [
+            (b"content-length", b"119"),
+            (b"content-type", b"application/json"),
+            (b"x-request-id", b"1b11844c52b34c33a6ad54b7bc2eb7c7"),
+            (b"access-control-expose-headers", b"X-Request-ID"),
+        ],
+    }
+
+    await logging_middleware(scope, receive_mock, send_mock)
+    send_wrapper: Send = extract_send_wrapper(logging_middleware)
+    await send_wrapper(message)
+
+    records: list[LogRecord] = filter_caplog(caplog.records, "web.suggest.request")
+    assert len(records) == 1
+    record: LogRecord = records[0]
+    log_data: dict[str, Any] = {
+        "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
+
+
+@pytest.mark.asyncio
+@pytest.mark.freeze_time("1998-03-31")
+async def test_logging_non_suggest_log_data(
+    caplog: LogCaptureFixture,
+    filter_caplog: FilterCaplogFixture,
+    logging_middleware: LoggingMiddleware,
+    extract_send_wrapper: Callable[[LoggingMiddleware], Send],
+    scope: Scope,
+    receive_mock: Receive,
+    send_mock: Send,
+) -> None:
+    caplog.set_level(logging.INFO)
+    expected_log_data: dict[str, Any] = {
+        "agent": "curl/7.84.0",
+        "path": "/__heartbeat__",
+        "method": "GET",
+        "lang": "en-US",
+        "querystring": {},
+        "errno": 0,
+        "code": "200",
+        "time": "1998-03-31T00:00:00",
+    }
+    scope.update(
+        {
+            "headers": [
+                (b"user-agent", b"curl/7.84.0"),
+                (b"accept-language", b"en-US"),
+            ],
+            "method": "GET",
+            "path": "/__heartbeat__",
+            "query_string": "",
+        }
+    )
+    message: Message = {"type": "http.response.start", "status": "200"}
+
+    await logging_middleware(scope, receive_mock, send_mock)
+    send_wrapper: Send = extract_send_wrapper(logging_middleware)
+    await send_wrapper(message)
+
+    records: list[LogRecord] = filter_caplog(caplog.records, "request.summary")
+    assert len(records) == 1
+    record: LogRecord = records[0]
+    log_data: dict[str, Any] = {
+        "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
+
+
+@pytest.mark.asyncio
+async def test_logging_invalid_scope_type(
+    caplog: LogCaptureFixture,
+    logging_middleware: LoggingMiddleware,
+    receive_mock: Receive,
+    send_mock: Send,
+) -> None:
+    """Test that no logging action takes place for an unexpected Scope type."""
+    caplog.set_level(logging.INFO)
+    scope: Scope = {"type": "not-http"}
+
+    await logging_middleware(scope, receive_mock, send_mock)
+
+    assert len(caplog.messages) == 0

tests/unit/middleware/test_user_agent.py

@@ -11,7 +11,7 @@
 from merino.middleware import ScopeKey
 from merino.middleware.user_agent import UserAgent, UserAgentMiddleware
 
-Scenario = tuple[str, str, str, str]
+Scenario = tuple[bytes, UserAgent]
 
 SCENARIOS: list[Scenario] = [
     (