Stop logging /healthz and the internal SSR->API hop, truncate logged IPs
All checks were successful
PR build (required check) / changes (pull_request) Successful in 7s
secrets-guard / encrypted (pull_request) Successful in 6s
PR build (required check) / build-frontend (pull_request) Has been skipped
shell-lint / shellcheck (pull_request) Successful in 7s
PR build (required check) / validate-observability (pull_request) Has been skipped
PR build (required check) / build-backend (pull_request) Successful in 58s
PR build (required check) / gate (pull_request) Successful in 2s
All checks were successful
PR build (required check) / changes (pull_request) Successful in 7s
secrets-guard / encrypted (pull_request) Successful in 6s
PR build (required check) / build-frontend (pull_request) Has been skipped
shell-lint / shellcheck (pull_request) Successful in 7s
PR build (required check) / validate-observability (pull_request) Has been skipped
PR build (required check) / build-backend (pull_request) Successful in 58s
PR build (required check) / gate (pull_request) Successful in 2s
/healthz accounted for ~47% of prod's daily access log and the internal frontend_ssr->backend content-API hop for another ~32%, each costing a threadpool dispatch + lock + file write on the request path for traffic that isn't meaningful to retain. classify_inbound gains "health" and "internal" categories for these, both excluded from audit.log_access (alongside the existing static/metrics/event exclusions) so they're never dispatched to the logging threadpool at all. The access log's client IP is now truncated to /24 (IPv4) or /48 (IPv6) before being persisted -- coarse geo/abuse signal without keeping a full, joinable address in Loki for the 30-day retention window, matching the privacy page's claim that IPs aren't logged beyond normal request handling. The rate limiter keyed off the same IP (_rate_ok) is untouched and still sees full precision. uvicorn's own --no-access-log now suppresses its duplicate per-request line, since the app's own middleware already writes one.
This commit is contained in:
parent
eaaa4f1ad9
commit
7bc0358278
5 changed files with 145 additions and 6 deletions
|
|
@ -96,6 +96,12 @@ def classify_inbound(path: str, base: str = "") -> str:
|
||||||
the app's mount prefix (e.g. ``/thermograph`` or ``""``).
|
the app's mount prefix (e.g. ``/thermograph`` or ``""``).
|
||||||
"""
|
"""
|
||||||
p = path 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
|
# 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
|
# 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.
|
# 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.
|
# category keeps record_inbound from double-counting every interaction.
|
||||||
if seg == "event":
|
if seg == "event":
|
||||||
return "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"
|
return f"api:{seg}" if seg else "api:other"
|
||||||
if p.endswith((".js", ".css", ".html", ".webmanifest", ".png", ".svg", ".ico",
|
if p.endswith((".js", ".css", ".html", ".webmanifest", ".png", ".svg", ".ico",
|
||||||
".json", ".woff", ".woff2", ".map", ".txt", ".xml")):
|
".json", ".woff", ".woff2", ".map", ".txt", ".xml")):
|
||||||
|
|
|
||||||
|
|
@ -85,4 +85,7 @@ if [ "${RUN_MIGRATIONS:-1}" != "0" ]; then
|
||||||
fi
|
fi
|
||||||
|
|
||||||
echo "==> Starting uvicorn on 0.0.0.0:${PORT:-8137} with ${WORKERS:-4} worker(s)"
|
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
|
||||||
|
|
|
||||||
|
|
@ -40,6 +40,16 @@ def test_classify_inbound_categories():
|
||||||
# dashboard probing /thermograph/... against a root-served (base="") prod app.
|
# dashboard probing /thermograph/... against a root-served (base="") prod app.
|
||||||
assert c("/thermograph/api/v2/metrics", "") == "metrics"
|
assert c("/thermograph/api/v2/metrics", "") == "metrics"
|
||||||
assert c("/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
|
# pages, static, seo
|
||||||
assert c("/thermograph/", "/thermograph") == "page"
|
assert c("/thermograph/", "/thermograph") == "page"
|
||||||
assert c("/thermograph/calendar", "/thermograph") == "page"
|
assert c("/thermograph/calendar", "/thermograph") == "page"
|
||||||
|
|
|
||||||
87
backend/tests/web/test_request_logging.py
Normal file
87
backend/tests/web/test_request_logging.py
Normal file
|
|
@ -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"
|
||||||
|
|
@ -3,6 +3,7 @@ import contextlib
|
||||||
import datetime
|
import datetime
|
||||||
import hashlib
|
import hashlib
|
||||||
import hmac
|
import hmac
|
||||||
|
import ipaddress
|
||||||
import json
|
import json
|
||||||
import os
|
import os
|
||||||
import queue
|
import queue
|
||||||
|
|
@ -263,13 +264,34 @@ def api_version():
|
||||||
|
|
||||||
def _client_ip(request) -> "str | None":
|
def _client_ip(request) -> "str | None":
|
||||||
"""The real client IP: the left-most X-Forwarded-For hop when a proxy fronts us
|
"""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")
|
xff = request.headers.get("x-forwarded-for")
|
||||||
if xff:
|
if xff:
|
||||||
return xff.split(",")[0].strip()
|
return xff.split(",")[0].strip()
|
||||||
return request.client.host if request.client else None
|
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")
|
@app.middleware("http")
|
||||||
async def revalidate_static(request, call_next):
|
async def revalidate_static(request, call_next):
|
||||||
"""Serve the frontend with no-cache (NOT no-store): browsers may keep a copy
|
"""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
|
# loop so one request's instrumentation can't stall every other request
|
||||||
# this worker is serving concurrently.
|
# this worker is serving concurrently.
|
||||||
await run_in_threadpool(metrics.record_inbound, cat, response.status_code)
|
await run_in_threadpool(metrics.record_inbound, cat, response.status_code)
|
||||||
# Retain per-request client IPs for later analysis; skip static assets and the
|
# Retain per-request client IPs for later analysis; skip static assets, the
|
||||||
# dashboard's own metrics polling to keep the log to real, meaningful traffic.
|
# dashboard's own metrics polling, the liveness probe (health -- by far the
|
||||||
if cat not in ("static", "metrics", "event"):
|
# 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, {
|
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})
|
"path": path, "status": response.status_code, "cat": cat})
|
||||||
# Threshold-gated slow-request line: RunAudit only times the 7 graded
|
# Threshold-gated slow-request line: RunAudit only times the 7 graded
|
||||||
# endpoints, so this is the only latency signal for auth/account/content
|
# endpoints, so this is the only latency signal for auth/account/content
|
||||||
|
|
|
||||||
Loading…
Reference in a new issue