From 6d6e76d13d37ffe635d63c6a4c5321114af34133 Mon Sep 17 00:00:00 2001 From: pavsoss Date: Tue, 28 Jul 2026 18:46:49 -0400 Subject: [PATCH] feat(ml-api): redact secrets/PII from logs and route errors through it --- README.md | 61 +++++++++ backend/api.py | 78 +++++++++-- backend/logging_config.py | 241 ++++++++++++++++++++++++++++++++++ backend/tests/test_logging.py | 136 +++++++++++++++++++ 4 files changed, 504 insertions(+), 12 deletions(-) create mode 100644 backend/logging_config.py create mode 100644 backend/tests/test_logging.py diff --git a/README.md b/README.md index f543aec..18cbca7 100644 --- a/README.md +++ b/README.md @@ -449,6 +449,67 @@ modified. Codes are defined in `backend/errors.py`. --- +## 🪵 Logging + +The Flask ML API emits **structured JSON logs** (issue #1006). Logging is +configured once at startup by `configure_logging()` in +`backend/logging_config.py`, which installs a JSON formatter on the root logger +so every line — including records from `app.logger` — is a single +self-describing object rather than free-form text. + +Each line carries a fixed core schema plus any structured fields passed at the +call site: + +```json +{ + "ts": "2026-07-29T09:41:03.512+00:00", + "level": "INFO", + "logger": "ml_api.access", + "msg": "request", + "request_id": "8f2c1e5b7a9d4c3e", + "method": "POST", + "path": "/predict", + "status": 200, + "latency_ms": 42.7, + "response_size": 1834 +} +``` + +* `request_id` — correlation id for the request. It is taken from the + `X-Request-ID` header when present; otherwise a fresh `uuid4` hex is minted in + `capture_request_id()` so every request is traceable (no more static + `unknown-ml-req`). A `RequestIdFilter` injects it onto every record and is + safe outside a request context (falls back to `-`). +* **Access log** — one line per request (`logger` = `ml_api.access`, `msg` = + `request`) with `method`, `path`, `status`, `latency_ms`, `request_id`, and + `response_size`. Latency is measured from a start time stamped in the first + `before_request` hook, so it covers requests short-circuited (e.g. a `403`) + before later hooks run. +* Use `get_logger(name)` to obtain a module logger; records flow through the + configured root. `configure_logging()` is idempotent, so a reimport or a test + that loads the app twice never double-emits. + +### Redaction + +Before a record is formatted it passes through a `RedactionFilter` that scrubs +sensitive material to `***`, so a token or address accidentally handed to a log +call never reaches the sink in the clear. It covers: + +* the `X-Internal-Secret` value, +* OAuth **access / refresh tokens** and HTTP `Bearer` tokens, +* threat-intel **API keys** (`SAFE_BROWSING_API_KEY`, `VIRUSTOTAL_API_KEY`), +* **email addresses** and message bodies. + +Both the rendered message and string-valued structured fields are cleaned. +Exact secret values present in the environment at startup are additionally +scrubbed literally, catching a bare value logged without a recognisable key. + +Contract coverage lives in `backend/tests/test_logging.py`: every emitted record +is valid JSON with a `request_id`, the id propagates from the header, and a +known secret / token / email never survives to the output. + +--- + ## 📊 Metrics & Monitoring The Flask ML API exposes a Prometheus-compatible `GET /metrics` endpoint (powered diff --git a/backend/api.py b/backend/api.py index 7cca6f0..2af303b 100644 --- a/backend/api.py +++ b/backend/api.py @@ -74,6 +74,13 @@ app = Flask(__name__) +# Install the JSON log formatter + request-id/redaction filters on the root +# logger before anything logs, so every line (including app.logger records that +# propagate here) is structured and scrubbed from the first request (#1006). +configure_logging() +logger = get_logger("ml_api") +access_logger = get_logger("ml_api.access") + xai_engine = ExplanationEngine() CORS(app, resources={r"/*": {"origins": "http://localhost:5173"}}) @@ -134,8 +141,9 @@ def decorated_function(*args, **kwargs): # Check internal secret provided = request.headers.get("X-Internal-Secret", "") if not provided or not hmac.compare_digest(provided, INTERNAL_SECRET): - app.logger.warning( - f"⚠️ Unauthorized internal request from {request.remote_addr}" + logger.warning( + "unauthorized_internal_request", + extra={"remote_addr": request.remote_addr, "path": request.path}, ) return error_response( ErrorCode.FORBIDDEN, @@ -145,9 +153,9 @@ def decorated_function(*args, **kwargs): extra={"success": False}, ) - # Log internal request - app.logger.info( - f"🔐 [ZERO-TRUST] Internal request to {request.path} from {request.remote_addr}" + logger.info( + "internal_request", + extra={"remote_addr": request.remote_addr, "path": request.path}, ) return f(*args, **kwargs) @@ -204,7 +212,7 @@ def decorated_function(*args, **kwargs): client_ip = client_ip.split(",")[0].strip() if client_ip not in allowed_list: - app.logger.warning(f"⚠️ Blocked request from unauthorized IP: {client_ip}") + logger.warning("blocked_unauthorized_ip", extra={"client_ip": client_ip}) return ( jsonify( {"success": False, "error": "Access denied from this IP address"} @@ -236,8 +244,9 @@ def decorated_function(*args, **kwargs): p in value.lower() for p in [">> logger = get_logger("ml_api") +>>> isinstance(logger, logging.Logger) +True +""" + +from datetime import datetime, timezone +import json +import logging +import os +import re +import sys + +__all__ = [ + "configure_logging", + "get_logger", + "JsonLogFormatter", + "RequestIdFilter", + "RedactionFilter", + "REDACTED", +] + +# Value substituted for any scrubbed secret / personal datum. +REDACTED = "***" + +# Placeholder emitted when no request context is active (startup, background +# scheduler jobs) so ``request_id`` is always present in the schema. +_NO_REQUEST_ID = "-" + +# LogRecord attributes that belong to the logging machinery rather than to +# caller-supplied context. Anything else found on a record is treated as a +# structured extra and emitted alongside the core fields. Derived from a probe +# record so it tracks the running interpreter's LogRecord shape. +_STANDARD_ATTRS = frozenset( + vars(logging.LogRecord("", 0, "", 0, "", None, None)).keys() +) | {"message", "asctime", "taskName"} + + +class JsonLogFormatter(logging.Formatter): + """Render a log record as a single-line JSON object. + + Core fields are always present; ``extra=`` keyword fields passed at the + call site are merged in at the top level, and an exception traceback (when + present) is attached under ``exc_info``. + + >>> record = logging.LogRecord("ml_api", logging.INFO, __file__, 1, + ... "hello", None, None) + >>> data = json.loads(JsonLogFormatter().format(record)) + >>> data["level"], data["logger"], data["msg"] + ('INFO', 'ml_api', 'hello') + """ + + def format(self, record): + payload = { + "ts": self.formatTime(record), + "level": record.levelname, + "logger": record.name, + "msg": record.getMessage(), + "request_id": getattr(record, "request_id", _NO_REQUEST_ID), + } + extras = { + key: value + for key, value in record.__dict__.items() + if key not in _STANDARD_ATTRS and key != "request_id" + } + payload.update(extras) + if record.exc_info: + payload["exc_info"] = self.formatException(record.exc_info) + # default=str keeps a stray non-serialisable extra from crashing the + # log call; ensure_ascii=False keeps unicode readable in the sink. + return json.dumps(payload, default=str, ensure_ascii=False) + + def formatTime(self, record, datefmt=None): + # ISO 8601 in UTC so lines from different hosts/timezones sort and + # correlate directly, regardless of the process's local timezone. + return datetime.fromtimestamp(record.created, tz=timezone.utc).isoformat() + + +class RequestIdFilter(logging.Filter): + """Inject the active request's ``g.request_id`` onto every record. + + Kept as a filter (not a formatter concern) so the id is available to every + handler and so the lookup stays safe when there is no Flask application or + request context, e.g. at import time or inside the background scheduler. + """ + + def filter(self, record): + if not hasattr(record, "request_id"): + record.request_id = _current_request_id() + return True + + +class RedactionFilter(logging.Filter): + """Scrub secrets and personal data from a record before it is emitted. + + Targets the material the ML API handles: the ``X-Internal-Secret``, OAuth + access/refresh tokens, threat-intel API keys (Safe Browsing / VirusTotal), + and email addresses / message bodies. Both the rendered message and any + string-valued structured extras are cleaned. Exact secret values known at + configuration time (passed via ``extra_secrets``) are additionally scrubbed + literally, catching a bare value logged without a recognisable key. + + >>> f = RedactionFilter(extra_secrets=["topsecretvalue"]) + >>> rec = logging.LogRecord("x", logging.INFO, __file__, 1, + ... "mail a@b.com token access_token=xyz secret=topsecretvalue", None, None) + >>> _ = f.filter(rec) + >>> "a@b.com" in rec.msg or "xyz" in rec.msg or "topsecretvalue" in rec.msg + False + """ + + # Ordered (pattern, replacement) rules. Each keeps any leading key/label so + # the line stays legible while the sensitive value collapses to ``***``. + _RULES = ( + # key: value / key="value" for sensitive keys (tokens, secrets, keys). + # Group 1 = key, group 2 = separator + optional quote, group 3 = value. + ( + re.compile( + r"(?i)" + r"(x[-_]internal[-_]secret" + r"|access[-_]?token|refresh[-_]?token" + r"|(?:safe[_-]?browsing|virustotal)[_-]?api[_-]?key" + r"|api[_-]?key|secret|password|token)" + r'(["\']?\s*[:=]\s*["\']?)' + r"([^\s\"',}&]+)" + ), + r"\1\2" + REDACTED, + ), + # HTTP Authorization bearer tokens. + (re.compile(r"(?i)(bearer\s+)([A-Za-z0-9._\-]+)"), r"\1" + REDACTED), + # Email addresses (personal data / message sender-recipient). + ( + re.compile(r"[A-Za-z0-9._%+\-]+@[A-Za-z0-9.\-]+\.[A-Za-z]{2,}"), + REDACTED, + ), + ) + + def __init__(self, extra_secrets=None): + super().__init__() + # Only non-empty literals; an empty/unset secret must not turn into a + # rule that replaces the empty string everywhere. + self._literals = tuple(s for s in (extra_secrets or []) if s) + + def filter(self, record): + record.msg = self._redact(record.getMessage()) + record.args = () + for key, value in list(record.__dict__.items()): + if key in _STANDARD_ATTRS or key == "request_id": + continue + if isinstance(value, str): + record.__dict__[key] = self._redact(value) + return True + + def _redact(self, text): + for literal in self._literals: + if literal in text: + text = text.replace(literal, REDACTED) + for pattern, replacement in self._RULES: + text = pattern.sub(replacement, text) + return text + + +def configure_logging(level=logging.INFO, *, stream=None, extra_secrets=None): + """Install the JSON formatter + request-id/redaction filters on the root. + + Idempotent: repeated calls (e.g. a reimport, or a test that imports the app + twice) are no-ops after the first, so log lines are never duplicated. + + ``extra_secrets`` defaults to the sensitive values present in the + environment (internal secret, Safe Browsing / VirusTotal keys) so their + exact values are scrubbed even when logged without a recognisable key. + """ + global _CONFIGURED + if _CONFIGURED: + return logging.getLogger() + + if extra_secrets is None: + extra_secrets = [ + os.environ.get("INTERNAL_SECRET"), + os.environ.get("SAFE_BROWSING_API_KEY"), + os.environ.get("VIRUSTOTAL_API_KEY"), + ] + + handler = logging.StreamHandler(stream or sys.stdout) + handler.setFormatter(JsonLogFormatter()) + handler.addFilter(RequestIdFilter()) + handler.addFilter(RedactionFilter(extra_secrets=extra_secrets)) + + root = logging.getLogger() + # Replace any default/basicConfig handlers so lines aren't emitted twice + # and every line goes through the JSON formatter. + root.handlers.clear() + root.addHandler(handler) + root.setLevel(level) + + _CONFIGURED = True + return root + + +def get_logger(name): + """Return a module logger; records flow through the configured root.""" + return logging.getLogger(name) + + +# Set once by configure_logging(); guards against double-configuration. +_CONFIGURED = False + + +def _current_request_id(): + # Import lazily and guard on has_request_context so this is safe to call + # from records emitted outside any Flask context. + try: + from flask import g, has_request_context + except Exception: + return _NO_REQUEST_ID + if not has_request_context(): + return _NO_REQUEST_ID + return getattr(g, "request_id", _NO_REQUEST_ID) diff --git a/backend/tests/test_logging.py b/backend/tests/test_logging.py new file mode 100644 index 0000000..a997b51 --- /dev/null +++ b/backend/tests/test_logging.py @@ -0,0 +1,136 @@ +"""Structured JSON logging + redaction contract for the ML API (issue #1006). + +Part 1 guarantees every emitted line is a JSON object carrying a ``request_id`` +that propagates from the ``X-Request-ID`` header. Part 2 guarantees secrets and +personal data (internal secret, OAuth tokens, API keys, emails / message +bodies) never reach the sink in the clear. + +The module-level unit tests exercise ``logging_config`` directly and do not +import the Flask app, so they run even where an optional app dependency is +missing. The propagation test drives the app's access log through a real +request. +""" + +import io +import json +import logging +import os +from pathlib import Path +import sys + +import pytest + +BASE_DIR = Path(__file__).resolve().parents[2] +BACKEND_DIR = BASE_DIR / "backend" + +sys.path.insert(0, str(BACKEND_DIR)) + +from logging_config import (JsonLogFormatter, REDACTED, + RedactionFilter, RequestIdFilter) + +KNOWN_SECRET = "super-secret-internal-value-do-not-log-1234567890" +KNOWN_TOKEN = "ya29.a0AfB_byC_fake_oauth_access_token_value" +KNOWN_EMAIL = "victim.user@example.com" + + +def _emit(record, *, redact_secrets=None): + """Run a record through the production filters + formatter, return JSON.""" + RequestIdFilter().filter(record) + if redact_secrets is not None: + RedactionFilter(extra_secrets=redact_secrets).filter(record) + return json.loads(JsonLogFormatter().format(record)) + + +def _record(msg, **extra): + record = logging.LogRecord("ml_api", logging.INFO, __file__, 1, msg, None, None) + for key, value in extra.items(): + setattr(record, key, value) + return record + + +def test_formatter_emits_valid_json_with_core_fields(): + data = _emit(_record("hello")) + assert data["msg"] == "hello" + assert data["level"] == "INFO" + assert data["logger"] == "ml_api" + # Outside a request context the id falls back to a stable placeholder. + assert data["request_id"] == "-" + + +def test_structured_extras_are_top_level_fields(): + data = _emit(_record("request", method="GET", path="/health", status=200)) + assert data["method"] == "GET" + assert data["path"] == "/health" + assert data["status"] == 200 + + +def test_redaction_scrubs_secret_token_and_email(): + msg = ( + f"connect user={KNOWN_EMAIL} " + f"access_token={KNOWN_TOKEN} " + f"X-Internal-Secret: {KNOWN_SECRET}" + ) + raw = json.dumps(_emit(_record(msg), redact_secrets=[KNOWN_SECRET])) + assert KNOWN_SECRET not in raw + assert KNOWN_TOKEN not in raw + assert KNOWN_EMAIL not in raw + assert REDACTED in raw + + +def test_redaction_scrubs_string_extras(): + data = _emit( + _record("oauth", email=KNOWN_EMAIL, refresh_token=KNOWN_TOKEN), + redact_secrets=[], + ) + assert data["email"] == REDACTED + assert KNOWN_TOKEN not in json.dumps(data) + + +def test_redaction_scrubs_bare_literal_secret_without_a_key(): + # A secret logged with no recognisable key still goes via the literal list. + data = _emit(_record(f"boot with {KNOWN_SECRET}"), redact_secrets=[KNOWN_SECRET]) + assert KNOWN_SECRET not in json.dumps(data) + + +class TestAccessLogPropagation: + """Drive the app so the access log stamps the header-supplied request id.""" + + @pytest.fixture(scope="class") + def api_module(self): + os.environ.setdefault("MODEL_PATH", str(BASE_DIR / "linear_svm_model.pkl")) + os.environ.setdefault( + "VECTORIZER_PATH", str(BACKEND_DIR / "tfidf_vectorizer.pkl") + ) + os.environ.setdefault("LABEL_ENCODER_PATH", str(BASE_DIR / "label_encoder.pkl")) + os.environ.setdefault("URL_MODEL_PATH", str(BACKEND_DIR / "url_detector.pkl")) + os.environ.setdefault( + "URL_VECTORIZER_PATH", str(BACKEND_DIR / "url_vectorizer.pkl") + ) + import api as api_module + + return api_module + + @pytest.fixture + def client(self, api_module): + api_module.app.config["TESTING"] = True + with api_module.app.test_client() as c: + yield c + + def test_request_id_propagates_from_header(self, client): + stream = io.StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(JsonLogFormatter()) + handler.addFilter(RequestIdFilter()) + access_logger = logging.getLogger("ml_api.access") + access_logger.addHandler(handler) + try: + client.get("/health", headers={"X-Request-ID": "known-req-42"}) + finally: + access_logger.removeHandler(handler) + + lines = [ln for ln in stream.getvalue().splitlines() if ln.strip()] + assert lines, "access log emitted no line" + record = json.loads(lines[-1]) + assert record["request_id"] == "known-req-42" + assert record["path"] == "/health" + assert record["method"] == "GET"