|
| 1 | +"""Unit tests for AuditLogMiddleware.""" |
| 2 | + |
| 3 | +from __future__ import annotations |
| 4 | + |
| 5 | +import logging |
| 6 | +import time |
| 7 | +from unittest.mock import patch |
| 8 | + |
| 9 | +import pytest |
| 10 | +from starlette.testclient import TestClient |
| 11 | +from fastapi import FastAPI |
| 12 | + |
| 13 | +from orb.api.middleware.audit_log_middleware import AuditLogMiddleware |
| 14 | + |
| 15 | + |
| 16 | +# --------------------------------------------------------------------------- |
| 17 | +# helpers |
| 18 | +# --------------------------------------------------------------------------- |
| 19 | + |
| 20 | +def _make_app_with_middleware(): |
| 21 | + """Return a minimal FastAPI app with AuditLogMiddleware attached.""" |
| 22 | + app = FastAPI() |
| 23 | + app.add_middleware(AuditLogMiddleware) |
| 24 | + |
| 25 | + @app.get("/api/v1/machines") |
| 26 | + async def machines(): |
| 27 | + return {"ok": True} |
| 28 | + |
| 29 | + @app.post("/api/v1/machines") |
| 30 | + async def create_machine(): |
| 31 | + return {"created": True} |
| 32 | + |
| 33 | + @app.get("/api/v1/config/settings") |
| 34 | + async def config_settings(): |
| 35 | + return {"cfg": True} |
| 36 | + |
| 37 | + @app.get("/api/v1/admin/status") |
| 38 | + async def admin_status(): |
| 39 | + return {"admin": True} |
| 40 | + |
| 41 | + @app.get("/api/v1/me") |
| 42 | + async def me(): |
| 43 | + return {"user": "self"} |
| 44 | + |
| 45 | + @app.get("/health") |
| 46 | + async def health(): |
| 47 | + return {"ok": True} |
| 48 | + |
| 49 | + @app.post("/api/v1/requests") |
| 50 | + async def create_request(): |
| 51 | + return {"req": True} |
| 52 | + |
| 53 | + return app |
| 54 | + |
| 55 | + |
| 56 | +# --------------------------------------------------------------------------- |
| 57 | +# dispatch matrix tests |
| 58 | +# --------------------------------------------------------------------------- |
| 59 | + |
| 60 | +@pytest.mark.unit |
| 61 | +class TestAuditLogMiddlewareDispatch: |
| 62 | + |
| 63 | + def test_get_non_audit_prefix_not_audited(self, caplog): |
| 64 | + """A plain GET not matching AUDIT_ALWAYS_PREFIXES is skipped.""" |
| 65 | + app = _make_app_with_middleware() |
| 66 | + client = TestClient(app, raise_server_exceptions=True) |
| 67 | + |
| 68 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 69 | + resp = client.get("/api/v1/machines") |
| 70 | + |
| 71 | + assert resp.status_code == 200 |
| 72 | + audit_records = [r for r in caplog.records if r.name == "orb.audit"] |
| 73 | + assert audit_records == [], "GET /api/v1/machines should not be audited" |
| 74 | + |
| 75 | + def test_get_config_prefix_is_audited(self, caplog): |
| 76 | + """GET /api/v1/config/... must be audited even though it's a safe verb.""" |
| 77 | + app = _make_app_with_middleware() |
| 78 | + client = TestClient(app) |
| 79 | + |
| 80 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 81 | + resp = client.get("/api/v1/config/settings") |
| 82 | + |
| 83 | + assert resp.status_code == 200 |
| 84 | + audit_records = [r for r in caplog.records if r.name == "orb.audit"] |
| 85 | + assert len(audit_records) == 1 |
| 86 | + |
| 87 | + def test_get_admin_prefix_is_audited(self, caplog): |
| 88 | + """GET /api/v1/admin/... must be audited.""" |
| 89 | + app = _make_app_with_middleware() |
| 90 | + client = TestClient(app) |
| 91 | + |
| 92 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 93 | + client.get("/api/v1/admin/status") |
| 94 | + |
| 95 | + audit_records = [r for r in caplog.records if r.name == "orb.audit"] |
| 96 | + assert len(audit_records) == 1 |
| 97 | + |
| 98 | + def test_get_me_prefix_is_audited(self, caplog): |
| 99 | + """GET /api/v1/me must be audited.""" |
| 100 | + app = _make_app_with_middleware() |
| 101 | + client = TestClient(app) |
| 102 | + |
| 103 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 104 | + client.get("/api/v1/me") |
| 105 | + |
| 106 | + audit_records = [r for r in caplog.records if r.name == "orb.audit"] |
| 107 | + assert len(audit_records) == 1 |
| 108 | + |
| 109 | + def test_non_get_mutating_request_is_audited(self, caplog): |
| 110 | + """POST /api/v1/requests must always be audited.""" |
| 111 | + app = _make_app_with_middleware() |
| 112 | + client = TestClient(app) |
| 113 | + |
| 114 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 115 | + client.post("/api/v1/requests") |
| 116 | + |
| 117 | + audit_records = [r for r in caplog.records if r.name == "orb.audit"] |
| 118 | + assert len(audit_records) == 1 |
| 119 | + |
| 120 | + def test_health_path_not_audited(self, caplog): |
| 121 | + """GET /health is in SAFE_PATHS and should never be audited.""" |
| 122 | + app = _make_app_with_middleware() |
| 123 | + client = TestClient(app) |
| 124 | + |
| 125 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 126 | + client.get("/health") |
| 127 | + |
| 128 | + audit_records = [r for r in caplog.records if r.name == "orb.audit"] |
| 129 | + assert audit_records == [] |
| 130 | + |
| 131 | + |
| 132 | +# --------------------------------------------------------------------------- |
| 133 | +# audit log fields |
| 134 | +# --------------------------------------------------------------------------- |
| 135 | + |
| 136 | +@pytest.mark.unit |
| 137 | +class TestAuditLogFields: |
| 138 | + |
| 139 | + def test_latency_ms_present_in_log(self, caplog): |
| 140 | + app = _make_app_with_middleware() |
| 141 | + client = TestClient(app) |
| 142 | + |
| 143 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 144 | + client.post("/api/v1/machines") |
| 145 | + |
| 146 | + records = [r for r in caplog.records if r.name == "orb.audit"] |
| 147 | + assert len(records) == 1 |
| 148 | + rec = records[0] |
| 149 | + latency = rec.__dict__.get("latency_ms") |
| 150 | + assert latency is not None |
| 151 | + assert isinstance(latency, float) |
| 152 | + assert latency >= 0 |
| 153 | + |
| 154 | + def test_client_ip_captured(self, caplog): |
| 155 | + app = _make_app_with_middleware() |
| 156 | + client = TestClient(app) |
| 157 | + |
| 158 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 159 | + client.post("/api/v1/machines") |
| 160 | + |
| 161 | + records = [r for r in caplog.records if r.name == "orb.audit"] |
| 162 | + assert records[0].__dict__.get("client_ip") is not None |
| 163 | + |
| 164 | + def test_user_id_defaults_to_anonymous(self, caplog): |
| 165 | + app = _make_app_with_middleware() |
| 166 | + client = TestClient(app) |
| 167 | + |
| 168 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 169 | + client.post("/api/v1/machines") |
| 170 | + |
| 171 | + records = [r for r in caplog.records if r.name == "orb.audit"] |
| 172 | + assert records[0].__dict__.get("user_id") == "anonymous" |
| 173 | + |
| 174 | + def test_status_code_recorded(self, caplog): |
| 175 | + app = _make_app_with_middleware() |
| 176 | + client = TestClient(app) |
| 177 | + |
| 178 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 179 | + client.post("/api/v1/machines") |
| 180 | + |
| 181 | + records = [r for r in caplog.records if r.name == "orb.audit"] |
| 182 | + assert records[0].__dict__.get("status_code") == 200 |
| 183 | + |
| 184 | + def test_method_and_path_recorded(self, caplog): |
| 185 | + app = _make_app_with_middleware() |
| 186 | + client = TestClient(app) |
| 187 | + |
| 188 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 189 | + client.post("/api/v1/requests") |
| 190 | + |
| 191 | + records = [r for r in caplog.records if r.name == "orb.audit"] |
| 192 | + rec = records[0] |
| 193 | + assert rec.__dict__.get("method") == "POST" |
| 194 | + assert rec.__dict__.get("path") == "/api/v1/requests" |
| 195 | + |
| 196 | + |
| 197 | +# --------------------------------------------------------------------------- |
| 198 | +# latency monotonic semantics |
| 199 | +# --------------------------------------------------------------------------- |
| 200 | + |
| 201 | +@pytest.mark.unit |
| 202 | +class TestAuditLogLatencySemantics: |
| 203 | + |
| 204 | + def test_latency_uses_monotonic_clock(self, caplog): |
| 205 | + """Latency must be measured with time.monotonic, not wall clock.""" |
| 206 | + app = _make_app_with_middleware() |
| 207 | + client = TestClient(app) |
| 208 | + |
| 209 | + call_times: list[float] = [] |
| 210 | + original_monotonic = time.monotonic |
| 211 | + |
| 212 | + def patched_monotonic(): |
| 213 | + t = original_monotonic() |
| 214 | + call_times.append(t) |
| 215 | + return t |
| 216 | + |
| 217 | + with caplog.at_level(logging.INFO, logger="orb.audit"): |
| 218 | + with patch("orb.api.middleware.audit_log_middleware.time.monotonic", patched_monotonic): |
| 219 | + client.post("/api/v1/machines") |
| 220 | + |
| 221 | + # monotonic must have been called at least twice (start + end) |
| 222 | + assert len(call_times) >= 2 |
0 commit comments