fix(logging): sanitise error kwarg at the structured cache-operation sinks (LAB-3666)

SECURITY.md

@@ -189,7 +189,7 @@ See [SSRF Protection](docs/features/ssrf-protection.md) for full details, includ
 
 ### Cache Key Redaction in Logs (CWE-532)
 
-Cache keys can embed caller-supplied tenant/user identifiers, so **the SDK's own loggers** (`cachekit.*`) never emit them verbatim ([CWE-532][cwe-532]). Every cachekit log path — decorator error handling (structured and backwards-compat), cache-operation logs, and SWR/TTL-refresh debug logs — replaces the key with a fixed-length blake2b digest (`<redacted:…>`), keeping log lines correlatable without leaking the key. Error paths are covered centrally at the shared error sink (`FeatureOrchestrator.handle_cache_error` / `log_cache_operation`), so new call sites are redacted by construction. `BackendError` redacts the key in its formatted text (`str(e)` carries `key=<redacted:…>`), while the `.key` attribute keeps the raw caller-supplied key for programmatic use — never log `e.key`. Its free-form `message` is caller-supplied and third-party exception text (a redis `ResponseError` naming the key, a pymemcache illegal-input error echoing it) has unknown provenance — so **no cachekit log line renders `str(e)`**. Every logging call that mentions an exception goes through `redact_error_for_log`, which emits only the exception type plus, for `BackendError`, its `BackendErrorType` classification; the full exception stays on the object (`original_exception`, `.message`) for programmatic access. Operators lose the provider's message text in the log line and keep it on the exception. An architecture test (`tests/unit/test_log_redaction_architecture.py`) walks every logging call in the package — `logger.*()`, `get_logger().*()`, `getattr(logger, level)()` — and fails CI if a key-shaped value reaches one unredacted in the message, `%s` arguments, or `extra=`; if an exception — any name bound by `except ... as`, a conventional name (`e`, `exc`, `err`, `error`, `*_err`), or an attribute of one — reaches one outside `redact_error_for_log`; or if a call emits a traceback (`logger.exception`, `exc_info=`). The guarantee does not depend on the next contributor remembering it. It is flow-insensitive: build log lines inline, not via a pre-formatted variable, and bind exceptions with `except ... as` or a conventional name (an `Exception`-typed parameter called `failure` is invisible to it), or the guard cannot see them.
+Cache keys can embed caller-supplied tenant/user identifiers, so **the SDK's own loggers** (`cachekit.*`) never emit them verbatim ([CWE-532][cwe-532]). Every cachekit log path — decorator error handling (structured and backwards-compat), cache-operation logs, and SWR/TTL-refresh debug logs — replaces the key with a fixed-length blake2b digest (`<redacted:…>`), keeping log lines correlatable without leaking the key. Error paths are covered centrally at the shared error sink (`FeatureOrchestrator.handle_cache_error` / `log_cache_operation`), so new call sites are redacted by construction. Both structured cache-operation sinks (`FeatureOrchestrator.log_cache_operation`, `UltraOptimizedStructuredLogger.cache_operation`) also sanitise an exception passed as `error=` themselves — pass the exception object, never `str(e)`, which is emitted as-is. `BackendError` redacts the key in its formatted text (`str(e)` carries `key=<redacted:…>`), while the `.key` attribute keeps the raw caller-supplied key for programmatic use — never log `e.key`. Its free-form `message` is caller-supplied and third-party exception text (a redis `ResponseError` naming the key, a pymemcache illegal-input error echoing it) has unknown provenance — so **no cachekit log line renders `str(e)`**. Every logging call that mentions an exception goes through `redact_error_for_log`, which emits only the exception type plus, for `BackendError`, its `BackendErrorType` classification; the full exception stays on the object (`original_exception`, `.message`) for programmatic access. Operators lose the provider's message text in the log line and keep it on the exception. An architecture test (`tests/unit/test_log_redaction_architecture.py`) walks every logging call in the package — `logger.*()`, `get_logger().*()`, `getattr(logger, level)()` — and fails CI if a key-shaped value reaches one unredacted in the message, `%s` arguments, or `extra=`; if an exception — any name bound by `except ... as`, a conventional name (`e`, `exc`, `err`, `error`, `*_err`), or an attribute of one — reaches one outside `redact_error_for_log`; or if a call emits a traceback (`logger.exception`, `exc_info=`). The guarantee does not depend on the next contributor remembering it. It is flow-insensitive: build log lines inline, not via a pre-formatted variable, and bind exceptions with `except ... as` or a conventional name (an `Exception`-typed parameter called `failure` is invisible to it), or the guard cannot see them.
 
 **Scope — transport logs are not covered.** The CachekitIO backend addresses entries by key in the request path (`GET /v1/cache/{key}`), and `httpx` logs every request line — method, full URL, status — at `INFO` on its own `httpx` logger. An application that enables `INFO` globally (`logging.basicConfig(level=logging.INFO)`) will therefore see raw keys in *httpx's* output on every operation, exactly as it would see any REST resource path. cachekit does not mute a third-party logger on your behalf; if your keys carry identifiers, silence or raise the level of that logger in your logging config:
 

