animaltrack/tests/test_web_middleware.py

# ABOUTME: Tests for request ID generation and logging middleware.
# ABOUTME: Covers ULID generation, scope storage, and NDJSON log format.

import json
import os
import time
from unittest.mock import MagicMock


def make_test_settings(
    csrf_secret: str = "test-secret",
    trusted_proxy_ips: str = "",
    auth_header_name: str = "X-Oidc-Username",
):
    """Create Settings for testing by setting env vars temporarily."""
    from animaltrack.config import Settings

    old_env = os.environ.copy()
    try:
        os.environ["CSRF_SECRET"] = csrf_secret
        os.environ["TRUSTED_PROXY_IPS"] = trusted_proxy_ips
        os.environ["AUTH_HEADER_NAME"] = auth_header_name
        return Settings()
    finally:
        os.environ.clear()
        os.environ.update(old_env)


class TestRequestIdBefore:
    """Tests for request ID generation middleware."""

    def test_generates_request_id(self):
        """Generates a request_id in the scope."""
        from animaltrack.web.middleware import request_id_before

        req = MagicMock()
        req.scope = {}

        request_id_before(req)

        assert "request_id" in req.scope
        assert req.scope["request_id"] is not None

    def test_request_id_is_ulid(self):
        """Request ID is a valid 26-char ULID."""
        from animaltrack.web.middleware import request_id_before

        req = MagicMock()
        req.scope = {}

        request_id_before(req)

        request_id = req.scope["request_id"]
        assert len(request_id) == 26
        # ULIDs are base32, should only contain valid chars
        valid_chars = "0123456789ABCDEFGHJKMNPQRSTVWXYZ"
        assert all(c in valid_chars for c in request_id.upper())

    def test_generates_unique_ids(self):
        """Each request gets a unique request_id."""
        from animaltrack.web.middleware import request_id_before

        ids = set()
        for _ in range(100):
            req = MagicMock()
            req.scope = {}
            request_id_before(req)
            ids.add(req.scope["request_id"])

        assert len(ids) == 100  # All unique

    def test_sets_start_time(self):
        """Sets request_start_time in scope for duration calculation."""
        from animaltrack.web.middleware import request_id_before

        req = MagicMock()
        req.scope = {}

        before = time.time()
        request_id_before(req)
        after = time.time()

        assert "request_start_time" in req.scope
        assert before <= req.scope["request_start_time"] <= after


