feat(ml-api): redact secrets/PII from logs and route errors through it

README.md

@@ -530,6 +530,25 @@ call site:
   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

backend/api.py

@@ -74,9 +74,9 @@
 
 app = Flask(__name__)
 
-# Install the JSON log formatter + request-id filter on the root logger before
-# anything logs, so every line (including app.logger records that propagate
-# here) is structured from the first request (#1006).
+# 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")
@@ -275,8 +275,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,
@@ -286,9 +287,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)
 
@@ -348,7 +349,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"}
@@ -380,8 +381,9 @@ def decorated_function(*args, **kwargs):
                     p in value.lower()
                     for p in ["<script", "javascript:", "onerror", "onload"]
                 ):
-                    app.logger.warning(
-                        f"⚠️  Suspicious query param: {key}={value[:50]}"
+                    logger.warning(
+                        "suspicious_query_param",
+                        extra={"param": key, "value_preview": value[:50]},
                     )
                     return (
                         jsonify(
@@ -398,8 +400,9 @@ def decorated_function(*args, **kwargs):
 
             data_str = json.dumps(data).lower()
             if any(p in data_str for p in ["<script", "javascript:", "onerror"]):
-                app.logger.warning(
-                    f"⚠️  Suspicious request body from {request.remote_addr}"
+                logger.warning(
+                    "suspicious_request_body",
+                    extra={"remote_addr": request.remote_addr},
                 )
                 return jsonify({"success": False, "error": "Invalid request body"}), 400
 
@@ -451,15 +454,31 @@ def _current_request_id():
     return getattr(g, "request_id", "unknown")
 
 
+def _log_error(code, status, message, *, exc_info=False):
+    """Emit one structured error line carrying the stable code + request id."""
+    logger.error(
+        "request_error",
+        exc_info=exc_info,
+        extra={
+            "error_code": ErrorCode(code).value,
+            "status": status,
+            "detail": message,
+            "request_id": _current_request_id(),
+        },
+    )
+
+
 @app.errorhandler(ApiError)
 def handle_api_error(e):
     """Render a raised ApiError through the shared error envelope (#986)."""
+    _log_error(e.code, e.status, e.message)
     return error_response(e.code, e.message, e.status, request_id=_current_request_id())
 
 
 @app.errorhandler(400)
 def handle_bad_request(e):
     message = getattr(e, "description", None) or "Bad request"
+    _log_error(ErrorCode.BAD_REQUEST, 400, message)
     return error_response(
         ErrorCode.BAD_REQUEST, message, 400, request_id=_current_request_id()
     )
@@ -468,6 +487,7 @@ def handle_bad_request(e):
 @app.errorhandler(403)
 def handle_forbidden(e):
     message = getattr(e, "description", None) or "Forbidden"
+    _log_error(ErrorCode.FORBIDDEN, 403, message)
     # success:false is part of the zero-trust JSON shape existing callers read.
     return error_response(
         ErrorCode.FORBIDDEN,
@@ -481,6 +501,7 @@ def handle_forbidden(e):
 @app.errorhandler(404)
 def handle_not_found(e):
     message = getattr(e, "description", None) or "Not found"
+    _log_error(ErrorCode.NOT_FOUND, 404, message)
     return error_response(
         ErrorCode.NOT_FOUND, message, 404, request_id=_current_request_id()
     )
@@ -494,7 +515,7 @@ def handle_internal_error(e):
     if isinstance(e, HTTPException):
         return e
     request_id = _current_request_id()
-    app.logger.exception(f"❌ [Request-ID: {request_id}] Unhandled exception")
+    _log_error(ErrorCode.INTERNAL_ERROR, 500, "Unhandled exception", exc_info=True)
     # Keep the legacy top-level request_id alongside the new envelope so clients
     # that already read it keep working.
     return error_response(

backend/logging_config.py

@@ -1,19 +1,24 @@
-"""Structured JSON logging for the Flask ML API (issue #1006, part 1).
+"""Structured JSON logging for the Flask ML API (issue #1006).
 
 The API historically emitted ad-hoc ``app.logger.warning(f"...")`` lines with
 emoji prefixes and interpolated request context. Those are impossible to parse
-reliably in a log pipeline. This module centralises logging on a single JSON
-formatter so every line is a self-describing object that a pipeline can index
-and correlate by ``request_id``.
+reliably in a log pipeline and occasionally embed sensitive material (the
+internal secret, OAuth tokens, threat-intel API keys, user email addresses and
+message bodies). This module centralises logging on a single JSON formatter so
+every line is a self-describing object that a pipeline can index, correlate by
+``request_id``, and safely retain.
 
-Two pieces cooperate:
+Three pieces cooperate:
 
 * :class:`JsonLogFormatter` renders each record as one JSON object with a fixed
   core schema (``ts``, ``level``, ``logger``, ``msg``, ``request_id``) plus any
   structured ``extra=`` fields passed at the call site.
 * :class:`RequestIdFilter` stamps the active request's ``g.request_id`` onto
   every record so the id propagates without threading it through call sites. It
   is safe outside an application/request context, falling back to ``"-"``.
+* :class:`RedactionFilter` (part 2) scrubs secrets and personal data from a
+  record *before* it is formatted, so a token or email accidentally passed to a
+  log call never reaches the sink in the clear.
 
 Call :func:`configure_logging` once at startup and obtain module loggers with
 :func:`get_logger`.
@@ -26,15 +31,22 @@
 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 = "-"
@@ -102,19 +114,100 @@ def filter(self, record):
         return True
 
 
-def configure_logging(level=logging.INFO, *, stream=None):
-    """Install the JSON formatter + request-id filter on the root logger.
+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