diff --git a/backend/core/metrics.py b/backend/core/metrics.py index 36b085b..7652bb5 100644 --- a/backend/core/metrics.py +++ b/backend/core/metrics.py @@ -96,6 +96,12 @@ def classify_inbound(path: str, base: str = "") -> str: the app's mount prefix (e.g. ``/thermograph`` or ``""``). """ p = path or "/" + # The liveness probe (Dockerfile HEALTHCHECK, Caddy health_uri) is by far the + # highest-volume single path in prod (measured ~47% of the access log) and is + # never real traffic — same posture as the metrics check below. Never under + # BASE (see /healthz's own docstring in web/app.py), so check before stripping. + if p.rstrip("/") == "/healthz": + return "health" # The dashboard polls the metrics endpoint; never count it as traffic, whatever base # prefix it arrives under — e.g. a `/thermograph/api/v2/metrics` probe against a # root-served prod app would otherwise land in "other" and show as an inbound error. @@ -118,6 +124,13 @@ def classify_inbound(path: str, base: str = "") -> str: # category keeps record_inbound from double-counting every interaction. if seg == "event": return "event" + # The SSR content API (backend/api/content_routes.py) is called only by + # the frontend_ssr service's own api_client.py, never by a browser — a + # server-to-server hop, not a page view. Its own category is what lets + # that (measured ~32% of the access log on prod) be excluded from the + # access log below without also hiding real external traffic. + if seg == "content": + return "internal" return f"api:{seg}" if seg else "api:other" if p.endswith((".js", ".css", ".html", ".webmanifest", ".png", ".svg", ".ico", ".json", ".woff", ".woff2", ".map", ".txt", ".xml")): diff --git a/backend/deploy/entrypoint.sh b/backend/deploy/entrypoint.sh index 9b6f399..9baf4b3 100755 --- a/backend/deploy/entrypoint.sh +++ b/backend/deploy/entrypoint.sh @@ -85,4 +85,7 @@ if [ "${RUN_MIGRATIONS:-1}" != "0" ]; then fi echo "==> Starting uvicorn on 0.0.0.0:${PORT:-8137} with ${WORKERS:-4} worker(s)" -exec uvicorn app:app --host 0.0.0.0 --port "${PORT:-8137}" --workers "${WORKERS:-4}" +# --no-access-log: the app's own request-logging middleware (audit.log_access, +# web/app.py) already writes a structured line per request; uvicorn's own access +# log just duplicated every one of them for no benefit. +exec uvicorn app:app --host 0.0.0.0 --port "${PORT:-8137}" --workers "${WORKERS:-4}" --no-access-log diff --git a/backend/tests/core/test_metrics.py b/backend/tests/core/test_metrics.py index 010f246..d58ad47 100644 --- a/backend/tests/core/test_metrics.py +++ b/backend/tests/core/test_metrics.py @@ -40,6 +40,16 @@ def test_classify_inbound_categories(): # dashboard probing /thermograph/... against a root-served (base="") prod app. assert c("/thermograph/api/v2/metrics", "") == "metrics" assert c("/api/v2/metrics", "") == "metrics" + # The SSR content API (backend/api/content_routes.py) is a server-to-server + # hop from frontend_ssr's own api_client.py, never a browser -- its own + # category is what lets it be excluded from the access log without also + # hiding real external traffic under the generic "api:*" bucket. + assert c("/thermograph/api/v2/content/hub", "/thermograph") == "internal" + assert c("/api/v2/content/city/tokyo", "") == "internal" + # The liveness probe: never under BASE, whatever base the app happens to be + # mounted at (it's registered at a fixed path -- see web/app.py's healthz). + assert c("/healthz") == "health" + assert c("/healthz", "/thermograph") == "health" # pages, static, seo assert c("/thermograph/", "/thermograph") == "page" assert c("/thermograph/calendar", "/thermograph") == "page" diff --git a/backend/tests/web/test_request_logging.py b/backend/tests/web/test_request_logging.py new file mode 100644 index 0000000..b14882b --- /dev/null +++ b/backend/tests/web/test_request_logging.py @@ -0,0 +1,87 @@ +"""The request-logging middleware (web/app.py's revalidate_static): what gets +counted, what gets written to the access log, and what gets truncated before +it's persisted. Companion to core/test_metrics.py's classify_inbound tests -- +these exercise the actual ASGI request path, not just the classifier function. +""" +import pytest +from fastapi.testclient import TestClient + +from web import app as appmod + +metrics = appmod.metrics # the exact module object app.py's own calls use -- +audit = appmod.audit # see the note on module-reload isolation below. + + +@pytest.fixture +def client(): + return TestClient(appmod.app) + + +def _patch_log_access(monkeypatch): + calls = [] + monkeypatch.setattr(audit, "log_access", lambda record: calls.append(record)) + return calls + + +def test_healthz_is_never_audited(monkeypatch, client): + """/healthz is ~47% of prod's daily access log; it must never even reach + audit.log_access (not just be cheap once there -- see classify_inbound's + "health" category and the exclusion in revalidate_static).""" + calls = _patch_log_access(monkeypatch) + r = client.get("/healthz") + assert r.status_code == 200 + assert calls == [] + + +def test_internal_category_is_never_audited(monkeypatch, client): + """The SSR content API's own category ("internal") is excluded from the + access log the same way -- it's a server-to-server hop (frontend_ssr's + api_client.py calling backend), not a page view.""" + calls = _patch_log_access(monkeypatch) + monkeypatch.setattr(metrics, "classify_inbound", lambda path, base: "internal") + r = client.get("/thermograph/api/version") + assert r.status_code == 200 + assert calls == [] + + +def test_access_log_ip_is_truncated_not_raw(monkeypatch, client): + calls = _patch_log_access(monkeypatch) + r = client.get("/thermograph/api/version", + headers={"X-Forwarded-For": "203.0.113.77, 10.0.0.1"}) + assert r.status_code == 200 + assert len(calls) == 1 + assert calls[0]["ip"] == "203.0.113.0" # /24, not the exact address + assert calls[0]["ip"] != "203.0.113.77" + + +def test_loggable_ip_truncation(): + assert appmod._loggable_ip("203.0.113.77") == "203.0.113.0" + assert appmod._loggable_ip("2001:db8:1234:5678::1") == "2001:db8:1234::" + assert appmod._loggable_ip(None) is None + assert appmod._loggable_ip("") == "" + assert appmod._loggable_ip("not-an-ip") == "not-an-ip" # best-effort, never raises + + +def test_rate_limiter_still_sees_the_full_precision_ip(monkeypatch, client): + """_client_ip (which feeds both the access log and the event rate limiter) + is never itself truncated -- only what audit.log_access persists is. A + /24-truncated rate-limit key would let one abuser exhaust a whole NAT'd + office's quota, which is exactly what must NOT happen here.""" + seen = {} + monkeypatch.setattr(metrics, "record_event", lambda name, **kw: seen.update(kw)) + r = client.post("/thermograph/api/v2/event", json={"event": "home.locate"}, + headers={"X-Forwarded-For": "203.0.113.77"}) + assert r.status_code == 204 + assert seen["ip"] == "203.0.113.77" + + +def test_event_route_records_end_to_end(client): + """Full HTTP round trip through the real ASGI route -- confirms the write + path backend/api/event -> metrics.record_event -> the counters store works + end to end (the existing suite only ever called record_event directly).""" + before = metrics.snapshot()["events_total"] + r = client.post("/thermograph/api/v2/event", json={"event": "home.locate"}) + assert r.status_code == 204 + after = metrics.snapshot() + assert after["events_total"] == before + 1 + assert after["events"]["home.locate"]["direct"] # no Referer sent -> "direct" diff --git a/backend/web/app.py b/backend/web/app.py index 0253319..b8a5d35 100644 --- a/backend/web/app.py +++ b/backend/web/app.py @@ -3,6 +3,7 @@ import contextlib import datetime import hashlib import hmac +import ipaddress import json import os import queue @@ -263,13 +264,34 @@ def api_version(): def _client_ip(request) -> "str | None": """The real client IP: the left-most X-Forwarded-For hop when a proxy fronts us - (Caddy on prod sets it), otherwise the direct peer address (LAN dev).""" + (Caddy on prod sets it), otherwise the direct peer address (LAN dev). Full + precision — the rate limiter (metrics._rate_ok) needs the exact address, since + a truncated key would let one abuser exhaust a whole NAT'd office's quota. + Truncate at the point of persistence instead (see _loggable_ip).""" xff = request.headers.get("x-forwarded-for") if xff: return xff.split(",")[0].strip() return request.client.host if request.client else None +def _loggable_ip(ip: "str | None") -> "str | None": + """Coarsen a client IP before it's written to the access log: /24 for IPv4, + /48 for IPv6. Keeps rough geo/abuse signal without keeping a full, joinable + address sitting in structured logs for the log's 30-day retention -- the + public privacy page promises IPs aren't logged beyond normal request handling, + and a raw address shipped to Loki was a live gap against that. Never the + input to the rate limiter (_client_ip's callers pass the untruncated value + there) -- this is only what gets persisted.""" + if not ip: + return ip + try: + addr = ipaddress.ip_address(ip) + except ValueError: + return ip # not a parseable address (e.g. a test/placeholder value) -- pass through + prefix = 24 if addr.version == 4 else 48 + return str(ipaddress.ip_network(f"{addr}/{prefix}", strict=False).network_address) + + @app.middleware("http") async def revalidate_static(request, call_next): """Serve the frontend with no-cache (NOT no-store): browsers may keep a copy @@ -288,11 +310,15 @@ async def revalidate_static(request, call_next): # loop so one request's instrumentation can't stall every other request # this worker is serving concurrently. await run_in_threadpool(metrics.record_inbound, cat, response.status_code) - # Retain per-request client IPs for later analysis; skip static assets and the - # dashboard's own metrics polling to keep the log to real, meaningful traffic. - if cat not in ("static", "metrics", "event"): + # Retain per-request client IPs for later analysis; skip static assets, the + # dashboard's own metrics polling, the liveness probe (health -- by far the + # highest-volume single path, and never real traffic), and the internal + # SSR->API hop (internal -- frontend_ssr's own server-to-server calls, not + # a page view) to keep the log to real, meaningful traffic. The IP itself is + # truncated (see _loggable_ip) -- coarse geo/abuse signal, not a full address. + if cat not in ("static", "metrics", "event", "health", "internal"): await run_in_threadpool(audit.log_access, { - "ip": _client_ip(request), "method": request.method, + "ip": _loggable_ip(_client_ip(request)), "method": request.method, "path": path, "status": response.status_code, "cat": cat}) # Threshold-gated slow-request line: RunAudit only times the 7 graded # endpoints, so this is the only latency signal for auth/account/content