feat(logging): structured JSON logs, request IDs, secret redaction

Rewrite logging_service with a JsonFormatter, a RedactionFilter that masks configured S3 credentials, and a RequestIdFilter
closes #177

Author: alexhambley

app/__init__.py

@@ -7,16 +7,23 @@
 from app.crates.ids import InvalidCrateId
 from app.crates.resolver import CrateNotFound, AmbiguousCrate
 from app.ro_crates.routes import v1_post_bp, v1_minio_post_bp, v1_minio_get_bp
+from app.services.logging_service import (
+    new_request_id,
+    set_request_id,
+    get_request_id,
+)
 from app.storage.errors import StorageError
 from app.utils.config import (
     Settings,
     InvalidAPIUsage,
     make_celery,
 )
-from flask import jsonify
+from flask import jsonify, request
 
 logger = logging.getLogger(__name__)
 
+REQUEST_ID_HEADER = "X-Request-ID"
+
 
 def create_app(settings: Settings | None = None) -> APIFlask:
     """
@@ -52,10 +59,14 @@ def create_app(settings: Settings | None = None) -> APIFlask:
     else:
         logger.info("Storage disabled: only metadata validation is available.")
 
-    if app.debug:
-        print("URL Map:")
-        for rule in app.url_map.iter_rules():
-            print(rule)
+    @app.before_request
+    def assign_request_id():
+        set_request_id(request.headers.get(REQUEST_ID_HEADER) or new_request_id())
+
+    @app.after_request
+    def attach_request_id(response):
+        response.headers[REQUEST_ID_HEADER] = get_request_id()
+        return response
 
     @app.errorhandler(InvalidAPIUsage)
     def invalid_api_usage(e):

app/services/logging_service.py

@@ -1,19 +1,90 @@
-"""Logging service for the application."""
-
-# Author: Alexander Hambley
-# License: MIT
-# Copyright (c) 2025 eScience Lab, The University of Manchester
+"""Structured JSON logging with request IDs and secret redaction."""
 
+import json
 import logging
+import uuid
+
+from contextvars import ContextVar
+from typing import Iterable, Optional
+
+# correlation ID readable from any logging call in the same context. per request basis.
+# (request handler or Celery task). Defaults to "-" when unset.
+_request_id: ContextVar[str] = ContextVar("request_id", default="-")
+
+
+def new_request_id() -> str:
+    """Return a fresh, unique request ID."""
+    return str(uuid.uuid4())
+
+
+def set_request_id(request_id: Optional[str]) -> None:
+    """Set the current request ID (``None`` resets to the default)."""
+    _request_id.set(request_id or "-")
+
+
+def get_request_id() -> str:
+    """Return the current request ID, or ``"-"`` if unset."""
+    return _request_id.get()
+
+
+class RequestIdFilter(logging.Filter):
+    """Attaches the current request ID to every log record."""
 
+    def filter(self, record: logging.LogRecord) -> bool:
+        record.request_id = get_request_id()
+        return True
 
-def setup_logging(level: int = logging.INFO) -> None:
+
+class RedactionFilter(logging.Filter):
+    """Masks known secret values wherever they appear in a log message."""
+
+    def __init__(self, secrets: Iterable[Optional[str]]):
+        super().__init__()
+        self._secrets = [s for s in secrets if s]
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        if self._secrets:
+            message = record.getMessage()
+            for secret in self._secrets:
+                message = message.replace(secret, "***")
+            record.msg = message
+            record.args = None
+        return True
+
+
+class JsonFormatter(logging.Formatter):
+    """Formats log records as single-line JSON."""
+
+    def format(self, record: logging.LogRecord) -> str:
+        payload = {
+            "timestamp": self.formatTime(record),
+            "level": record.levelname,
+            "logger": record.name,
+            "message": record.getMessage(),
+            "request_id": getattr(record, "request_id", "-"),
+        }
+        if record.exc_info:
+            payload["exc_info"] = self.formatException(record.exc_info)
+        return json.dumps(payload)
+
+
+def setup_logging(settings=None, level: int = logging.INFO) -> None:
     """
-    Configure the logging for the application.
+    Configure root logging: JSON output, request IDs, and secret redaction.
 
