diff --git a/README.md b/README.md index 246bbc9..31fcd3b 100644 --- a/README.md +++ b/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 diff --git a/backend/api.py b/backend/api.py index 182e275..8115d56 100644 --- a/backend/api.py +++ b/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 [">> 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 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"