class TestLoggingAfter:
    """Tests for request logging middleware."""

    def test_logs_in_ndjson_format(self, capsys):
        """Log line is valid JSON."""
        from animaltrack.web.middleware import logging_after

        req = MagicMock()
        req.scope = {"request_id": "TEST123", "request_start_time": time.time()}
        req.url = MagicMock(path="/test")
        req.method = "GET"
        req.headers = {}
        req.client = MagicMock(host="127.0.0.1")

        resp = MagicMock()
        resp.status_code = 200

        settings = make_test_settings()

        logging_after(req, resp, settings)

        captured = capsys.readouterr()
        log_line = captured.out.strip()

        # Should be valid JSON
        parsed = json.loads(log_line)
        assert isinstance(parsed, dict)

    def test_log_includes_required_fields(self, capsys):
        """Log includes: ts, level, route, actor, ip, method, status, duration_ms."""
        from animaltrack.models.reference import User, UserRole
        from animaltrack.web.middleware import logging_after

        user = User(
            username="testuser",
            role=UserRole.RECORDER,
            active=True,
            created_at_utc=1000000,
            updated_at_utc=1000000,
        )

        req = MagicMock()
        req.scope = {
            "request_id": "TEST123",
            "request_start_time": time.time() - 0.1,  # 100ms ago
            "auth": user,
        }
        req.url = MagicMock(path="/test/route")
        req.method = "POST"
        req.headers = {}
        req.client = MagicMock(host="127.0.0.1")

        resp = MagicMock()
        resp.status_code = 201

        settings = make_test_settings()

        logging_after(req, resp, settings)

        captured = capsys.readouterr()
        parsed = json.loads(captured.out.strip())

        assert "ts" in parsed
        assert parsed["level"] == "info"
        assert parsed["route"] == "/test/route"
        assert parsed["actor"] == "testuser"
        assert parsed["method"] == "POST"
        assert parsed["status"] == 201
        assert "duration_ms" in parsed
        assert parsed["duration_ms"] >= 0

    def test_log_includes_request_id(self, capsys):
        """Log includes request_id field."""
        from animaltrack.web.middleware import logging_after

        req = MagicMock()
        req.scope = {"request_id": "01ARZ3NDEKTSV4RRFFQ69G5FAV", "request_start_time": time.time()}
        req.url = MagicMock(path="/test")
        req.method = "GET"
        req.headers = {}
        req.client = MagicMock(host="127.0.0.1")

        resp = MagicMock()
        resp.status_code = 200

        settings = make_test_settings()

        logging_after(req, resp, settings)

        captured = capsys.readouterr()
        parsed = json.loads(captured.out.strip())

        assert parsed["request_id"] == "01ARZ3NDEKTSV4RRFFQ69G5FAV"

    def test_log_includes_event_id_when_provided(self, capsys):
        """Log includes event_id field when provided."""
        from animaltrack.web.middleware import logging_after

        req = MagicMock()
        req.scope = {"request_id": "TEST123", "request_start_time": time.time()}
        req.url = MagicMock(path="/actions/product-collected")
        req.method = "POST"
        req.headers = {}
        req.client = MagicMock(host="127.0.0.1")

        resp = MagicMock()
        resp.status_code = 200

        settings = make_test_settings()

        logging_after(req, resp, settings, event_id="01ARZ3NDEKTSV4RRFFQ69G5EVT")

        captured = capsys.readouterr()
        parsed = json.loads(captured.out.strip())

        assert parsed["event_id"] == "01ARZ3NDEKTSV4RRFFQ69G5EVT"

    def test_duration_ms_accurate(self, capsys):
        """duration_ms reflects actual request time."""
        from animaltrack.web.middleware import logging_after

        req = MagicMock()
        # Started 150ms ago
        req.scope = {"request_id": "TEST123", "request_start_time": time.time() - 0.150}
        req.url = MagicMock(path="/test")
        req.method = "GET"
        req.headers = {}
        req.client = MagicMock(host="127.0.0.1")

        resp = MagicMock()
        resp.status_code = 200

        settings = make_test_settings()

        logging_after(req, resp, settings)

        captured = capsys.readouterr()
        parsed = json.loads(captured.out.strip())

        # Should be approximately 150ms (with some tolerance)
        assert 100 <= parsed["duration_ms"] <= 250

    def test_logs_x_forwarded_for_ip(self, capsys):
        """Log ip field uses X-Forwarded-For when present."""
        from animaltrack.web.middleware import logging_after

        req = MagicMock()
        req.scope = {"request_id": "TEST123", "request_start_time": time.time()}
        req.url = MagicMock(path="/test")
        req.method = "GET"
        req.headers = {"x-forwarded-for": "203.0.113.50, 10.0.0.1"}
        req.client = MagicMock(host="10.0.0.1")  # Proxy IP

        resp = MagicMock()
        resp.status_code = 200

        settings = make_test_settings()

        logging_after(req, resp, settings)

        captured = capsys.readouterr()
        parsed = json.loads(captured.out.strip())

        # Should use the client IP from X-Forwarded-For, not the proxy IP
        assert parsed["ip"] == "203.0.113.50"

    def test_actor_is_none_when_unauthenticated(self, capsys):
        """Log actor is None when no user in scope."""
        from animaltrack.web.middleware import logging_after

        req = MagicMock()
        req.scope = {"request_id": "TEST123", "request_start_time": time.time()}
        req.url = MagicMock(path="/healthz")
        req.method = "GET"
        req.headers = {}
        req.client = MagicMock(host="127.0.0.1")

        resp = MagicMock()
        resp.status_code = 200

        settings = make_test_settings()

        logging_after(req, resp, settings)

        captured = capsys.readouterr()
        parsed = json.loads(captured.out.strip())

        assert parsed["actor"] is None

    def test_timestamp_is_milliseconds(self, capsys):
        """Log ts field is milliseconds since epoch."""
        from animaltrack.web.middleware import logging_after

        req = MagicMock()
        req.scope = {"request_id": "TEST123", "request_start_time": time.time()}
        req.url = MagicMock(path="/test")
        req.method = "GET"
        req.headers = {}
        req.client = MagicMock(host="127.0.0.1")

        resp = MagicMock()
        resp.status_code = 200

        settings = make_test_settings()

        before_ms = int(time.time() * 1000)
        logging_after(req, resp, settings)
        after_ms = int(time.time() * 1000)

        captured = capsys.readouterr()
        parsed = json.loads(captured.out.strip())

        # ts should be between before and after (in milliseconds)
        assert before_ms <= parsed["ts"] <= after_ms
        # Should be a reasonable timestamp (year 2020+)
        assert parsed["ts"] > 1577836800000  # 2020-01-01