src/cachekit/decorators/orchestrator.py

@@ -271,13 +271,16 @@ def set_span_attributes(self, span: Any, attributes: dict[str, Any]):
         """Set attributes on a span (no-op)."""
         pass
 
-    def log_cache_operation(self, **kwargs):
-        """Log cache operation with structured logging. Redacts ``key`` (CWE-532)."""
+    def log_cache_operation(self, **kwargs: Any) -> None:
+        """Log cache operation with structured logging. Redacts ``key``, sanitises ``error`` (CWE-532)."""
         if self._enable_structured_logging and kwargs:
             operation = kwargs.get("operation", "unknown")
             # Redact in kwargs itself — it is splatted into the structured payload below.
             if "key" in kwargs:
                 kwargs["key"] = redact_key_for_log(kwargs["key"])
+            # CWE-532 at the sink: render an exception key-free; a str is already rendered (re-sanitising one emits "str").
+            if isinstance(kwargs.get("error"), BaseException):
+                kwargs["error"] = redact_error_for_log(kwargs["error"])
             key = kwargs.get("key", "unknown")
             self.log_structured("info", f"Cache operation: {operation}", cache_key=key, **kwargs)
 
@@ -457,8 +460,8 @@ def handle_cache_error(
             operation=f"{operation}_failed",
             key=cache_key,
             namespace=namespace,
-            # Key-free error text (CWE-532): an arbitrary exception's str() may echo
-            # the raw key, so only BackendError (self-sanitising) is logged verbatim.
+            # Key-free error text (CWE-532): type name only, or BackendError(error_type) —
+            # no exception's str() is trusted. The sink renders a raw object the same way.
             error=redact_error_for_log(error),
             error_type=type(error).__name__,
             duration_ms=duration_ms,

src/cachekit/logging.py

@@ -261,6 +261,10 @@ def cache_operation(self, operation: str, cache_key: str, **kwargs):
         # correlation between the two sinks. Sentinels stay readable too.
         display_key = redact_key_for_log(cache_key) if cache_key else ""
 
+        # CWE-532 at the sink: render an exception key-free; a str is already rendered (re-sanitising one emits "str").
+        if isinstance(kwargs.get("error"), BaseException):
+            kwargs["error"] = redact_error_for_log(kwargs["error"])
+
         # Determine log level based on error presence
         level = "ERROR" if "error" in kwargs else "INFO"
 
@@ -412,8 +416,8 @@ def _get_context(self) -> dict[str, Any]:
 
     # Compatibility methods for tests
     def redis_operation_failed(self, operation: str, key: str, error: Exception, **kwargs):
-        """Log Redis operation failure. Error text is key-free (CWE-532)."""
-        self.cache_operation(operation, key, error=redact_error_for_log(error), error_type=type(error).__name__, **kwargs)
+        """Log Redis operation failure. ``cache_operation`` renders the error key-free (CWE-532)."""
+        self.cache_operation(operation, key, error=error, error_type=type(error).__name__, **kwargs)
 
     def cache_hit(self, key: str, **kwargs):
         """Log cache hit."""

tests/unit/test_error_path_key_redaction.py

@@ -395,6 +395,53 @@ def test_arbitrary_exception_reduced_to_type_name(self) -> None:
         assert TENANT_KEY not in rendered
 
 
+ERROR_KWARGS = [
+    pytest.param(ValueError(f"WRONGTYPE for {TENANT_KEY}"), "ValueError", id="provider_exception"),
+    pytest.param(
+        BackendError(f"provider failure for {TENANT_KEY}", error_type=BackendErrorType.TIMEOUT, key=TENANT_KEY),
+        "BackendError(timeout)",
+        id="backenderror_key_in_message",
+    ),
+    pytest.param("Connection timeout", "Connection timeout", id="str_passes_through"),
+]
+
+
+class TestErrorKwargSanitisedAtSink:
+    """An ``error`` kwarg is sanitised once, at each structured sink (CWE-532, defence in depth).
+
+    Three in-tree callers, three shapes: ``handle_cache_error`` pre-renders to a str,
+    ``redis_operation_failed`` passes the exception object, and the circuit-breaker path
+    in ``wrapper.py`` passes a str literal. The sink must emit all three key-free, and a
+    str must pass through untouched (re-sanitising one would emit the literal ``"str"``).
+    The assertion runs over the whole payload, not the ``error`` field alone.
+    """
+
+    @pytest.mark.parametrize(("error", "rendered"), ERROR_KWARGS)
+    def test_logging_sink(self, error: object, rendered: str, caplog: pytest.LogCaptureFixture) -> None:
+        logger = UltraOptimizedStructuredLogger("test.error_kwarg")
+
+        with caplog.at_level(logging.INFO, logger="test.error_kwarg"):
+            logger.cache_operation("set", TENANT_KEY, error=error)
+
+        assert not any(TENANT_KEY in m for m in _messages(caplog))
+        assert caplog.records[-1].structured["error"] == rendered
+
+    @pytest.mark.parametrize(("error", "rendered"), ERROR_KWARGS)
+    def test_orchestrator_sink(self, error: object, rendered: str, caplog: pytest.LogCaptureFixture) -> None:
+        orchestrator = FeatureOrchestrator(
+            namespace="test",
+            circuit_breaker_enabled=False,
+            backpressure_enabled=False,
+            enable_structured_logging=True,
+        )
+
+        with caplog.at_level(logging.INFO):
+            orchestrator.log_cache_operation(operation="set_failed", key=TENANT_KEY, error=error)
+
+        assert not any(TENANT_KEY in m for m in _messages(caplog))
+        assert caplog.records[-1].structured["error"] == rendered
+
+
 class TestClassifierMessagesAreKeyFree:
     """Every backend classifier must build a key-free BackendError.message (CWE-532).
 

tests/unit/test_log_redaction_architecture.py

@@ -29,9 +29,10 @@
 held in a parameter with an unconventional name (``failure: Exception``) is not
 recognised. Build log lines inline, and bind exceptions with ``except ... as``
 or a conventional name, so the guard can see them. Sink-central redaction is not
-exempted: the sinks' own stdlib calls satisfy the rule; callers passing raw keys
-*into* ``handle_cache_error`` / ``log_cache_operation`` / ``SimpleLogger.cache_*``
-are covered by those sinks' contract tests, not here.
+exempted: the sinks' own stdlib calls satisfy the rule; callers passing raw keys or
+exceptions *into* ``handle_cache_error`` / ``log_cache_operation`` /
+``cache_operation`` / ``SimpleLogger.cache_*`` are covered by those sinks' contract
+tests, not here.
 """
 
 from __future__ import annotations

tests/unit/test_structured_logging.py

@@ -8,6 +8,7 @@
 
 import pytest
 
+from cachekit.backends.errors import BackendError, BackendErrorType
 from cachekit.logging import (
     JsonFormatter,
     StructuredRedisLogger,
@@ -115,21 +116,29 @@ def test_cache_operation_error_logging(self, mock_log, logger):
         assert extra["error"] == "Connection timeout"
         assert extra["error_type"] == "TimeoutError"
 
+    @pytest.mark.parametrize(
+        ("error", "rendered", "error_type"),
+        [
+            (ValueError("Test error"), "ValueError", "ValueError"),
+            (BackendError("Redis timeout", error_type=BackendErrorType.TIMEOUT), "BackendError(timeout)", "BackendError"),
+        ],
+        ids=["provider_exception", "backend_error"],
+    )
     @patch("cachekit.logging.logging.Logger.log")
-    def test_redis_operation_failed_override(self, mock_log, logger):
+    def test_redis_operation_failed_override(self, mock_log, logger, error, rendered, error_type):
         """redis_operation_failed emits a key-free error representation (CWE-532).
 
         A non-BackendError's str() has unknown provenance and may echo the raw cache
-        key, so only its type name reaches the log; error_type still carries the type.
+        key, so only its type name reaches the log; a BackendError renders as
+        ``TypeName(error_type)``. error_type still carries the Python type.
         """
-        error = ValueError("Test error")
         logger.redis_operation_failed("get", "test_key", error)
 
         mock_log.assert_called_once()
         extra = mock_log.call_args[1]["extra"]["structured"]
         assert extra["operation"] == "get"
-        assert extra["error"] == "ValueError"  # not the raw "Test error" message
-        assert extra["error_type"] == "ValueError"
+        assert extra["error"] == rendered  # never the raw message
+        assert extra["error_type"] == error_type
 
     @patch("cachekit.logging.logging.Logger.log")
     def test_cache_hit_override(self, mock_log, logger):