-    :param level: The logging level to set. Defaults to INFO.
+    :param settings: Optional Settings; its credentials are redacted from logs.
+    :param level: The logging level to set.
     """
-    logging.basicConfig(
-        level=level,
-        format="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
-    )
+    secrets = []
+    if settings is not None:
+        secrets = [settings.s3_secret_key, settings.s3_access_key]
+
+    handler = logging.StreamHandler()
+    handler.setFormatter(JsonFormatter())
+    handler.addFilter(RequestIdFilter())
+    handler.addFilter(RedactionFilter(secrets))
+
+    root = logging.getLogger()
+    root.handlers.clear()
+    root.addHandler(handler)
+    root.setLevel(level)

cratey.py

@@ -8,7 +8,7 @@
 from app.services.logging_service import setup_logging
 
 app = create_app()
-setup_logging()
+setup_logging(app.config["SETTINGS"])
 
 if __name__ == "__main__":
     # Run the Flask development server:

tests/test_app_factory.py

@@ -59,3 +59,25 @@ def test_storage_routes_registered_when_enabled():
 def test_profiles_path_exposed_to_app_config():
     app = create_app(settings=Settings.from_env({"PROFILES_PATH": "/custom/profiles"}))
     assert app.config["PROFILES_PATH"] == "/custom/profiles"
+
+
+def test_response_includes_generated_request_id_header():
+    app = create_app(settings=Settings.from_env({}))
+    client = app.test_client()
+
+    response = client.post("/v1/ro_crates/validate_metadata", json={"crate_json": "{}"})
+
+    assert response.headers.get("X-Request-ID")
+
+
+def test_incoming_request_id_is_echoed():
+    app = create_app(settings=Settings.from_env({}))
+    client = app.test_client()
+
+    response = client.post(
+        "/v1/ro_crates/validate_metadata",
+        json={"crate_json": "{}"},
+        headers={"X-Request-ID": "caller-supplied-id"},
+    )
+
+    assert response.headers["X-Request-ID"] == "caller-supplied-id"

tests/test_logging.py

@@ -0,0 +1,74 @@
+"""Tests for structured logging, request IDs, and secret redaction."""
+
+import json
+import logging
+
+from app.services.logging_service import (
+    JsonFormatter,
+    RedactionFilter,
+    RequestIdFilter,
+    set_request_id,
+    get_request_id,
+    new_request_id,
+)
+
+
+def _record(msg, args=None):
+    return logging.LogRecord("svc", logging.INFO, "path", 1, msg, args, None)
+
+
+def test_json_formatter_emits_expected_fields():
+    record = _record("hello")
+    record.request_id = "r1"
+
+    payload = json.loads(JsonFormatter().format(record))
+
+    assert payload["level"] == "INFO"
+    assert payload["logger"] == "svc"
+    assert payload["message"] == "hello"
+    assert payload["request_id"] == "r1"
+    assert "timestamp" in payload
+
+
+def test_redaction_filter_masks_secret_values():
+    redact = RedactionFilter(["supersecret", "AKIAEXAMPLE"])
+    record = _record("connecting with key=%s token=%s", ("AKIAEXAMPLE", "supersecret"))
+
+    redact.filter(record)
+
+    message = record.getMessage()
+    assert "supersecret" not in message
+    assert "AKIAEXAMPLE" not in message
+    assert message.count("***") == 2
+
+
+def test_redaction_filter_ignores_empty_secrets():
+    redact = RedactionFilter([None, "", "real"])
+    record = _record("value=real")
+    redact.filter(record)
+    assert record.getMessage() == "value=***"
+
+
+def test_request_id_filter_injects_current_id():
+    set_request_id("abc-123")
+    record = _record("anything")
+
+    RequestIdFilter().filter(record)
+
+    assert record.request_id == "abc-123"
+
+
+def test_request_id_filter_defaults_when_unset():
+    set_request_id(None)
+    record = _record("anything")
+    RequestIdFilter().filter(record)
+    assert record.request_id == "-"
+
+
+def test_new_request_id_is_unique():
+    assert new_request_id() != new_request_id()
+
+
+def test_get_request_id_round_trips():
+    set_request_id("xyz")
+    assert get_request_id() == "xyz"