From 6123827d68ec5cba0b65dd3c4822eb97387ee376 Mon Sep 17 00:00:00 2001 From: Mark S Date: Thu, 17 Sep 2026 19:57:05 +1000 Subject: [PATCH 1/3] security(logging): sanitise error kwarg at the structured cache-operation sinks (LAB-3666) UltraOptimizedStructuredLogger.cache_operation and FeatureOrchestrator.log_cache_operation splat **kwargs into the structured payload without sanitising an `error` kwarg, so a caller passing `error=e` would emit the provider exception's text, which can carry the raw cache key (CWE-532). Both in-tree callers pre-sanitise today; this is defence in depth so the next caller need not remember. Each sink now replaces a BaseException `error` with redact_error_for_log(value) before it enters the payload. Strings pass through unchanged: they are already rendered, and re-sanitising one would emit the literal "str". redis_operation_failed passes the object and lets the sink render it; the emitted error/error_type fields are byte-identical to before. New direct-call tests drive each sink with a provider exception and a BackendError whose message embeds a sentinel key and assert over the whole emitted payload. --- .secrets.baseline | 6 +-- SECURITY.md | 2 +- src/cachekit/decorators/orchestrator.py | 9 ++-- src/cachekit/logging.py | 8 +++- tests/unit/test_error_path_key_redaction.py | 47 +++++++++++++++++++ tests/unit/test_log_redaction_architecture.py | 7 +-- tests/unit/test_structured_logging.py | 19 ++++++-- 7 files changed, 81 insertions(+), 17 deletions(-) diff --git a/.secrets.baseline b/.secrets.baseline index 4e41319f..fd899605 100644 --- a/.secrets.baseline +++ b/.secrets.baseline @@ -867,14 +867,14 @@ "filename": "tests/unit/test_structured_logging.py", "hashed_secret": "0cb62954c5feaf5379bfb79b8e0087953ec49b9c", "is_verified": false, - "line_number": 45 + "line_number": 46 }, { "type": "JSON Web Token", "filename": "tests/unit/test_structured_logging.py", "hashed_secret": "d6b66ddd9ea7dbe760114bfe9a97352a5e139134", "is_verified": false, - "line_number": 50 + "line_number": 51 } ], "tests/unit/test_tenant_context.py": [ @@ -887,5 +887,5 @@ } ] }, - "generated_at": "2026-09-14T08:02:35Z" + "generated_at": "2026-09-17T09:56:46Z" } diff --git a/SECURITY.md b/SECURITY.md index 22dd6aee..40a03602 100644 --- a/SECURITY.md +++ b/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 (``), 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=`), 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 (``), 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=`), 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: diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py index e663e0ec..113d0a37 100644 --- a/src/cachekit/decorators/orchestrator.py +++ b/src/cachekit/decorators/orchestrator.py @@ -272,12 +272,15 @@ def set_span_attributes(self, span: Any, attributes: dict[str, Any]): pass def log_cache_operation(self, **kwargs): - """Log cache operation with structured logging. Redacts ``key`` (CWE-532).""" + """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, diff --git a/src/cachekit/logging.py b/src/cachekit/logging.py index ad4ea278..510c3326 100644 --- a/src/cachekit/logging.py +++ b/src/cachekit/logging.py @@ -263,6 +263,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" @@ -414,8 +418,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.""" diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index 95507e55..55d165e7 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/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). diff --git a/tests/unit/test_log_redaction_architecture.py b/tests/unit/test_log_redaction_architecture.py index 01068f77..d41378e8 100644 --- a/tests/unit/test_log_redaction_architecture.py +++ b/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 diff --git a/tests/unit/test_structured_logging.py b/tests/unit/test_structured_logging.py index 5d46ee2e..9184d4ef 100644 --- a/tests/unit/test_structured_logging.py +++ b/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, @@ -169,21 +170,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): From 2db581be20f31565c75217111ce0f7e99f0124ea Mon Sep 17 00:00:00 2001 From: Mark S Date: Fri, 18 Sep 2026 07:09:11 +1000 Subject: [PATCH 2/3] chore: second commit so the squash header uses the PR title This PR had a single commit whose header type is not a conventional commit type. The repository squashes with COMMIT_OR_PR_TITLE, so a single-commit PR squashes under the commit header rather than the linted PR title, and release-please would then skip the change silently. A second commit makes the squash default to the PR title, which the title lint has already checked. No code changes. From fe87d172f4e8df55e9b25638e3da9608c2391604 Mon Sep 17 00:00:00 2001 From: Mark S Date: Fri, 18 Sep 2026 07:22:25 +1000 Subject: [PATCH 3/3] style(orchestrator): annotate log_cache_operation signature Public method on FeatureOrchestrator; add **kwargs: Any and -> None so the signature matches the repository's public-API typing rule. No behaviour change. --- src/cachekit/decorators/orchestrator.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py index 113d0a37..cb041f53 100644 --- a/src/cachekit/decorators/orchestrator.py +++ b/src/cachekit/decorators/orchestrator.py @@ -271,7 +271,7 @@ 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): + 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")