From 63d9132e38aaf1bfe204a97cd3de38f0e63900ef Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Mon, 31 Aug 2026 02:14:12 +1000 Subject: [PATCH 1/8] fix(logging): redact cache keys at the shared error sink (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Raw cache keys embed caller-supplied tenant/user identifiers and were still logged verbatim on every non-cache_set error path (CWE-532). Redact once inside FeatureOrchestrator.handle_cache_error and log_cache_operation so all callers — current and future — are covered by construction; the three LAB-109 cache_set call sites now pass the raw key and the sink emits the identical blake2b digest as before. Sentinels (unknown, ) stay readable. --- SECURITY.md | 4 + src/cachekit/decorators/orchestrator.py | 27 +++++- src/cachekit/decorators/wrapper.py | 6 +- .../unit/test_orchestrator_error_handling.py | 93 +++++++++++++++++++ 4 files changed, 125 insertions(+), 5 deletions(-) diff --git a/SECURITY.md b/SECURITY.md index 008160a..28f6f23 100644 --- a/SECURITY.md +++ b/SECURITY.md @@ -187,6 +187,10 @@ When using `@cache.io` (CachekitIOBackend), the SDK includes built-in Server-Sid See [SSRF Protection](docs/features/ssrf-protection.md) for full details, including custom host configuration for development environments. +### Cache Key Redaction in Logs (CWE-532) + +Cache keys can embed caller-supplied tenant/user identifiers, so they never reach logs verbatim ([CWE-532][cwe-532]). Every 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. + ### Lock Token Transport (CWE-532) The distributed-lock capability token (`lock_id`) is sent in the `X-CacheKit-Lock-Id` request header when releasing a lock (`DELETE /v1/cache/{key}/lock`), **never** in the URL query string. Query strings are routinely captured by access logs, proxy/CDN logs, and OpenTelemetry `http.url` spans ([CWE-532][cwe-532]); a leaked token could be replayed to release a lock within its short TTL. The CacheKit SaaS backend dual-reads the header and the legacy `?lock_id=` query during migration, preferring the header (removed in protocol 2.0). diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py index 66abbc2..f71b4de 100644 --- a/src/cachekit/decorators/orchestrator.py +++ b/src/cachekit/decorators/orchestrator.py @@ -3,6 +3,7 @@ import uuid from typing import Any, Optional +from ..cache_handler import redact_cache_key from ..monitoring.correlation_tracking import CorrelationTracker from ..monitoring.pool_monitor import OptimizedPoolMonitor @@ -19,6 +20,20 @@ _operation_context: contextvars.ContextVar[Optional[dict[str, Any]]] = contextvars.ContextVar("operation_context", default=None) +def _redact_key_for_log(cache_key: object) -> str: + """Redact a cache key for logging unless it is a sentinel or already redacted. + + Cache keys embed caller-supplied tenant/user identifiers and must never reach + logs verbatim (CWE-532, issue #163). Real keys are canonical ``ns:...`` strings; + sentinels (``unknown``, ````) and pre-redacted values + (````) carry no caller data and stay readable as-is. + """ + key_str = str(cache_key) + if key_str == "unknown" or (key_str.startswith("<") and key_str.endswith(">")): + return key_str + return redact_cache_key(key_str) + + class FeatureOrchestrator: """Orchestrates existing reliability and monitoring features. @@ -271,9 +286,12 @@ def set_span_attributes(self, span: Any, attributes: dict[str, Any]): pass def log_cache_operation(self, **kwargs): - """Log cache operation with structured logging.""" + """Log cache operation with structured logging. Redacts ``key`` (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"]) key = kwargs.get("key", "unknown") self.log_structured("info", f"Cache operation: {operation}", cache_key=key, **kwargs) @@ -414,7 +432,8 @@ def handle_cache_error( Args: error: The exception that occurred operation: Operation type (e.g., "key_generation", "cache_get", "cache_set") - cache_key: Cache key involved (use "unknown" if unavailable) + cache_key: Cache key involved (use "unknown" if unavailable). Pass the + raw key — it is redacted here before any logging (CWE-532). namespace: Cache namespace (defaults to orchestrator namespace) span: Optional tracing span for recording duration_ms: Operation duration in milliseconds @@ -433,6 +452,10 @@ def handle_cache_error( # Use orchestrator namespace if not provided namespace = namespace or self.namespace + # Redact once at the sink so every error path is covered by construction + # (CWE-532) — callers pass the raw key; sentinels pass through readable. + cache_key = _redact_key_for_log(cache_key) + # 1. Record exception in span and metrics if span: self.record_exception(span, error) diff --git a/src/cachekit/decorators/wrapper.py b/src/cachekit/decorators/wrapper.py index f84847a..76cf0c4 100644 --- a/src/cachekit/decorators/wrapper.py +++ b/src/cachekit/decorators/wrapper.py @@ -1373,7 +1373,7 @@ def sync_wrapper(*args: Any, **kwargs: Any) -> Any: # noqa: PLR0912 features.handle_cache_error( error=e, operation="cache_set", - cache_key=redact_cache_key(cache_key) if cache_key else "unknown", + cache_key=cache_key or "unknown", namespace=namespace or "default", duration_ms=set_duration_ms, serializer="rust", @@ -1815,7 +1815,7 @@ async def async_wrapper(*args: Any, **kwargs: Any) -> Any: features.handle_cache_error( error=e, operation="cache_set", - cache_key=redact_cache_key(cache_key) if cache_key else "unknown", + cache_key=cache_key or "unknown", namespace=namespace or "default", duration_ms=set_duration_ms, correlation_id=correlation_id, @@ -1897,7 +1897,7 @@ async def async_wrapper(*args: Any, **kwargs: Any) -> Any: features.handle_cache_error( error=e, operation="cache_set", - cache_key=redact_cache_key(cache_key) if cache_key else "unknown", + cache_key=cache_key or "unknown", namespace=namespace or "default", duration_ms=set_duration_ms, correlation_id=correlation_id, diff --git a/tests/unit/test_orchestrator_error_handling.py b/tests/unit/test_orchestrator_error_handling.py index bbd0ed1..b462176 100644 --- a/tests/unit/test_orchestrator_error_handling.py +++ b/tests/unit/test_orchestrator_error_handling.py @@ -4,8 +4,11 @@ actual behavior and contracts, not implementation details. """ +import logging + import pytest +from cachekit.cache_handler import redact_cache_key from cachekit.decorators.orchestrator import FeatureOrchestrator @@ -271,3 +274,93 @@ def test_error_handler_with_nested_exceptions(self): ) # Test passes if no exception + + +class TestCacheKeyRedaction: + """Raw cache keys must never reach logs on any error path (CWE-532, LAB-304). + + Keys embed caller-supplied tenant/user identifiers; the sink redacts once so + every caller is covered by construction. + """ + + # A canonical key carrying a tenant-identifying argument digest segment + TENANT_KEY = "ns:prod:func:app.get_user:args:tenant-42-alice-secret:v1" + + def _orchestrator(self) -> FeatureOrchestrator: + return FeatureOrchestrator( + namespace="test", + circuit_breaker_enabled=False, + enable_structured_logging=True, + ) + + @pytest.mark.parametrize("operation", ["cache_get", "key_generation", "backend_connection", "client_creation"]) + def test_non_cache_set_failure_never_logs_raw_key(self, operation: str, caplog: pytest.LogCaptureFixture) -> None: + """The tenant key must not appear verbatim in any log record — structured or backwards-compat.""" + with caplog.at_level(logging.INFO): + self._orchestrator().handle_cache_error( + error=ConnectionError("backend down"), + operation=operation, + cache_key=self.TENANT_KEY, + duration_ms=1.0, + ) + + assert caplog.records, "error handler must log" + for record in caplog.records: + assert self.TENANT_KEY not in record.getMessage() + structured = getattr(record, "structured", None) + if structured is not None: + assert self.TENANT_KEY not in str(structured) + + def test_backwards_compat_log_carries_correlatable_digest(self, caplog: pytest.LogCaptureFixture) -> None: + """Redaction keeps failures correlatable: the blake2b digest replaces the raw key.""" + with caplog.at_level(logging.WARNING): + self._orchestrator().handle_cache_error( + error=ConnectionError("backend down"), + operation="cache_get", + cache_key=self.TENANT_KEY, + ) + + digest = redact_cache_key(self.TENANT_KEY) + assert any(digest in record.getMessage() for record in caplog.records) + + def test_cache_set_digest_unchanged_from_lab_109(self, caplog: pytest.LogCaptureFixture) -> None: + """cache_set callers now pass the raw key; the sink must emit the SAME digest + the call-site redaction produced before (LAB-109 behaviour intact).""" + with caplog.at_level(logging.WARNING): + self._orchestrator().handle_cache_error( + error=OSError("disk full"), + operation="cache_set", + cache_key=self.TENANT_KEY, + ) + + digest = redact_cache_key(self.TENANT_KEY) + assert any(digest in record.getMessage() for record in caplog.records) + assert not any(self.TENANT_KEY in record.getMessage() for record in caplog.records) + + @pytest.mark.parametrize("sentinel", ["unknown", "", ""]) + def test_sentinels_pass_through_unredacted(self, sentinel: str, caplog: pytest.LogCaptureFixture) -> None: + """Non-key sentinels carry no caller data and stay readable (no double-redaction).""" + with caplog.at_level(logging.WARNING): + self._orchestrator().handle_cache_error( + error=ValueError("boom"), + operation="key_generation", + cache_key=sentinel, + ) + + assert any(sentinel in record.getMessage() for record in caplog.records) + + def test_structured_log_cache_operation_redacts_key(self, caplog: pytest.LogCaptureFixture) -> None: + """Direct log_cache_operation callers (circuit-breaker, hit logs) are covered too.""" + with caplog.at_level(logging.INFO): + self._orchestrator().log_cache_operation( + operation="circuit_breaker_open", + key=self.TENANT_KEY, + error="Circuit breaker is OPEN", + ) + + assert caplog.records + for record in caplog.records: + assert self.TENANT_KEY not in record.getMessage() + structured = getattr(record, "structured", None) + if structured is not None: + assert self.TENANT_KEY not in str(structured) From 9eab94f0e26c7cce1b8a73e8c9e0657a019d5144 Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Mon, 31 Aug 2026 02:40:03 +1000 Subject: [PATCH 2/8] fix(logging): redact remaining raw-key log sites tree-wide (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Expert-panel review of the sink change found direct logger calls that bypass FeatureOrchestrator and still logged raw keys: wrapper.py TTL- refresh/lock/deserialize/interop-delete paths, cache_handler.py backend error paths, SimpleLogger cache_hit/miss/stored/invalidated, and the L1 TTL-skip debug line. All now redact. redact_cache_key moves to the hash_utils leaf module (verbatim; re- exported from cache_handler) so backends/provider.py and l1_cache.py can use it without a circular import through cache_handler. Existing tests asserting raw keys in log messages updated to assert the digest instead — the bare-key-vs-:lock-suffix contract in test_wrapper_lock_bare_key.py survives via digest inequality. --- .secrets.baseline | 4 +- lab304.diff | 224 +++++++++++++++++++++++ src/cachekit/backends/provider.py | 18 +- src/cachekit/cache_handler.py | 59 +++--- src/cachekit/decorators/orchestrator.py | 3 + src/cachekit/decorators/wrapper.py | 28 +-- src/cachekit/hash_utils.py | 14 ++ src/cachekit/l1_cache.py | 8 +- tests/unit/backends/test_provider.py | 15 +- tests/unit/test_wrapper_lock_bare_key.py | 17 +- 10 files changed, 321 insertions(+), 69 deletions(-) create mode 100644 lab304.diff diff --git a/.secrets.baseline b/.secrets.baseline index 809c294..c2fb19f 100644 --- a/.secrets.baseline +++ b/.secrets.baseline @@ -222,7 +222,7 @@ "filename": "src/cachekit/cache_handler.py", "hashed_secret": "5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8", "is_verified": false, - "line_number": 430 + "line_number": 423 } ], "src/cachekit/config/decorator.py": [ @@ -887,5 +887,5 @@ } ] }, - "generated_at": "2026-08-07T16:45:43Z" + "generated_at": "2026-08-30T16:39:38Z" } diff --git a/lab304.diff b/lab304.diff new file mode 100644 index 0000000..a4b8e2f --- /dev/null +++ b/lab304.diff @@ -0,0 +1,224 @@ +diff --git a/SECURITY.md b/SECURITY.md +index 008160a..28f6f23 100644 +--- a/SECURITY.md ++++ b/SECURITY.md +@@ -187,6 +187,10 @@ When using `@cache.io` (CachekitIOBackend), the SDK includes built-in Server-Sid + + See [SSRF Protection](docs/features/ssrf-protection.md) for full details, including custom host configuration for development environments. + ++### Cache Key Redaction in Logs (CWE-532) ++ ++Cache keys can embed caller-supplied tenant/user identifiers, so they never reach logs verbatim ([CWE-532][cwe-532]). Every 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. ++ + ### Lock Token Transport (CWE-532) + + The distributed-lock capability token (`lock_id`) is sent in the `X-CacheKit-Lock-Id` request header when releasing a lock (`DELETE /v1/cache/{key}/lock`), **never** in the URL query string. Query strings are routinely captured by access logs, proxy/CDN logs, and OpenTelemetry `http.url` spans ([CWE-532][cwe-532]); a leaked token could be replayed to release a lock within its short TTL. The CacheKit SaaS backend dual-reads the header and the legacy `?lock_id=` query during migration, preferring the header (removed in protocol 2.0). +diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py +index 66abbc2..f71b4de 100644 +--- a/src/cachekit/decorators/orchestrator.py ++++ b/src/cachekit/decorators/orchestrator.py +@@ -3,6 +3,7 @@ import logging + import uuid + from typing import Any, Optional + ++from ..cache_handler import redact_cache_key + from ..monitoring.correlation_tracking import CorrelationTracker + from ..monitoring.pool_monitor import OptimizedPoolMonitor + +@@ -19,6 +20,20 @@ logger = logging.getLogger(__name__) + _operation_context: contextvars.ContextVar[Optional[dict[str, Any]]] = contextvars.ContextVar("operation_context", default=None) + + ++def _redact_key_for_log(cache_key: object) -> str: ++ """Redact a cache key for logging unless it is a sentinel or already redacted. ++ ++ Cache keys embed caller-supplied tenant/user identifiers and must never reach ++ logs verbatim (CWE-532, issue #163). Real keys are canonical ``ns:...`` strings; ++ sentinels (``unknown``, ````) and pre-redacted values ++ (````) carry no caller data and stay readable as-is. ++ """ ++ key_str = str(cache_key) ++ if key_str == "unknown" or (key_str.startswith("<") and key_str.endswith(">")): ++ return key_str ++ return redact_cache_key(key_str) ++ ++ + class FeatureOrchestrator: + """Orchestrates existing reliability and monitoring features. + +@@ -271,9 +286,12 @@ class FeatureOrchestrator: + pass + + def log_cache_operation(self, **kwargs): +- """Log cache operation with structured logging.""" ++ """Log cache operation with structured logging. Redacts ``key`` (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"]) + key = kwargs.get("key", "unknown") + self.log_structured("info", f"Cache operation: {operation}", cache_key=key, **kwargs) + +@@ -414,7 +432,8 @@ class FeatureOrchestrator: + Args: + error: The exception that occurred + operation: Operation type (e.g., "key_generation", "cache_get", "cache_set") +- cache_key: Cache key involved (use "unknown" if unavailable) ++ cache_key: Cache key involved (use "unknown" if unavailable). Pass the ++ raw key — it is redacted here before any logging (CWE-532). + namespace: Cache namespace (defaults to orchestrator namespace) + span: Optional tracing span for recording + duration_ms: Operation duration in milliseconds +@@ -433,6 +452,10 @@ class FeatureOrchestrator: + # Use orchestrator namespace if not provided + namespace = namespace or self.namespace + ++ # Redact once at the sink so every error path is covered by construction ++ # (CWE-532) — callers pass the raw key; sentinels pass through readable. ++ cache_key = _redact_key_for_log(cache_key) ++ + # 1. Record exception in span and metrics + if span: + self.record_exception(span, error) +diff --git a/src/cachekit/decorators/wrapper.py b/src/cachekit/decorators/wrapper.py +index f84847a..76cf0c4 100644 +--- a/src/cachekit/decorators/wrapper.py ++++ b/src/cachekit/decorators/wrapper.py +@@ -1373,7 +1373,7 @@ def create_cache_wrapper( + features.handle_cache_error( + error=e, + operation="cache_set", +- cache_key=redact_cache_key(cache_key) if cache_key else "unknown", ++ cache_key=cache_key or "unknown", + namespace=namespace or "default", + duration_ms=set_duration_ms, + serializer="rust", +@@ -1815,7 +1815,7 @@ def create_cache_wrapper( + features.handle_cache_error( + error=e, + operation="cache_set", +- cache_key=redact_cache_key(cache_key) if cache_key else "unknown", ++ cache_key=cache_key or "unknown", + namespace=namespace or "default", + duration_ms=set_duration_ms, + correlation_id=correlation_id, +@@ -1897,7 +1897,7 @@ def create_cache_wrapper( + features.handle_cache_error( + error=e, + operation="cache_set", +- cache_key=redact_cache_key(cache_key) if cache_key else "unknown", ++ cache_key=cache_key or "unknown", + namespace=namespace or "default", + duration_ms=set_duration_ms, + correlation_id=correlation_id, +diff --git a/tests/unit/test_orchestrator_error_handling.py b/tests/unit/test_orchestrator_error_handling.py +index bbd0ed1..b462176 100644 +--- a/tests/unit/test_orchestrator_error_handling.py ++++ b/tests/unit/test_orchestrator_error_handling.py +@@ -4,8 +4,11 @@ Tests the error handling orchestration without test theatre - validates + actual behavior and contracts, not implementation details. + """ + ++import logging ++ + import pytest + ++from cachekit.cache_handler import redact_cache_key + from cachekit.decorators.orchestrator import FeatureOrchestrator + + +@@ -271,3 +274,93 @@ class TestErrorHandlerEdgeCases: + ) + + # Test passes if no exception ++ ++ ++class TestCacheKeyRedaction: ++ """Raw cache keys must never reach logs on any error path (CWE-532, LAB-304). ++ ++ Keys embed caller-supplied tenant/user identifiers; the sink redacts once so ++ every caller is covered by construction. ++ """ ++ ++ # A canonical key carrying a tenant-identifying argument digest segment ++ TENANT_KEY = "ns:prod:func:app.get_user:args:tenant-42-alice-secret:v1" ++ ++ def _orchestrator(self) -> FeatureOrchestrator: ++ return FeatureOrchestrator( ++ namespace="test", ++ circuit_breaker_enabled=False, ++ enable_structured_logging=True, ++ ) ++ ++ @pytest.mark.parametrize("operation", ["cache_get", "key_generation", "backend_connection", "client_creation"]) ++ def test_non_cache_set_failure_never_logs_raw_key(self, operation: str, caplog: pytest.LogCaptureFixture) -> None: ++ """The tenant key must not appear verbatim in any log record — structured or backwards-compat.""" ++ with caplog.at_level(logging.INFO): ++ self._orchestrator().handle_cache_error( ++ error=ConnectionError("backend down"), ++ operation=operation, ++ cache_key=self.TENANT_KEY, ++ duration_ms=1.0, ++ ) ++ ++ assert caplog.records, "error handler must log" ++ for record in caplog.records: ++ assert self.TENANT_KEY not in record.getMessage() ++ structured = getattr(record, "structured", None) ++ if structured is not None: ++ assert self.TENANT_KEY not in str(structured) ++ ++ def test_backwards_compat_log_carries_correlatable_digest(self, caplog: pytest.LogCaptureFixture) -> None: ++ """Redaction keeps failures correlatable: the blake2b digest replaces the raw key.""" ++ with caplog.at_level(logging.WARNING): ++ self._orchestrator().handle_cache_error( ++ error=ConnectionError("backend down"), ++ operation="cache_get", ++ cache_key=self.TENANT_KEY, ++ ) ++ ++ digest = redact_cache_key(self.TENANT_KEY) ++ assert any(digest in record.getMessage() for record in caplog.records) ++ ++ def test_cache_set_digest_unchanged_from_lab_109(self, caplog: pytest.LogCaptureFixture) -> None: ++ """cache_set callers now pass the raw key; the sink must emit the SAME digest ++ the call-site redaction produced before (LAB-109 behaviour intact).""" ++ with caplog.at_level(logging.WARNING): ++ self._orchestrator().handle_cache_error( ++ error=OSError("disk full"), ++ operation="cache_set", ++ cache_key=self.TENANT_KEY, ++ ) ++ ++ digest = redact_cache_key(self.TENANT_KEY) ++ assert any(digest in record.getMessage() for record in caplog.records) ++ assert not any(self.TENANT_KEY in record.getMessage() for record in caplog.records) ++ ++ @pytest.mark.parametrize("sentinel", ["unknown", "", ""]) ++ def test_sentinels_pass_through_unredacted(self, sentinel: str, caplog: pytest.LogCaptureFixture) -> None: ++ """Non-key sentinels carry no caller data and stay readable (no double-redaction).""" ++ with caplog.at_level(logging.WARNING): ++ self._orchestrator().handle_cache_error( ++ error=ValueError("boom"), ++ operation="key_generation", ++ cache_key=sentinel, ++ ) ++ ++ assert any(sentinel in record.getMessage() for record in caplog.records) ++ ++ def test_structured_log_cache_operation_redacts_key(self, caplog: pytest.LogCaptureFixture) -> None: ++ """Direct log_cache_operation callers (circuit-breaker, hit logs) are covered too.""" ++ with caplog.at_level(logging.INFO): ++ self._orchestrator().log_cache_operation( ++ operation="circuit_breaker_open", ++ key=self.TENANT_KEY, ++ error="Circuit breaker is OPEN", ++ ) ++ ++ assert caplog.records ++ for record in caplog.records: ++ assert self.TENANT_KEY not in record.getMessage() ++ structured = getattr(record, "structured", None) ++ if structured is not None: ++ assert self.TENANT_KEY not in str(structured) diff --git a/src/cachekit/backends/provider.py b/src/cachekit/backends/provider.py index a6e4b07..d8f44d8 100644 --- a/src/cachekit/backends/provider.py +++ b/src/cachekit/backends/provider.py @@ -9,6 +9,8 @@ from typing import TYPE_CHECKING, Optional +from cachekit.hash_utils import redact_cache_key + if TYPE_CHECKING: import redis import redis.asyncio as redis_async @@ -59,21 +61,21 @@ def error(self, message: str): self._logger.error(message) def cache_hit(self, key: str, source: str = "Redis"): - """Log cache hits.""" - self._logger.debug(f"{source} cache hit for key: {key}") + """Log cache hits. Keys are redacted — they embed caller identifiers (CWE-532).""" + self._logger.debug(f"{source} cache hit for key: {redact_cache_key(key)}") def cache_miss(self, key: str): - """Log cache misses.""" - self._logger.debug(f"Cache miss for key: {key}") + """Log cache misses. Keys are redacted — they embed caller identifiers (CWE-532).""" + self._logger.debug(f"Cache miss for key: {redact_cache_key(key)}") def cache_stored(self, key: str, ttl=None): - """Log cache storage operations.""" + """Log cache storage operations. Keys are redacted — they embed caller identifiers (CWE-532).""" ttl_info = f" with TTL {ttl}" if ttl else "" - self._logger.debug(f"Cached result for key: {key}{ttl_info}") + self._logger.debug(f"Cached result for key: {redact_cache_key(key)}{ttl_info}") def cache_invalidated(self, key: str, source: str = "Redis"): - """Log cache invalidation.""" - self._logger.debug(f"Invalidated {source} cache for key: {key}") + """Log cache invalidation. Keys are redacted — they embed caller identifiers (CWE-532).""" + self._logger.debug(f"Invalidated {source} cache for key: {redact_cache_key(key)}") class DefaultLoggerProvider(LoggerProvider): diff --git a/src/cachekit/cache_handler.py b/src/cachekit/cache_handler.py index 1fce645..bde63e1 100644 --- a/src/cachekit/cache_handler.py +++ b/src/cachekit/cache_handler.py @@ -7,7 +7,6 @@ from __future__ import annotations import asyncio -import hashlib import threading import warnings from collections.abc import Callable @@ -29,6 +28,10 @@ ) from cachekit.config import ConfigurationError, get_settings from cachekit.di import DIContainer + +# Re-exported for backwards compatibility — redact_cache_key moved to the hash_utils +# leaf module so backend/L1 modules can redact without importing this module (cycle). +from cachekit.hash_utils import redact_cache_key from cachekit.interop import InteropError from cachekit.key_generator import CacheKeyGenerator from cachekit.serializers.base import ( @@ -76,16 +79,6 @@ def get_backend_provider(): return container.get(BackendProviderInterface) -def redact_cache_key(cache_key: object) -> str: - """Redact a cache key for log/error messages. - - Cache keys can embed caller-supplied tenant/user identifiers, so they must never reach - logs verbatim (issue #163). A fixed-length blake2b digest keeps messages correlatable - across the sync and async cache-set failure paths without leaking the key itself. - """ - return f"" - - # Lazy logger initialization to avoid import-time container access _logger = None @@ -1256,7 +1249,7 @@ def _notify_deserialize_error(self, error: Exception, cache_key: str) -> None: try: self.on_deserialize_error(error, cache_key) except Exception as hook_err: # observability must never break the miss path - get_logger().warning(f"on_deserialize_error hook failed for {cache_key}: {hook_err}") + get_logger().warning(f"on_deserialize_error hook failed for {redact_cache_key(cache_key)}: {hook_err}") def get_cache_key( self, @@ -1382,7 +1375,7 @@ def get_cached_value(self, cache_key: str, refresh_ttl: Optional[int] = None) -> self._handle_l2_read_error(e, cache_key) # raises when fail-closed (LAB-108) return None except Exception as e: - get_logger().warning(f"Backend operation failed for get on {cache_key}: {e}") + get_logger().warning(f"Backend operation failed for get on {redact_cache_key(cache_key)}: {e}") return None def get_cached_value_with_freshness(self, cache_key: str) -> Optional[tuple[tuple[bool, Any], bool]]: @@ -1502,7 +1495,7 @@ async def get_cached_value_async(self, cache_key: str, refresh_ttl: Optional[int await self._handle_l2_read_error_async(e, cache_key) # raises when fail-closed (LAB-108) return None except Exception as e: - get_logger().warning(f"Backend operation failed for get on {cache_key}: {e}") + get_logger().warning(f"Backend operation failed for get on {redact_cache_key(cache_key)}: {e}") return None def store_result( @@ -1714,9 +1707,9 @@ def invalidate_cache( self._backend.delete(cache_key) get_logger().cache_invalidated(cache_key, "Backend") except BackendError as e: - get_logger().error(f"Backend operation failed for invalidation on {cache_key}: {e}") + get_logger().error(f"Backend operation failed for invalidation on {redact_cache_key(cache_key)}: {e}") except Exception as e: - get_logger().error(f"Unexpected error invalidating {cache_key}: {e}") + get_logger().error(f"Unexpected error invalidating {redact_cache_key(cache_key)}: {e}") async def invalidate_cache_async( self, @@ -1746,9 +1739,9 @@ async def invalidate_cache_async( self._backend.delete(cache_key) get_logger().cache_invalidated(cache_key, "Backend") except BackendError as e: - get_logger().error(f"Backend operation failed for invalidation on {cache_key}: {e}") + get_logger().error(f"Backend operation failed for invalidation on {redact_cache_key(cache_key)}: {e}") except Exception as e: - get_logger().error(f"Unexpected error invalidating {cache_key}: {e}") + get_logger().error(f"Unexpected error invalidating {redact_cache_key(cache_key)}: {e}") @runtime_checkable @@ -1920,7 +1913,7 @@ async def _maybe_refresh_ttl(self, key: str, refresh_ttl: int) -> None: ) except Exception as e: # Log but don't fail the cache operation - get_logger().debug(f"Failed to refresh TTL for {key}: {e}") + get_logger().debug(f"Failed to refresh TTL for {redact_cache_key(key)}: {e}") def get(self, key: str, refresh_ttl: Optional[int] = None) -> Optional[bytes]: """Get value from cache using backend. @@ -1941,10 +1934,10 @@ def get(self, key: str, refresh_ttl: Optional[int] = None) -> Optional[bytes]: return value except BackendError as e: - get_logger().error(f"Backend error getting key {key}: {e}") + get_logger().error(f"Backend error getting key {redact_cache_key(key)}: {e}") return None except Exception as e: - get_logger().error(f"Unexpected error getting key {key}: {e}") + get_logger().error(f"Unexpected error getting key {redact_cache_key(key)}: {e}") return None def get_buffer(self, key: str) -> Optional[BufferHandle]: @@ -1958,10 +1951,10 @@ def get_buffer(self, key: str) -> Optional[BufferHandle]: try: return self._with_backpressure_and_timeout(self.backend.get_buffer, key) except BackendError as e: - get_logger().error(f"Backend error mmapping key {key}: {e}") + get_logger().error(f"Backend error mmapping key {redact_cache_key(key)}: {e}") return None except Exception as e: - get_logger().error(f"Unexpected error mmapping key {key}: {e}") + get_logger().error(f"Unexpected error mmapping key {redact_cache_key(key)}: {e}") return None def get_with_freshness(self, key: str) -> Optional[tuple[bytes, bool]]: @@ -2024,10 +2017,10 @@ def set( self._with_backpressure_and_timeout(self.backend.set, key, value, ttl) return True except BackendError as e: - get_logger().error(f"Backend error setting key {key}: {e}") + get_logger().error(f"Backend error setting key {redact_cache_key(key)}: {e}") return False except Exception as e: - get_logger().error(f"Unexpected error setting key {key}: {e}") + get_logger().error(f"Unexpected error setting key {redact_cache_key(key)}: {e}") return False def set_streaming(self, key: str, write_payload: Callable[[BinaryIO], None], ttl: Optional[int] = None) -> Optional[bool]: @@ -2083,10 +2076,10 @@ def delete(self, key: str) -> bool: try: return self._with_backpressure_and_timeout(self.backend.delete, key) except BackendError as e: - get_logger().error(f"Backend error deleting key {key}: {e}") + get_logger().error(f"Backend error deleting key {redact_cache_key(key)}: {e}") return False except Exception as e: - get_logger().error(f"Unexpected error deleting key {key}: {e}") + get_logger().error(f"Unexpected error deleting key {redact_cache_key(key)}: {e}") return False async def _with_backpressure_and_timeout_async(self, operation, *args, **kwargs): @@ -2120,10 +2113,10 @@ async def get_async(self, key: str, refresh_ttl: Optional[int] = None) -> Option return value except BackendError as e: - get_logger().error(f"Backend error getting key {key}: {e}") + get_logger().error(f"Backend error getting key {redact_cache_key(key)}: {e}") return None except Exception as e: - get_logger().error(f"Unexpected error getting key {key}: {e}") + get_logger().error(f"Unexpected error getting key {redact_cache_key(key)}: {e}") return None async def set_async( @@ -2147,10 +2140,10 @@ async def set_async( await self._with_backpressure_and_timeout_async(self.backend.set, key, value, ttl) return True except BackendError as e: - get_logger().error(f"Backend error setting key {key}: {e}") + get_logger().error(f"Backend error setting key {redact_cache_key(key)}: {e}") return False except Exception as e: - get_logger().error(f"Unexpected error setting key {key}: {e}") + get_logger().error(f"Unexpected error setting key {redact_cache_key(key)}: {e}") return False async def delete_async(self, key: str) -> bool: @@ -2162,8 +2155,8 @@ async def delete_async(self, key: str) -> bool: # Run sync backend operation in thread pool return await self._with_backpressure_and_timeout_async(self.backend.delete, key) except BackendError as e: - get_logger().error(f"Backend error deleting key {key}: {e}") + get_logger().error(f"Backend error deleting key {redact_cache_key(key)}: {e}") return False except Exception as e: - get_logger().error(f"Unexpected error deleting key {key}: {e}") + get_logger().error(f"Unexpected error deleting key {redact_cache_key(key)}: {e}") return False diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py index f71b4de..a15bcce 100644 --- a/src/cachekit/decorators/orchestrator.py +++ b/src/cachekit/decorators/orchestrator.py @@ -27,6 +27,9 @@ def _redact_key_for_log(cache_key: object) -> str: logs verbatim (CWE-532, issue #163). Real keys are canonical ``ns:...`` strings; sentinels (``unknown``, ````) and pre-redacted values (````) carry no caller data and stay readable as-is. + + The broad ``<...>`` match also makes redaction idempotent — handle_cache_error's + redacted output flows through log_cache_operation's redaction a second time. """ key_str = str(cache_key) if key_str == "unknown" or (key_str.startswith("<") and key_str.endswith(">")): diff --git a/src/cachekit/decorators/wrapper.py b/src/cachekit/decorators/wrapper.py index 76cf0c4..78bd836 100644 --- a/src/cachekit/decorators/wrapper.py +++ b/src/cachekit/decorators/wrapper.py @@ -1229,7 +1229,7 @@ def sync_wrapper(*args: Any, **kwargs: Any) -> Any: # noqa: PLR0912 raise except Exception as e: # L1 deserialization failed - invalidate and continue to L2 - logger().warning(f"L1 cache deserialization failed for {cache_key}: {e}") + logger().warning(f"L1 cache deserialization failed for {redact_cache_key(cache_key)}: {e}") _l1_cache.invalidate(cache_key) # Continue with the rest of the sync wrapper logic... @@ -1386,7 +1386,7 @@ def sync_wrapper(*args: Any, **kwargs: Any) -> Any: # noqa: PLR0912 features.handle_cache_error( error=e, operation="backend_connection", - cache_key=cache_key, + cache_key=cache_key or "unknown", namespace=namespace or "default", duration_ms=0.0, correlation_id=correlation_id, @@ -1577,7 +1577,7 @@ async def async_wrapper(*args: Any, **kwargs: Any) -> Any: raise except Exception as e: # L1 deserialization failed - invalidate and continue to L2 - logger().warning(f"L1 cache deserialization failed for {cache_key}: {e}") + logger().warning(f"L1 cache deserialization failed for {redact_cache_key(cache_key)}: {e}") _l1_cache.invalidate(cache_key) # Initialize backend only when needed (lazy init for performance) @@ -1661,7 +1661,7 @@ async def async_wrapper(*args: Any, **kwargs: Any) -> Any: task.add_done_callback(lambda t: _ttl_refresh_done_callback(t, cache_key)) except Exception as e: # TTL refresh is optional, don't fail on error - _logger.debug("TTL refresh failed for %s: %s", cache_key, e) + _logger.debug("TTL refresh failed for %s: %s", redact_cache_key(cache_key), e) elif refresh_ttl_on_get and ttl: # Backend can't inspect TTL: warn once instead of silently ignoring # the opted-in flag (LAB-446). Still degrades gracefully. @@ -1744,7 +1744,9 @@ async def async_wrapper(*args: Any, **kwargs: Any) -> Any: else: # Lock timeout - double-check cache before giving up # Another request may have populated it while we waited - logger().warning(f"Failed to acquire lock for {cache_key} after {blocking_timeout}s, checking cache") + logger().warning( + f"Failed to acquire lock for {redact_cache_key(cache_key)} after {blocking_timeout}s, checking cache" + ) try: # Routed through get_cached_value_async: corrupt entries evict (#159) cached_result = await operation_handler.get_cached_value_async(cache_key) @@ -1769,7 +1771,7 @@ async def async_wrapper(*args: Any, **kwargs: Any) -> Any: except Exception: # Cache check failed - fall through to execute function logger().warning( - f"Cache check after lock timeout failed for {cache_key}, executing without lock" + f"Cache check after lock timeout failed for {redact_cache_key(cache_key)}, executing without lock" ) # Execute the original function (with or without lock) @@ -1846,12 +1848,14 @@ async def async_wrapper(*args: Any, **kwargs: Any) -> Any: raise e.original_exception from e # Lock operation failed - execute without lock - logger().warning(f"Lock operation failed for {cache_key}, executing without lock: {e}") + logger().warning(f"Lock operation failed for {redact_cache_key(cache_key)}, executing without lock: {e}") # Fall through to execute without locking # Execute without locking (either backend doesn't support it or lock failed) if not hasattr(_backend, "acquire_lock"): - logger().debug(f"Backend doesn't support locking for {cache_key}, executing without thundering herd protection") + logger().debug( + f"Backend doesn't support locking for {redact_cache_key(cache_key)}, executing without thundering herd protection" + ) try: # Execute the original function @@ -1944,7 +1948,7 @@ def invalidate_cache(*args: Any, **kwargs: Any) -> None: try: _backend.delete(key) except Exception as e: - _logger.debug("Failed to delete L2 key %s: %s", key, e) + _logger.debug("Failed to delete L2 key %s: %s", redact_cache_key(key), e) continue # keep key tracked for retry _cached_keys.discard(key) return @@ -1971,7 +1975,7 @@ def invalidate_cache(*args: Any, **kwargs: Any) -> None: try: _backend.delete(cache_key) except Exception as e: - _logger.error("Failed to delete L2 interop key %s: %s", cache_key, e) + _logger.error("Failed to delete L2 interop key %s: %s", redact_cache_key(cache_key), e) else: invalidator.invalidate_cache(func, args, kwargs, namespace) @@ -2002,7 +2006,7 @@ async def ainvalidate_cache(*args: Any, **kwargs: Any) -> None: try: _backend.delete(key) except Exception as e: - _logger.debug("Failed to delete L2 key %s: %s", key, e) + _logger.debug("Failed to delete L2 key %s: %s", redact_cache_key(key), e) continue _cached_keys.discard(key) return @@ -2030,7 +2034,7 @@ async def ainvalidate_cache(*args: Any, **kwargs: Any) -> None: try: _backend.delete(cache_key) except Exception as e: - _logger.error("Failed to delete L2 interop key %s: %s", cache_key, e) + _logger.error("Failed to delete L2 interop key %s: %s", redact_cache_key(cache_key), e) else: await invalidator.invalidate_cache_async(func, args, kwargs, namespace) diff --git a/src/cachekit/hash_utils.py b/src/cachekit/hash_utils.py index 235a5be..ec6f318 100644 --- a/src/cachekit/hash_utils.py +++ b/src/cachekit/hash_utils.py @@ -3,11 +3,25 @@ Uses BLAKE3 for hashing (approximately 2-3 GB/s throughput). """ +import hashlib from typing import Union import blake3 +def redact_cache_key(cache_key: object) -> str: + """Redact a cache key for log/error messages. + + Cache keys can embed caller-supplied tenant/user identifiers, so they must never reach + logs verbatim (issue #163). A fixed-length blake2b digest keeps messages correlatable + across the sync and async cache-set failure paths without leaking the key itself. + + Lives in this leaf module so backend/L1 modules can use it without importing + cache_handler (which imports them). + """ + return f"" + + def fast_hash(data: Union[str, bytes], digest_size: int = 8) -> str: """Ultra-fast hash using BLAKE3 - optimized for hot paths. diff --git a/src/cachekit/l1_cache.py b/src/cachekit/l1_cache.py index 845d4ec..5b67f33 100644 --- a/src/cachekit/l1_cache.py +++ b/src/cachekit/l1_cache.py @@ -12,6 +12,8 @@ from dataclasses import dataclass from typing import Any, Optional +from cachekit.hash_utils import redact_cache_key + logger = logging.getLogger(__name__) @@ -182,7 +184,11 @@ def put( # Skip caching if the effective TTL is non-finite (NaN/inf would create an # immortal entry that never expires) or too short (would expire immediately). if not math.isfinite(expiry) or expiry <= current_time: - logger.debug("Skipping L1 cache for key %s - non-finite or too-short TTL (effective expiry: %r)", key, expiry) + logger.debug( + "Skipping L1 cache for key %s - non-finite or too-short TTL (effective expiry: %r)", + redact_cache_key(key), + expiry, + ) return # Estimate size diff --git a/tests/unit/backends/test_provider.py b/tests/unit/backends/test_provider.py index 98ddf21..96e1b1a 100644 --- a/tests/unit/backends/test_provider.py +++ b/tests/unit/backends/test_provider.py @@ -25,6 +25,7 @@ LoggerProvider, SimpleLogger, ) +from cachekit.hash_utils import redact_cache_key # noqa: I001 @pytest.mark.unit @@ -117,7 +118,7 @@ def test_cache_hit_default_source(self) -> None: logger.cache_hit("key:123") - mock_logger.debug.assert_called_once_with("Redis cache hit for key: key:123") + mock_logger.debug.assert_called_once_with(f"Redis cache hit for key: {redact_cache_key('key:123')}") def test_cache_hit_custom_source(self) -> None: """Test cache hit logging with custom source.""" @@ -126,7 +127,7 @@ def test_cache_hit_custom_source(self) -> None: logger.cache_hit("key:456", source="Memcached") - mock_logger.debug.assert_called_once_with("Memcached cache hit for key: key:456") + mock_logger.debug.assert_called_once_with(f"Memcached cache hit for key: {redact_cache_key('key:456')}") def test_cache_miss(self) -> None: """Test cache miss logging.""" @@ -135,7 +136,7 @@ def test_cache_miss(self) -> None: logger.cache_miss("key:789") - mock_logger.debug.assert_called_once_with("Cache miss for key: key:789") + mock_logger.debug.assert_called_once_with(f"Cache miss for key: {redact_cache_key('key:789')}") def test_cache_stored_without_ttl(self) -> None: """Test cache storage logging without TTL.""" @@ -144,7 +145,7 @@ def test_cache_stored_without_ttl(self) -> None: logger.cache_stored("key:111") - mock_logger.debug.assert_called_once_with("Cached result for key: key:111") + mock_logger.debug.assert_called_once_with(f"Cached result for key: {redact_cache_key('key:111')}") def test_cache_stored_with_ttl(self) -> None: """Test cache storage logging with TTL.""" @@ -153,7 +154,7 @@ def test_cache_stored_with_ttl(self) -> None: logger.cache_stored("key:222", ttl=3600) - mock_logger.debug.assert_called_once_with("Cached result for key: key:222 with TTL 3600") + mock_logger.debug.assert_called_once_with(f"Cached result for key: {redact_cache_key('key:222')} with TTL 3600") def test_cache_invalidated_default_source(self) -> None: """Test cache invalidation logging with default source.""" @@ -162,7 +163,7 @@ def test_cache_invalidated_default_source(self) -> None: logger.cache_invalidated("key:333") - mock_logger.debug.assert_called_once_with("Invalidated Redis cache for key: key:333") + mock_logger.debug.assert_called_once_with(f"Invalidated Redis cache for key: {redact_cache_key('key:333')}") def test_cache_invalidated_custom_source(self) -> None: """Test cache invalidation logging with custom source.""" @@ -171,7 +172,7 @@ def test_cache_invalidated_custom_source(self) -> None: logger.cache_invalidated("key:444", source="L1") - mock_logger.debug.assert_called_once_with("Invalidated L1 cache for key: key:444") + mock_logger.debug.assert_called_once_with(f"Invalidated L1 cache for key: {redact_cache_key('key:444')}") @pytest.mark.unit diff --git a/tests/unit/test_wrapper_lock_bare_key.py b/tests/unit/test_wrapper_lock_bare_key.py index 85c3447..f7096c0 100644 --- a/tests/unit/test_wrapper_lock_bare_key.py +++ b/tests/unit/test_wrapper_lock_bare_key.py @@ -33,6 +33,7 @@ import pytest from cachekit import cache +from cachekit.hash_utils import redact_cache_key class _RecordingLockableBackend: @@ -196,14 +197,16 @@ async def my_func(x: int) -> dict[str, int]: assert len(backend.lock_keys) == 1 bare_key = backend.lock_keys[0] - # The warning must reference the bare cache_key (no ``:lock`` smuggled in) - # so operators reading logs see the same key shape that ``get``/``set`` use. + # The warning must reference the redacted digest of the BARE cache_key — + # a ``:lock``-suffixed key would digest differently, so the bare-key + # contract is still pinned. Raw keys never reach logs (CWE-532, LAB-304). timeout_warnings = [r for r in caplog.records if "Failed to acquire lock" in r.message] assert len(timeout_warnings) == 1, ( f"expected exactly one lock-timeout warning; got {[r.message for r in caplog.records]!r}" ) msg = timeout_warnings[0].message - assert bare_key in msg, f"warning must name the bare cache_key {bare_key!r}; got {msg!r}" + assert redact_cache_key(bare_key) in msg, f"warning must name the bare cache_key's digest; got {msg!r}" + assert bare_key not in msg, f"warning leaked the raw cache_key: {msg!r}" assert ":lock" not in msg, f"warning leaked ':lock' suffix: {msg!r}" @@ -238,14 +241,16 @@ async def my_func(x: int) -> dict[str, int]: assert len(backend.lock_keys) == 1 bare_key = backend.lock_keys[0] - # The lock-operation-failed warning must reference the bare cache_key — - # not a ``:lock``-suffixed variant — matching the protocol contract. + # The lock-operation-failed warning must reference the redacted digest of + # the bare cache_key — a ``:lock``-suffixed key would digest differently. + # Raw keys never reach logs (CWE-532, LAB-304). lock_failed_warnings = [r for r in caplog.records if "Lock operation failed" in r.message] assert len(lock_failed_warnings) == 1, ( f"expected one lock-operation-failed warning; got {[r.message for r in caplog.records]!r}" ) msg = lock_failed_warnings[0].message - assert bare_key in msg, f"warning must name the bare cache_key {bare_key!r}; got {msg!r}" + assert redact_cache_key(bare_key) in msg, f"warning must name the bare cache_key's digest; got {msg!r}" + assert bare_key not in msg, f"warning leaked the raw cache_key: {msg!r}" assert ":lock" not in msg, f"warning leaked ':lock' suffix: {msg!r}" From 238f4a41c6181d57c32021a8f93369d32ec6fe35 Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Mon, 31 Aug 2026 02:40:33 +1000 Subject: [PATCH 3/8] chore: remove stray review-scratch diff file (LAB-304) --- lab304.diff | 224 ---------------------------------------------------- 1 file changed, 224 deletions(-) delete mode 100644 lab304.diff diff --git a/lab304.diff b/lab304.diff deleted file mode 100644 index a4b8e2f..0000000 --- a/lab304.diff +++ /dev/null @@ -1,224 +0,0 @@ -diff --git a/SECURITY.md b/SECURITY.md -index 008160a..28f6f23 100644 ---- a/SECURITY.md -+++ b/SECURITY.md -@@ -187,6 +187,10 @@ When using `@cache.io` (CachekitIOBackend), the SDK includes built-in Server-Sid - - See [SSRF Protection](docs/features/ssrf-protection.md) for full details, including custom host configuration for development environments. - -+### Cache Key Redaction in Logs (CWE-532) -+ -+Cache keys can embed caller-supplied tenant/user identifiers, so they never reach logs verbatim ([CWE-532][cwe-532]). Every 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. -+ - ### Lock Token Transport (CWE-532) - - The distributed-lock capability token (`lock_id`) is sent in the `X-CacheKit-Lock-Id` request header when releasing a lock (`DELETE /v1/cache/{key}/lock`), **never** in the URL query string. Query strings are routinely captured by access logs, proxy/CDN logs, and OpenTelemetry `http.url` spans ([CWE-532][cwe-532]); a leaked token could be replayed to release a lock within its short TTL. The CacheKit SaaS backend dual-reads the header and the legacy `?lock_id=` query during migration, preferring the header (removed in protocol 2.0). -diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py -index 66abbc2..f71b4de 100644 ---- a/src/cachekit/decorators/orchestrator.py -+++ b/src/cachekit/decorators/orchestrator.py -@@ -3,6 +3,7 @@ import logging - import uuid - from typing import Any, Optional - -+from ..cache_handler import redact_cache_key - from ..monitoring.correlation_tracking import CorrelationTracker - from ..monitoring.pool_monitor import OptimizedPoolMonitor - -@@ -19,6 +20,20 @@ logger = logging.getLogger(__name__) - _operation_context: contextvars.ContextVar[Optional[dict[str, Any]]] = contextvars.ContextVar("operation_context", default=None) - - -+def _redact_key_for_log(cache_key: object) -> str: -+ """Redact a cache key for logging unless it is a sentinel or already redacted. -+ -+ Cache keys embed caller-supplied tenant/user identifiers and must never reach -+ logs verbatim (CWE-532, issue #163). Real keys are canonical ``ns:...`` strings; -+ sentinels (``unknown``, ````) and pre-redacted values -+ (````) carry no caller data and stay readable as-is. -+ """ -+ key_str = str(cache_key) -+ if key_str == "unknown" or (key_str.startswith("<") and key_str.endswith(">")): -+ return key_str -+ return redact_cache_key(key_str) -+ -+ - class FeatureOrchestrator: - """Orchestrates existing reliability and monitoring features. - -@@ -271,9 +286,12 @@ class FeatureOrchestrator: - pass - - def log_cache_operation(self, **kwargs): -- """Log cache operation with structured logging.""" -+ """Log cache operation with structured logging. Redacts ``key`` (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"]) - key = kwargs.get("key", "unknown") - self.log_structured("info", f"Cache operation: {operation}", cache_key=key, **kwargs) - -@@ -414,7 +432,8 @@ class FeatureOrchestrator: - Args: - error: The exception that occurred - operation: Operation type (e.g., "key_generation", "cache_get", "cache_set") -- cache_key: Cache key involved (use "unknown" if unavailable) -+ cache_key: Cache key involved (use "unknown" if unavailable). Pass the -+ raw key — it is redacted here before any logging (CWE-532). - namespace: Cache namespace (defaults to orchestrator namespace) - span: Optional tracing span for recording - duration_ms: Operation duration in milliseconds -@@ -433,6 +452,10 @@ class FeatureOrchestrator: - # Use orchestrator namespace if not provided - namespace = namespace or self.namespace - -+ # Redact once at the sink so every error path is covered by construction -+ # (CWE-532) — callers pass the raw key; sentinels pass through readable. -+ cache_key = _redact_key_for_log(cache_key) -+ - # 1. Record exception in span and metrics - if span: - self.record_exception(span, error) -diff --git a/src/cachekit/decorators/wrapper.py b/src/cachekit/decorators/wrapper.py -index f84847a..76cf0c4 100644 ---- a/src/cachekit/decorators/wrapper.py -+++ b/src/cachekit/decorators/wrapper.py -@@ -1373,7 +1373,7 @@ def create_cache_wrapper( - features.handle_cache_error( - error=e, - operation="cache_set", -- cache_key=redact_cache_key(cache_key) if cache_key else "unknown", -+ cache_key=cache_key or "unknown", - namespace=namespace or "default", - duration_ms=set_duration_ms, - serializer="rust", -@@ -1815,7 +1815,7 @@ def create_cache_wrapper( - features.handle_cache_error( - error=e, - operation="cache_set", -- cache_key=redact_cache_key(cache_key) if cache_key else "unknown", -+ cache_key=cache_key or "unknown", - namespace=namespace or "default", - duration_ms=set_duration_ms, - correlation_id=correlation_id, -@@ -1897,7 +1897,7 @@ def create_cache_wrapper( - features.handle_cache_error( - error=e, - operation="cache_set", -- cache_key=redact_cache_key(cache_key) if cache_key else "unknown", -+ cache_key=cache_key or "unknown", - namespace=namespace or "default", - duration_ms=set_duration_ms, - correlation_id=correlation_id, -diff --git a/tests/unit/test_orchestrator_error_handling.py b/tests/unit/test_orchestrator_error_handling.py -index bbd0ed1..b462176 100644 ---- a/tests/unit/test_orchestrator_error_handling.py -+++ b/tests/unit/test_orchestrator_error_handling.py -@@ -4,8 +4,11 @@ Tests the error handling orchestration without test theatre - validates - actual behavior and contracts, not implementation details. - """ - -+import logging -+ - import pytest - -+from cachekit.cache_handler import redact_cache_key - from cachekit.decorators.orchestrator import FeatureOrchestrator - - -@@ -271,3 +274,93 @@ class TestErrorHandlerEdgeCases: - ) - - # Test passes if no exception -+ -+ -+class TestCacheKeyRedaction: -+ """Raw cache keys must never reach logs on any error path (CWE-532, LAB-304). -+ -+ Keys embed caller-supplied tenant/user identifiers; the sink redacts once so -+ every caller is covered by construction. -+ """ -+ -+ # A canonical key carrying a tenant-identifying argument digest segment -+ TENANT_KEY = "ns:prod:func:app.get_user:args:tenant-42-alice-secret:v1" -+ -+ def _orchestrator(self) -> FeatureOrchestrator: -+ return FeatureOrchestrator( -+ namespace="test", -+ circuit_breaker_enabled=False, -+ enable_structured_logging=True, -+ ) -+ -+ @pytest.mark.parametrize("operation", ["cache_get", "key_generation", "backend_connection", "client_creation"]) -+ def test_non_cache_set_failure_never_logs_raw_key(self, operation: str, caplog: pytest.LogCaptureFixture) -> None: -+ """The tenant key must not appear verbatim in any log record — structured or backwards-compat.""" -+ with caplog.at_level(logging.INFO): -+ self._orchestrator().handle_cache_error( -+ error=ConnectionError("backend down"), -+ operation=operation, -+ cache_key=self.TENANT_KEY, -+ duration_ms=1.0, -+ ) -+ -+ assert caplog.records, "error handler must log" -+ for record in caplog.records: -+ assert self.TENANT_KEY not in record.getMessage() -+ structured = getattr(record, "structured", None) -+ if structured is not None: -+ assert self.TENANT_KEY not in str(structured) -+ -+ def test_backwards_compat_log_carries_correlatable_digest(self, caplog: pytest.LogCaptureFixture) -> None: -+ """Redaction keeps failures correlatable: the blake2b digest replaces the raw key.""" -+ with caplog.at_level(logging.WARNING): -+ self._orchestrator().handle_cache_error( -+ error=ConnectionError("backend down"), -+ operation="cache_get", -+ cache_key=self.TENANT_KEY, -+ ) -+ -+ digest = redact_cache_key(self.TENANT_KEY) -+ assert any(digest in record.getMessage() for record in caplog.records) -+ -+ def test_cache_set_digest_unchanged_from_lab_109(self, caplog: pytest.LogCaptureFixture) -> None: -+ """cache_set callers now pass the raw key; the sink must emit the SAME digest -+ the call-site redaction produced before (LAB-109 behaviour intact).""" -+ with caplog.at_level(logging.WARNING): -+ self._orchestrator().handle_cache_error( -+ error=OSError("disk full"), -+ operation="cache_set", -+ cache_key=self.TENANT_KEY, -+ ) -+ -+ digest = redact_cache_key(self.TENANT_KEY) -+ assert any(digest in record.getMessage() for record in caplog.records) -+ assert not any(self.TENANT_KEY in record.getMessage() for record in caplog.records) -+ -+ @pytest.mark.parametrize("sentinel", ["unknown", "", ""]) -+ def test_sentinels_pass_through_unredacted(self, sentinel: str, caplog: pytest.LogCaptureFixture) -> None: -+ """Non-key sentinels carry no caller data and stay readable (no double-redaction).""" -+ with caplog.at_level(logging.WARNING): -+ self._orchestrator().handle_cache_error( -+ error=ValueError("boom"), -+ operation="key_generation", -+ cache_key=sentinel, -+ ) -+ -+ assert any(sentinel in record.getMessage() for record in caplog.records) -+ -+ def test_structured_log_cache_operation_redacts_key(self, caplog: pytest.LogCaptureFixture) -> None: -+ """Direct log_cache_operation callers (circuit-breaker, hit logs) are covered too.""" -+ with caplog.at_level(logging.INFO): -+ self._orchestrator().log_cache_operation( -+ operation="circuit_breaker_open", -+ key=self.TENANT_KEY, -+ error="Circuit breaker is OPEN", -+ ) -+ -+ assert caplog.records -+ for record in caplog.records: -+ assert self.TENANT_KEY not in record.getMessage() -+ structured = getattr(record, "structured", None) -+ if structured is not None: -+ assert self.TENANT_KEY not in str(structured) From fdafd01f63505818c63397a653a5b775051df29d Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Mon, 31 Aug 2026 02:59:31 +1000 Subject: [PATCH 4/8] fix(logging): cover error-path redaction with tests; bump pip floor for PYSEC-2026-3721 (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - New tests/unit/test_error_path_key_redaction.py drives backend set/delete/invalidation/TTL-refresh failures and asserts the key appears only as its digest (also lifts patch coverage over the 80% codecov gate — these error paths were previously untested). - Redact the multiline 'Refreshed TTL for' debug log that the tree sweep missed (f-string on the continuation line). - pip>=26.2 (dev-only transitive dep via pip-audit): fixes PYSEC-2026-3721, which failed the Python Dependency CVEs check; unrelated to this diff but blocking its CI. --- pyproject.toml | 9 +- src/cachekit/cache_handler.py | 2 +- tests/unit/test_error_path_key_redaction.py | 149 ++++++++++++++++++++ uv.lock | 8 +- 4 files changed, 159 insertions(+), 9 deletions(-) create mode 100644 tests/unit/test_error_path_key_redaction.py diff --git a/pyproject.toml b/pyproject.toml index 3860e79..4b74fa9 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -247,10 +247,11 @@ constraint-dependencies = [ "urllib3>=2.7.0", "fonttools>=4.60.2", "werkzeug>=3.1.4", - # pip is a dev-only transitive dep (pip-audit -> pip-api -> pip). 26.1.2 fixes - # PYSEC-2026-196 (entry-point path traversal), GHSA-58qw-9mgm-455v (tar/zip - # confusion) and GHSA-jp4c-xjxw-mgf9 (self-update import ordering). - "pip>=26.1.2", + # pip is a dev-only transitive dep (pip-audit -> pip-api -> pip). 26.2 fixes + # PYSEC-2026-3721; 26.1.2 fixed PYSEC-2026-196 (entry-point path traversal), + # GHSA-58qw-9mgm-455v (tar/zip confusion) and GHSA-jp4c-xjxw-mgf9 (self-update + # import ordering). + "pip>=26.2", # h2 is a transitive dep (httpx[http2] -> h2). 4.4.1 fixes # GHSA-6hr6-w5qg-qmwg (duplicate Host headers forwarded on HTTP/2 -> # HTTP/1.1 downgrade — request smuggling primitive). diff --git a/src/cachekit/cache_handler.py b/src/cachekit/cache_handler.py index bde63e1..79f4d87 100644 --- a/src/cachekit/cache_handler.py +++ b/src/cachekit/cache_handler.py @@ -1908,7 +1908,7 @@ async def _maybe_refresh_ttl(self, key: str, refresh_ttl: int) -> None: if remaining_ttl is not None and remaining_ttl < refresh_ttl * self.ttl_refresh_threshold: await self.backend.refresh_ttl(key, refresh_ttl) get_logger().debug( - f"Refreshed TTL for {key}: {refresh_ttl}s " + f"Refreshed TTL for {redact_cache_key(key)}: {refresh_ttl}s " f"(remaining: {remaining_ttl}s, threshold: {self.ttl_refresh_threshold})" ) except Exception as e: diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py new file mode 100644 index 0000000..b187ed3 --- /dev/null +++ b/tests/unit/test_error_path_key_redaction.py @@ -0,0 +1,149 @@ +"""Error-path log redaction for backend operations (CWE-532, LAB-304). + +Companion to ``tests/unit/test_orchestrator_error_handling.py``'s +``TestCacheKeyRedaction``: that file pins the decorator error sink; this file +pins the direct logger calls in ``cache_handler.py`` — backend set/delete +failures, invalidation failures, and TTL-refresh failures. Each test drives a +real failure and asserts the tenant-identifying key appears only as its +blake2b digest, never verbatim. +""" + +from __future__ import annotations + +import logging +from typing import Any, Optional + +import pytest + +from cachekit.backends.errors import BackendError, BackendErrorType +from cachekit.cache_handler import CacheInvalidator, StandardCacheHandler +from cachekit.hash_utils import redact_cache_key +from cachekit.key_generator import CacheKeyGenerator + +TENANT_KEY = "ns:tenant-42-alice-secret:func:app.get_user:args:deadbeef:v1" + + +class _FailingBackend: + """Minimal BaseBackend whose mutating operations raise a configured error.""" + + def __init__(self, error: Exception) -> None: + self._error = error + self.received_keys: list[str] = [] + + def get(self, key: str) -> Optional[bytes]: + self.received_keys.append(key) + raise self._error + + def set(self, key: str, value: bytes, ttl: Optional[int] = None) -> None: + self.received_keys.append(key) + raise self._error + + def delete(self, key: str) -> bool: + self.received_keys.append(key) + raise self._error + + def exists(self, key: str) -> bool: + return False + + def health_check(self) -> tuple[bool, dict[str, Any]]: + return True, {"backend_type": "failing"} + + +class _FailingTTLBackend(_FailingBackend): + """Adds TTL inspection so supports_ttl_inspection() passes; get_ttl raises.""" + + async def get_ttl(self, key: str) -> Optional[int]: + self.received_keys.append(key) + raise self._error + + async def refresh_ttl(self, key: str, ttl: int) -> bool: + raise self._error + + +def _assert_redacted(caplog: pytest.LogCaptureFixture, raw_key: str) -> None: + """The digest must appear in some record; the raw key in none.""" + digest = redact_cache_key(raw_key) + messages = [r.getMessage() for r in caplog.records] + assert any(digest in m for m in messages), f"expected digest {digest!r} in logs; got {messages!r}" + assert not any(raw_key in m for m in messages), f"raw key leaked into logs: {messages!r}" + + +class TestStandardCacheHandlerRedaction: + """set/delete/TTL-refresh failures log the digest, never the raw key.""" + + @pytest.mark.parametrize( + "error", + [BackendError("backend down", error_type=BackendErrorType.TRANSIENT), ValueError("unexpected")], + ids=["backend_error", "unexpected_error"], + ) + def test_set_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + handler = StandardCacheHandler(backend=_FailingBackend(error)) + + with caplog.at_level(logging.ERROR): + assert handler.set(TENANT_KEY, b"value", ttl=60) is False + + _assert_redacted(caplog, TENANT_KEY) + + @pytest.mark.parametrize( + "error", + [BackendError("backend down", error_type=BackendErrorType.TRANSIENT), ValueError("unexpected")], + ids=["backend_error", "unexpected_error"], + ) + def test_delete_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + handler = StandardCacheHandler(backend=_FailingBackend(error)) + + with caplog.at_level(logging.ERROR): + assert handler.delete(TENANT_KEY) is False + + _assert_redacted(caplog, TENANT_KEY) + + async def test_ttl_refresh_failure_redacts_key(self, caplog: pytest.LogCaptureFixture) -> None: + """get_ttl raising must not fail the operation — and must log only the digest.""" + handler = StandardCacheHandler(backend=_FailingTTLBackend(ValueError("ttl probe failed"))) + + with caplog.at_level(logging.DEBUG): + await handler._maybe_refresh_ttl(TENANT_KEY, refresh_ttl=300) + + _assert_redacted(caplog, TENANT_KEY) + + +class TestCacheInvalidatorRedaction: + """Invalidation failures (sync + async) log the digest of the generated key.""" + + def _invalidator(self, error: Exception) -> tuple[CacheInvalidator, _FailingBackend]: + backend = _FailingBackend(error) + return CacheInvalidator(key_generator=CacheKeyGenerator(), backend=backend), backend + + @pytest.mark.parametrize( + "error", + [BackendError("backend down", error_type=BackendErrorType.TRANSIENT), ValueError("unexpected")], + ids=["backend_error", "unexpected_error"], + ) + def test_sync_invalidation_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + invalidator, backend = self._invalidator(error) + + def cached_func(user: str) -> str: + return user + + with caplog.at_level(logging.ERROR): + invalidator.invalidate_cache(cached_func, ("alice",), {}, namespace="tenant-42-secret") + + assert len(backend.received_keys) == 1 + _assert_redacted(caplog, backend.received_keys[0]) + + @pytest.mark.parametrize( + "error", + [BackendError("backend down", error_type=BackendErrorType.TRANSIENT), ValueError("unexpected")], + ids=["backend_error", "unexpected_error"], + ) + async def test_async_invalidation_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + invalidator, backend = self._invalidator(error) + + def cached_func(user: str) -> str: + return user + + with caplog.at_level(logging.ERROR): + await invalidator.invalidate_cache_async(cached_func, ("alice",), {}, namespace="tenant-42-secret") + + assert len(backend.received_keys) == 1 + _assert_redacted(caplog, backend.received_keys[0]) diff --git a/uv.lock b/uv.lock index 4f9df25..0281576 100644 --- a/uv.lock +++ b/uv.lock @@ -11,7 +11,7 @@ resolution-markers = [ constraints = [ { name = "fonttools", specifier = ">=4.60.2" }, { name = "h2", specifier = ">=4.4.1" }, - { name = "pip", specifier = ">=26.1.2" }, + { name = "pip", specifier = ">=26.2" }, { name = "urllib3", specifier = ">=2.7.0" }, { name = "werkzeug", specifier = ">=3.1.4" }, ] @@ -1283,11 +1283,11 @@ wheels = [ [[package]] name = "pip" -version = "26.1.2" +version = "26.2.1" source = { registry = "https://pypi.org/simple" } -sdist = { url = "https://files.pythonhosted.org/packages/01/91/47e7d486260f618783899587af63ccf7980fb60245c3e63dd4571c6b57ad/pip-26.1.2.tar.gz", hash = "sha256:f49cd134c61cf2fd75e0ce2676db03e4054504a5a4986d00f8299ae632dc4605", size = 1840799, upload-time = "2026-05-31T17:33:58.56Z" } +sdist = { url = "https://files.pythonhosted.org/packages/ae/15/4500e320e6b101ec3b719ae85b697d9940b6cda672bc555bd6016fc60c6f/pip-26.2.1.tar.gz", hash = "sha256:f6ad667e89a1fe78046c8f13232b247200f5258d7828f3f7883d660878e0813f", size = 1848877, upload-time = "2026-08-04T22:51:14.148Z" } wheels = [ - { url = "https://files.pythonhosted.org/packages/5d/95/6b5cb3461ea5673ba0995989746db58eb18b91b54dbf331e72f569540946/pip-26.1.2-py3-none-any.whl", hash = "sha256:382ff9f685ee3bc25864f820aa50505825f10f5458ffff07e30a6d96e5715cab", size = 1813144, upload-time = "2026-05-31T17:33:56.772Z" }, + { url = "https://files.pythonhosted.org/packages/f3/6e/1736e5b4ae2b778ef2f81c47d797de9f891d4d8acb047a24ca37a60294dd/pip-26.2.1-py3-none-any.whl", hash = "sha256:71138adf1f4ca900cdb7d289c21b7494329f2332b6d85f0e1c42108c0384ed3e", size = 1816632, upload-time = "2026-08-04T22:51:12.472Z" }, ] [[package]] From 352f828394f1794a86cef4b09bb89e8edeff150c Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Mon, 31 Aug 2026 03:23:04 +1000 Subject: [PATCH 5/8] =?UTF-8?q?fix:=20address=20coderabbit=20review=20?= =?UTF-8?q?=E2=80=94=20redact=20BackendError=20key=20in=20exception=20text?= =?UTF-8?q?;=20strict=20log=20pass-through?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit BackendError._format_message() now embeds the redacted digest instead of a 50-char raw-key prefix, making every downstream {e} interpolation safe by construction (orchestrator sinks, cache_handler sinks, wrapper lock warning). _redact_key_for_log() pass-through narrowed from any <...> string to an explicit sentinel allow-list plus the exact format. CodeRabbit-Resolved: orchestrator.py:36:Restrict the angle-bracket pass CodeRabbit-Resolved: orchestrator.py:460:Sanitise BackendError text bef CodeRabbit-Resolved: wrapper.py:1851:Sanitise lock-operation except --- src/cachekit/backends/errors.py | 14 +++-- src/cachekit/decorators/orchestrator.py | 22 +++++-- .../test_backend_error_handling.py | 24 ++++---- tests/integration/test_redis_backend.py | 6 +- tests/unit/test_backend_protocol.py | 19 +++--- tests/unit/test_error_path_key_redaction.py | 33 +++++++++++ .../unit/test_orchestrator_error_handling.py | 58 ++++++++++++++++++- tests/unit/test_wrapper_lock_bare_key.py | 50 ++++++++++++++++ 8 files changed, 195 insertions(+), 31 deletions(-) diff --git a/src/cachekit/backends/errors.py b/src/cachekit/backends/errors.py index 80ff1a1..82665ba 100644 --- a/src/cachekit/backends/errors.py +++ b/src/cachekit/backends/errors.py @@ -10,6 +10,8 @@ from enum import Enum from typing import Optional +from ..hash_utils import redact_cache_key + class BackendErrorType(str, Enum): """Error classification for circuit breaker and retry decisions. @@ -52,7 +54,9 @@ class BackendError(Exception): error_type: Error classification (see BackendErrorType) original_exception: The original exception that caused this error (if any) operation: The operation that failed (get, set, delete, exists) - key: The cache key involved in the operation (optional, for debugging) + key: The cache key involved in the operation (optional, for debugging). + Kept raw on the attribute for programmatic access; the formatted + exception text carries only its redacted digest (CWE-532). Example: >>> from redis import ConnectionError as RedisConnectionError @@ -99,9 +103,11 @@ def _format_message(self) -> str: if self.operation: parts.append(f"operation={self.operation}") if self.key: - # Truncate key for security/readability - key_display = self.key[:50] + "..." if len(self.key) > 50 else self.key - parts.append(f"key={key_display}") + # Redact, don't truncate: str(e) reaches log interpolation at every + # error sink, and cache keys embed caller-supplied tenant/user + # identifiers (CWE-532, LAB-304). The fixed-length digest keeps the + # message correlatable with the sinks' own redact_cache_key() output. + parts.append(f"key={redact_cache_key(self.key)}") if self.error_type: parts.append(f"type={self.error_type.value}") return " | ".join(parts) diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py index a15bcce..c0edcce 100644 --- a/src/cachekit/decorators/orchestrator.py +++ b/src/cachekit/decorators/orchestrator.py @@ -1,5 +1,6 @@ import contextvars import logging +import re import uuid from typing import Any, Optional @@ -20,19 +21,28 @@ _operation_context: contextvars.ContextVar[Optional[dict[str, Any]]] = contextvars.ContextVar("operation_context", default=None) +# Only values that provably carry no caller data pass through unredacted: the +# known sentinels, and the exact output format of redact_cache_key(). A broad +# "<...>" match would let a raw key like "" through. +_SENTINEL_KEYS = frozenset({"unknown", ""}) +_REDACTED_KEY_RE = re.compile(r"\Z") + + def _redact_key_for_log(cache_key: object) -> str: - """Redact a cache key for logging unless it is a sentinel or already redacted. + """Redact a cache key for logging unless it is a known sentinel or already redacted. Cache keys embed caller-supplied tenant/user identifiers and must never reach logs verbatim (CWE-532, issue #163). Real keys are canonical ``ns:...`` strings; - sentinels (``unknown``, ````) and pre-redacted values - (````) carry no caller data and stay readable as-is. + sentinels (``unknown``, ````) and redact_cache_key() output + (````) carry no caller data and stay readable as-is. - The broad ``<...>`` match also makes redaction idempotent — handle_cache_error's - redacted output flows through log_cache_operation's redaction a second time. + Matching the strict generated format keeps redaction idempotent — + handle_cache_error's redacted output flows through log_cache_operation's + redaction a second time — without opening a pass-through for arbitrary + angle-bracketed strings. """ key_str = str(cache_key) - if key_str == "unknown" or (key_str.startswith("<") and key_str.endswith(">")): + if key_str in _SENTINEL_KEYS or _REDACTED_KEY_RE.fullmatch(key_str): return key_str return redact_cache_key(key_str) diff --git a/tests/integration/test_backend_error_handling.py b/tests/integration/test_backend_error_handling.py index c5bc6d9..2667aaa 100644 --- a/tests/integration/test_backend_error_handling.py +++ b/tests/integration/test_backend_error_handling.py @@ -21,6 +21,7 @@ from cachekit.backends.errors import BackendError, BackendErrorType, CapabilityNotAvailableError from cachekit.backends.redis.error_handler import classify_redis_error from cachekit.backends.redis.provider import PerRequestRedisBackend +from cachekit.hash_utils import redact_cache_key @pytest.mark.integration @@ -99,7 +100,7 @@ def test_error_repr(self): assert "transient" in repr_str def test_error_formatted_message(self): - """Test formatted message includes operation and key context.""" + """Formatted message includes operation context and the redacted key digest.""" error = BackendError( "Get failed", error_type=BackendErrorType.TRANSIENT, @@ -109,21 +110,23 @@ def test_error_formatted_message(self): msg = str(error) assert "Get failed" in msg assert "operation=get" in msg - assert "key=user:123" in msg + assert f"key={redact_cache_key('user:123')}" in msg assert "type=transient" in msg - def test_error_key_truncation(self): - """Test long keys are truncated in error messages.""" - long_key = "x" * 100 + def test_error_key_redacted_not_leaked(self): + """The raw key never appears in the exception text — only its fixed-length + digest (CWE-532, LAB-304). The attribute keeps the raw key for programmatic use.""" + tenant_key = "ns:tenant-42-alice-secret:func:app.get_user:args:deadbeef:v1" error = BackendError( "Error", error_type=BackendErrorType.TRANSIENT, - key=long_key, + key=tenant_key, ) msg = str(error) - assert "..." in msg - assert long_key not in msg - assert len(msg) < len(long_key) + assert tenant_key not in msg + assert "tenant-42-alice-secret" not in msg + assert redact_cache_key(tenant_key) in msg + assert error.key == tenant_key @pytest.mark.integration @@ -272,5 +275,6 @@ def test_error_message_composition(self): msg = str(error) assert "Operation failed" in msg assert "get" in msg - assert "cache:user:123" in msg + assert f"key={redact_cache_key('cache:user:123')}" in msg + assert "cache:user:123" not in msg assert "transient" in msg diff --git a/tests/integration/test_redis_backend.py b/tests/integration/test_redis_backend.py index 595b084..a158853 100644 --- a/tests/integration/test_redis_backend.py +++ b/tests/integration/test_redis_backend.py @@ -17,6 +17,7 @@ from cachekit.backends.base import BackendError, BaseBackend from cachekit.backends.redis import RedisBackend +from cachekit.hash_utils import redact_cache_key from ..utils.redis_test_helpers import RedisIsolationMixin @@ -486,10 +487,11 @@ def test_operation_errors_include_context(self): assert error.operation == "get" # Should include key for debugging assert error.key == "cache:user:123" - # Should include both in formatted message + # Formatted message carries the operation and the redacted key digest error_msg = str(error) assert "operation=get" in error_msg - assert "cache:user:123" in error_msg + assert redact_cache_key("cache:user:123") in error_msg + assert "cache:user:123" not in error_msg # ============================================================================= diff --git a/tests/unit/test_backend_protocol.py b/tests/unit/test_backend_protocol.py index e4d1618..4db9b33 100644 --- a/tests/unit/test_backend_protocol.py +++ b/tests/unit/test_backend_protocol.py @@ -8,6 +8,7 @@ import pytest from cachekit.backends.base import BackendError, BaseBackend +from cachekit.hash_utils import redact_cache_key @pytest.mark.unit @@ -31,21 +32,22 @@ def test_error_with_operation(self): assert error.operation == "get" def test_error_with_key(self): - """BackendError should include key in formatted message.""" + """BackendError should include the redacted key digest in the formatted message.""" error = BackendError("Failed to store", operation="set", key="cache:user:123") error_msg = str(error) assert "Failed to store" in error_msg assert "operation=set" in error_msg - assert "key=cache:user:123" in error_msg - assert error.key == "cache:user:123" + assert f"key={redact_cache_key('cache:user:123')}" in error_msg + assert "cache:user:123" not in error_msg # raw key never in text (CWE-532) + assert error.key == "cache:user:123" # attribute stays raw for programmatic use - def test_error_with_long_key_truncation(self): - """BackendError should truncate long keys for readability.""" + def test_error_with_long_key_stays_fixed_length(self): + """Redaction replaces truncation: long keys become a fixed-length digest.""" long_key = "cache:" + "x" * 100 error = BackendError("Failed", operation="get", key=long_key) error_msg = str(error) - assert "..." in error_msg - assert len(error_msg) < len(long_key) + 50 # Truncated + assert long_key not in error_msg + assert redact_cache_key(long_key) in error_msg def test_error_serializability(self): """BackendError should contain only serializable types.""" @@ -276,7 +278,8 @@ def test_error_context_for_get_operation(self): assert error.operation == "get" assert error.key == "cache:user:123" assert "get" in str(error) - assert "cache:user:123" in str(error) + assert redact_cache_key("cache:user:123") in str(error) + assert "cache:user:123" not in str(error) def test_error_context_for_set_operation(self): """BackendError should capture context for set operations.""" diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index b187ed3..acb3f68 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/tests/unit/test_error_path_key_redaction.py @@ -147,3 +147,36 @@ def cached_func(user: str) -> str: assert len(backend.received_keys) == 1 _assert_redacted(caplog, backend.received_keys[0]) + + +class TestKeyCarryingBackendErrorRedaction: + """A BackendError that carries the raw key must not leak it through ``{e}``. + + ``BackendError.__str__`` includes a ``key=`` segment; the get() sinks + interpolate the exception verbatim, so the exception text itself must be + redacted (CodeRabbit PR #264). + """ + + def _key_carrying_error(self) -> BackendError: + return BackendError( + "backend down", + error_type=BackendErrorType.TRANSIENT, + operation="get", + key=TENANT_KEY, + ) + + def test_sync_get_failure_redacts_key_in_exception_text(self, caplog: pytest.LogCaptureFixture) -> None: + handler = StandardCacheHandler(backend=_FailingBackend(self._key_carrying_error())) + + with caplog.at_level(logging.ERROR): + assert handler.get(TENANT_KEY) is None + + _assert_redacted(caplog, TENANT_KEY) + + async def test_async_get_failure_redacts_key_in_exception_text(self, caplog: pytest.LogCaptureFixture) -> None: + handler = StandardCacheHandler(backend=_FailingBackend(self._key_carrying_error())) + + with caplog.at_level(logging.ERROR): + assert await handler.get_async(TENANT_KEY) is None + + _assert_redacted(caplog, TENANT_KEY) diff --git a/tests/unit/test_orchestrator_error_handling.py b/tests/unit/test_orchestrator_error_handling.py index b462176..4fcaadf 100644 --- a/tests/unit/test_orchestrator_error_handling.py +++ b/tests/unit/test_orchestrator_error_handling.py @@ -8,8 +8,9 @@ import pytest +from cachekit.backends.errors import BackendError, BackendErrorType from cachekit.cache_handler import redact_cache_key -from cachekit.decorators.orchestrator import FeatureOrchestrator +from cachekit.decorators.orchestrator import FeatureOrchestrator, _redact_key_for_log class TestErrorHandlerOrchestration: @@ -364,3 +365,58 @@ def test_structured_log_cache_operation_redacts_key(self, caplog: pytest.LogCapt structured = getattr(record, "structured", None) if structured is not None: assert self.TENANT_KEY not in str(structured) + + def test_backend_error_carrying_raw_key_is_sanitised(self, caplog: pytest.LogCaptureFixture) -> None: + """BackendError text must not leak its key attribute through {error} interpolation. + + BackendError.__str__ appends a key= segment; redacting the separate + cache_key argument does not touch that value (CodeRabbit PR #264). + """ + error = BackendError( + "backend down", + error_type=BackendErrorType.TRANSIENT, + operation="get", + key=self.TENANT_KEY, + ) + with caplog.at_level(logging.INFO): + self._orchestrator().handle_cache_error( + error=error, + operation="cache_get", + cache_key=self.TENANT_KEY, + duration_ms=1.0, + ) + + assert caplog.records, "error handler must log" + for record in caplog.records: + assert self.TENANT_KEY not in record.getMessage() + structured = getattr(record, "structured", None) + if structured is not None: + assert self.TENANT_KEY not in str(structured) + + def test_angle_bracketed_raw_key_is_redacted(self, caplog: pytest.LogCaptureFixture) -> None: + """A raw key that merely looks bracketed must not ride the sentinel pass-through.""" + bracketed = "" + with caplog.at_level(logging.WARNING): + self._orchestrator().handle_cache_error( + error=ConnectionError("backend down"), + operation="cache_get", + cache_key=bracketed, + ) + + digest = redact_cache_key(bracketed) + assert any(digest in record.getMessage() for record in caplog.records) + assert not any(bracketed in record.getMessage() for record in caplog.records) + + def test_pass_through_is_strict_allow_list(self) -> None: + """Only known sentinels and redact_cache_key() output pass through unredacted.""" + assert _redact_key_for_log("unknown") == "unknown" + assert _redact_key_for_log("") == "" + + already_redacted = redact_cache_key("anything") + assert _redact_key_for_log(already_redacted) == already_redacted + + # Arbitrary bracketed strings are NOT sentinels — they get redacted... + assert _redact_key_for_log("") == redact_cache_key("") + # ...and redaction stays idempotent through a second pass. + once = _redact_key_for_log("") + assert _redact_key_for_log(once) == once diff --git a/tests/unit/test_wrapper_lock_bare_key.py b/tests/unit/test_wrapper_lock_bare_key.py index f7096c0..d380d7f 100644 --- a/tests/unit/test_wrapper_lock_bare_key.py +++ b/tests/unit/test_wrapper_lock_bare_key.py @@ -25,6 +25,7 @@ from __future__ import annotations +import logging from collections.abc import AsyncIterator, Iterator from contextlib import asynccontextmanager from typing import Any, Optional @@ -33,6 +34,7 @@ import pytest from cachekit import cache +from cachekit.backends.errors import BackendError, BackendErrorType from cachekit.hash_utils import redact_cache_key @@ -309,3 +311,51 @@ def release(self) -> None: assert ":lock:lock" not in wire_name, ( f"double ':lock' suffix in Redis wire name: {wire_name!r} — both wrapper and backend appended the suffix" ) + + +class _LockFailingBackend(_RecordingLockableBackend): + """acquire_lock records the key, then fails with a key-carrying BackendError.""" + + @asynccontextmanager + async def acquire_lock( + self, + key: str, + timeout: float = 10.0, + blocking_timeout: Optional[float] = None, + ) -> AsyncIterator[bool]: + """Raise a BackendError that embeds the cache key, as real backends do.""" + self.lock_keys.append(key) + raise BackendError( + "lock backend down", + error_type=BackendErrorType.TRANSIENT, + operation="acquire_lock", + key=key, + ) + yield True # pragma: no cover — unreachable, satisfies the generator contract + + +@pytest.mark.unit +@pytest.mark.asyncio +class TestLockFailureWarningRedactsKey: + """The 'Lock operation failed' warning interpolates ``{e}`` — a BackendError + carrying the cache key must not leak it into the log (CodeRabbit PR #264).""" + + async def test_lock_failure_warning_never_logs_raw_key(self, caplog: pytest.LogCaptureFixture) -> None: + backend = _LockFailingBackend() + + @cache(backend=backend, ttl=300, l1_enabled=False) + async def my_func(x: int) -> dict[str, int]: + return {"x": x} + + with caplog.at_level(logging.WARNING): + result = await my_func(7) + + # Fallback contract intact: lock failure degrades to lock-free execution. + assert result == {"x": 7} + assert len(backend.lock_keys) == 1 + raw_key = backend.lock_keys[0] + + lock_warnings = [r.getMessage() for r in caplog.records if "Lock operation failed" in r.getMessage()] + assert lock_warnings, "lock failure must be logged" + assert not any(raw_key in m for m in lock_warnings), f"raw cache key leaked into lock warning: {lock_warnings!r}" + assert any(redact_cache_key(raw_key) in m for m in lock_warnings), "digest must keep the failure correlatable" From f34f042d8ce8cbfd430eeaaa3bc840dd6dc98852 Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Mon, 31 Aug 2026 03:38:36 +1000 Subject: [PATCH 6/8] fix(logging): close residual raw-key channels found by panel review (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Expert-panel findings on the CodeRabbit remediation commit — the key= segment of BackendError was redacted, but the message field was a second channel: - memcached oversized-value guard embedded the raw key in the message; dropped (the redacted key= segment carries correlation). - memcached error classification interpolated wrapped exception text into the message; pymemcache illegal-input errors echo the full raw key. Permanent and unknown branches now carry only the exception type name; original_exception keeps full detail. - StructuredLogger.cache_operation logged a raw cache_key[:50] prefix (and PII-pattern masking never caught tenant ids in keys); now always emits the redact_cache_key digest. Dead _mask_sensitive_data helper removed. - SECURITY.md updated to state the message-field guarantee; hash_utils docstring cross-references the format-pinning regex and test. --- SECURITY.md | 2 +- src/cachekit/backends/memcached/backend.py | 5 ++- .../backends/memcached/error_handler.py | 13 ++++--- src/cachekit/hash_utils.py | 4 +++ src/cachekit/logging.py | 17 ++++----- .../test_memcached_backend_critical.py | 36 +++++++++++++++++++ .../unit/test_orchestrator_error_handling.py | 4 +-- tests/unit/test_structured_logging.py | 22 +++++++----- 8 files changed, 76 insertions(+), 27 deletions(-) diff --git a/SECURITY.md b/SECURITY.md index 28f6f23..4cba081 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 they never reach logs verbatim ([CWE-532][cwe-532]). Every 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. +Cache keys can embed caller-supplied tenant/user identifiers, so they never reach logs verbatim ([CWE-532][cwe-532]). Every 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 its `key` at construction, so `str(e)` is safe at any log sink; backend error *messages* carry no raw key either — wrapped third-party exception text of unknown provenance (e.g. pymemcache illegal-input errors, which echo the key) is reduced to the exception type name, with the original exception preserved on `original_exception` for programmatic access. ### Lock Token Transport (CWE-532) diff --git a/src/cachekit/backends/memcached/backend.py b/src/cachekit/backends/memcached/backend.py index 1f80167..d041e43 100644 --- a/src/cachekit/backends/memcached/backend.py +++ b/src/cachekit/backends/memcached/backend.py @@ -127,7 +127,10 @@ def set(self, key: str, value: bytes, ttl: Optional[int] = None) -> None: if max_size and len(value) > max_size: raise BackendError( message=( - f"Value for key {key!r} is {len(value)} bytes, which exceeds the Memcached " + # No raw key in the message — it reaches log sinks via str(e) + # (CWE-532); the key= segment _format_message appends carries + # the redacted digest for correlation. + f"Value is {len(value)} bytes, which exceeds the Memcached " f"max item size of {max_size} bytes. Memcached cannot store it. Enable " f"compression, use a larger-payload backend (Redis/SaaS/File), or raise both " f"the server's -I limit and CACHEKIT_MEMCACHED_MAX_ITEM_SIZE_BYTES." diff --git a/src/cachekit/backends/memcached/error_handler.py b/src/cachekit/backends/memcached/error_handler.py index 880ca9e..f0cd862 100644 --- a/src/cachekit/backends/memcached/error_handler.py +++ b/src/cachekit/backends/memcached/error_handler.py @@ -68,19 +68,24 @@ def classify_memcached_error( key=key, ) - # Permanent — illegal input, client errors (don't retry) + # Permanent — illegal input, client errors (don't retry). + # Only the exception TYPE goes in the message: pymemcache embeds the raw + # cache key in illegal-input error text ("Key is too long: %r"), and the + # message reaches log sinks via str(e) (CWE-532). Full details stay on + # original_exception for programmatic access. if isinstance(exc, (MemcacheIllegalInputError, MemcacheClientError)): return BackendError( - message=f"Memcached permanent error during {operation}: {exc}", + message=f"Memcached permanent error during {operation}: {type(exc).__name__}", error_type=BackendErrorType.PERMANENT, original_exception=exc, operation=operation, key=key, ) - # Unknown — safe default + # Unknown — safe default. Arbitrary exception text has unknown provenance + # and may embed the key, so only the type name goes in the message (CWE-532). return BackendError( - message=f"Memcached unknown error during {operation}: {exc}", + message=f"Memcached unknown error during {operation}: {type(exc).__name__}", error_type=BackendErrorType.UNKNOWN, original_exception=exc, operation=operation, diff --git a/src/cachekit/hash_utils.py b/src/cachekit/hash_utils.py index ec6f318..355db80 100644 --- a/src/cachekit/hash_utils.py +++ b/src/cachekit/hash_utils.py @@ -18,6 +18,10 @@ def redact_cache_key(cache_key: object) -> str: Lives in this leaf module so backend/L1 modules can use it without importing cache_handler (which imports them). + + The exact output format (````) is pinned by + ``decorators.orchestrator._REDACTED_KEY_RE`` and + ``test_pass_through_is_strict_allow_list`` — change them together. """ return f"" diff --git a/src/cachekit/logging.py b/src/cachekit/logging.py index c5ccc8a..45d32de 100644 --- a/src/cachekit/logging.py +++ b/src/cachekit/logging.py @@ -15,6 +15,7 @@ from typing import Any, Optional from cachekit.config import get_settings +from cachekit.hash_utils import redact_cache_key # Configure base logger logger = logging.getLogger(__name__) @@ -251,11 +252,11 @@ def error(self, message: str, **kwargs): def cache_operation(self, operation: str, cache_key: str, **kwargs): """Log cache operation with standard fields.""" - # Mask cache key if needed - if self.mask_sensitive and cache_key: - display_key = self._mask_sensitive_data(cache_key) - else: - display_key = cache_key[:50] if cache_key else "" # Truncate long keys + # Always redact: cache keys embed caller-supplied tenant/user identifiers + # (CWE-532, LAB-304). PII-pattern masking (SSN/email/...) does not catch + # them, and a raw [:50] prefix is exactly the leak — so neither is an + # alternative to the digest. + display_key = redact_cache_key(cache_key) if cache_key else "" # Determine log level based on error presence level = "ERROR" if "error" in kwargs else "INFO" @@ -406,12 +407,6 @@ def _get_context(self) -> dict[str, Any]: context["correlation_id"] = self._context.correlation_id return context - def _mask_sensitive_data(self, data: str) -> str: - """Mask sensitive data if enabled.""" - if self.mask_sensitive: - return mask_sensitive_patterns(data) - return data - # Compatibility methods for tests def redis_operation_failed(self, operation: str, key: str, error: Exception, **kwargs): """Log Redis operation failure.""" diff --git a/tests/critical/test_memcached_backend_critical.py b/tests/critical/test_memcached_backend_critical.py index b5d1445..6525e75 100644 --- a/tests/critical/test_memcached_backend_critical.py +++ b/tests/critical/test_memcached_backend_critical.py @@ -345,3 +345,39 @@ def compute(x: int) -> int: assert call_count == 1 # Cache hit finally: set_default_backend(original) + + +@pytest.mark.critical +def test_oversized_value_error_never_leaks_raw_key(backend, mock_hash_client): + """The oversized-value message must not embed the raw key — str(e) reaches + log sinks verbatim (CWE-532, LAB-304); the key= digest segment carries correlation.""" + tenant_key = "ns:tenant-42-alice-secret:func:app.get_user:args:deadbeef:v1" + big = b"\x00" * (1024 * 1024 + 1) + + with pytest.raises(BackendError) as exc_info: + backend.set(tenant_key, big, ttl=60) + + assert tenant_key not in str(exc_info.value) + assert "tenant-42-alice-secret" not in str(exc_info.value) + assert exc_info.value.key == tenant_key # raw on the attribute for programmatic use + + +@pytest.mark.critical +def test_classified_error_never_leaks_key_from_wrapped_exception_text(): + """pymemcache embeds the raw key in illegal-input exception text; the classified + BackendError message must carry only the exception type (CWE-532).""" + from pymemcache.exceptions import MemcacheIllegalInputError + + tenant_key = "ns:tenant-42-alice-secret:" + "x" * 300 + exc = MemcacheIllegalInputError(f"Key is too long: {tenant_key!r}") + + err = classify_memcached_error(exc, operation="set", key=tenant_key) + + assert err.error_type == BackendErrorType.PERMANENT + assert tenant_key not in str(err) + assert "tenant-42-alice-secret" not in str(err) + assert err.original_exception is exc # full detail preserved for programmatic access + + # Unknown-fallback branch: arbitrary exception text has unknown provenance + err = classify_memcached_error(RuntimeError(f"boom {tenant_key}"), operation="get", key=tenant_key) + assert "tenant-42-alice-secret" not in str(err) diff --git a/tests/unit/test_orchestrator_error_handling.py b/tests/unit/test_orchestrator_error_handling.py index 4fcaadf..1e80998 100644 --- a/tests/unit/test_orchestrator_error_handling.py +++ b/tests/unit/test_orchestrator_error_handling.py @@ -416,7 +416,7 @@ def test_pass_through_is_strict_allow_list(self) -> None: assert _redact_key_for_log(already_redacted) == already_redacted # Arbitrary bracketed strings are NOT sentinels — they get redacted... - assert _redact_key_for_log("") == redact_cache_key("") - # ...and redaction stays idempotent through a second pass. once = _redact_key_for_log("") + assert once == redact_cache_key("") + # ...and redaction stays idempotent through a second pass. assert _redact_key_for_log(once) == once diff --git a/tests/unit/test_structured_logging.py b/tests/unit/test_structured_logging.py index 0aabe19..603d619 100644 --- a/tests/unit/test_structured_logging.py +++ b/tests/unit/test_structured_logging.py @@ -106,15 +106,19 @@ def test_get_context(self, logger): context = logger._get_context() assert context["trace_id"] == trace_id - def test_mask_sensitive_data(self, logger, logger_no_mask): - """Test sensitive data masking.""" - sensitive = "email@test.com" + def test_cache_key_always_redacted(self, logger, logger_no_mask): + """cache_operation redacts the key regardless of mask_sensitive (CWE-532, LAB-304).""" + from unittest.mock import patch as _patch - # With masking enabled - assert logger._mask_sensitive_data(sensitive) == "XXX@XXX.XXX" + from cachekit.hash_utils import redact_cache_key - # With masking disabled - assert logger_no_mask._mask_sensitive_data(sensitive) == sensitive + sensitive = "ns:tenant-42:func:app.f:args:email@test.com:v1" + for lg in (logger, logger_no_mask): + with _patch("cachekit.logging.logging.Logger.log") as mock_log: + lg.cache_operation("get", sensitive, hit=True) + extra = mock_log.call_args[1]["extra"]["structured"] + assert extra["cache_key"] == redact_cache_key(sensitive) + assert sensitive not in str(extra) @patch("cachekit.logging.logging.Logger.log") def test_cache_operation_logging(self, mock_log, logger): @@ -140,7 +144,9 @@ def test_cache_operation_logging(self, mock_log, logger): # Check structured context extra = call_args[1]["extra"]["structured"] assert extra["operation"] == "get" - assert extra["cache_key"] == "user:XXX@XXX.XXX" # Masked + from cachekit.hash_utils import redact_cache_key + + assert extra["cache_key"] == redact_cache_key("user:email@test.com") # Redacted digest (CWE-532) assert extra["namespace"] == "users" assert extra["serializer"] == "orjson" assert extra["duration_ms"] == 1.5 From 9f5c39004f76ae9efc5ccb29c433c80c72c002d1 Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Mon, 31 Aug 2026 04:12:39 +1000 Subject: [PATCH 7/8] fix(logging): share one redaction policy between both log sinks (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit cache_operation() called redact_cache_key() bare, so a key that had already been redacted upstream got hashed a second time and emitted a different digest than FeatureOrchestrator produced for the same key — the two sinks could not be joined in a log query. Recognised sentinels ("unknown", "") were hashed into opaque digests for the same reason. The _redact_key_for_log policy moved from decorators/orchestrator.py to hash_utils.py as redact_key_for_log(), beside redact_cache_key(). logging.py already imported that leaf module, so both sinks now share one implementation rather than logging.py importing the decorator package (wrong direction) or growing a second copy that drifts. orchestrator keeps a module-level alias, so existing callers and tests are unaffected; its now-unused re and redact_cache_key imports are dropped. The format-pinning regex now lives next to the function that emits the format, retiring the cross-module docstring reference. cache_hit/cache_miss/cache_stored all funnel through cache_operation, so the single call site covers them. Coverage: TestStructuredLoggerCacheOperationRedaction pins raw-key redaction, pre-redacted pass-through, both sentinels, cross-sink digest agreement, and the empty-key case. Verified they fail against the previous implementation (3 of the 6 discriminate; the rest hold in both). CodeRabbit-Resolved: logging.py:259:Preserve approved redacted values --- src/cachekit/decorators/orchestrator.py | 31 +++----------- src/cachekit/hash_utils.py | 37 +++++++++++++++- src/cachekit/logging.py | 9 +++- tests/unit/test_error_path_key_redaction.py | 47 ++++++++++++++++++++- 4 files changed, 93 insertions(+), 31 deletions(-) diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py index c0edcce..8aa0b1a 100644 --- a/src/cachekit/decorators/orchestrator.py +++ b/src/cachekit/decorators/orchestrator.py @@ -1,10 +1,9 @@ import contextvars import logging -import re import uuid from typing import Any, Optional -from ..cache_handler import redact_cache_key +from ..hash_utils import redact_key_for_log from ..monitoring.correlation_tracking import CorrelationTracker from ..monitoring.pool_monitor import OptimizedPoolMonitor @@ -21,30 +20,10 @@ _operation_context: contextvars.ContextVar[Optional[dict[str, Any]]] = contextvars.ContextVar("operation_context", default=None) -# Only values that provably carry no caller data pass through unredacted: the -# known sentinels, and the exact output format of redact_cache_key(). A broad -# "<...>" match would let a raw key like "" through. -_SENTINEL_KEYS = frozenset({"unknown", ""}) -_REDACTED_KEY_RE = re.compile(r"\Z") - - -def _redact_key_for_log(cache_key: object) -> str: - """Redact a cache key for logging unless it is a known sentinel or already redacted. - - Cache keys embed caller-supplied tenant/user identifiers and must never reach - logs verbatim (CWE-532, issue #163). Real keys are canonical ``ns:...`` strings; - sentinels (``unknown``, ````) and redact_cache_key() output - (````) carry no caller data and stay readable as-is. - - Matching the strict generated format keeps redaction idempotent — - handle_cache_error's redacted output flows through log_cache_operation's - redaction a second time — without opening a pass-through for arbitrary - angle-bracketed strings. - """ - key_str = str(cache_key) - if key_str in _SENTINEL_KEYS or _REDACTED_KEY_RE.fullmatch(key_str): - return key_str - return redact_cache_key(key_str) +# The redaction policy moved to hash_utils so cachekit.logging can apply the same +# pass-through rules without importing this module (both sinks must emit the same +# digest for a given key, or log correlation breaks). Alias kept for existing callers. +_redact_key_for_log = redact_key_for_log class FeatureOrchestrator: diff --git a/src/cachekit/hash_utils.py b/src/cachekit/hash_utils.py index 355db80..7034d1a 100644 --- a/src/cachekit/hash_utils.py +++ b/src/cachekit/hash_utils.py @@ -4,6 +4,7 @@ """ import hashlib +import re from typing import Union import blake3 @@ -20,12 +21,44 @@ def redact_cache_key(cache_key: object) -> str: cache_handler (which imports them). The exact output format (````) is pinned by - ``decorators.orchestrator._REDACTED_KEY_RE`` and - ``test_pass_through_is_strict_allow_list`` — change them together. + ``_REDACTED_KEY_RE`` below and by ``test_pass_through_is_strict_allow_list`` + — change them together. """ return f"" +#: Key placeholders that carry no caller data and stay readable in logs. +SENTINEL_KEYS = frozenset({"unknown", ""}) + +#: Matches exactly what redact_cache_key() emits — keep the two in step. +_REDACTED_KEY_RE = re.compile(r"\Z") + + +def redact_key_for_log(cache_key: object) -> str: + """Redact a cache key for logging unless it is a known sentinel or already redacted. + + Cache keys embed caller-supplied tenant/user identifiers and must never reach + logs verbatim (CWE-532, issue #163). Real keys are canonical ``ns:...`` strings; + sentinels (``unknown``, ````) and redact_cache_key() output + (````) carry no caller data and stay readable as-is. + + Matching the strict generated format makes redaction idempotent, so one key can + cross several sinks — ``handle_cache_error`` into ``log_cache_operation``, or a + caller handing an already-redacted value straight to ``SimpleLogger`` — and still + emit a single digest that correlates across all of them. Re-hashing would mint a + fresh digest per hop and break that correlation, without opening a pass-through + for arbitrary angle-bracketed strings. + + Lives beside redact_cache_key() in this leaf module so both the decorator + orchestrator and ``cachekit.logging`` share one policy without importing each + other. + """ + key_str = str(cache_key) + if key_str in SENTINEL_KEYS or _REDACTED_KEY_RE.fullmatch(key_str): + return key_str + return redact_cache_key(key_str) + + def fast_hash(data: Union[str, bytes], digest_size: int = 8) -> str: """Ultra-fast hash using BLAKE3 - optimized for hot paths. diff --git a/src/cachekit/logging.py b/src/cachekit/logging.py index 45d32de..723b0f2 100644 --- a/src/cachekit/logging.py +++ b/src/cachekit/logging.py @@ -15,7 +15,7 @@ from typing import Any, Optional from cachekit.config import get_settings -from cachekit.hash_utils import redact_cache_key +from cachekit.hash_utils import redact_key_for_log # Configure base logger logger = logging.getLogger(__name__) @@ -256,7 +256,12 @@ def cache_operation(self, operation: str, cache_key: str, **kwargs): # (CWE-532, LAB-304). PII-pattern masking (SSN/email/...) does not catch # them, and a raw [:50] prefix is exactly the leak — so neither is an # alternative to the digest. - display_key = redact_cache_key(cache_key) if cache_key else "" + # + # Same guard the orchestrator sink uses, not a bare redact_cache_key(): + # callers reach this method with values already redacted upstream, and + # re-hashing would emit a second, different digest for one key and break + # correlation between the two sinks. Sentinels stay readable too. + display_key = redact_key_for_log(cache_key) if cache_key else "" # Determine log level based on error presence level = "ERROR" if "error" in kwargs else "INFO" diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index acb3f68..b76f5dc 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/tests/unit/test_error_path_key_redaction.py @@ -17,8 +17,10 @@ from cachekit.backends.errors import BackendError, BackendErrorType from cachekit.cache_handler import CacheInvalidator, StandardCacheHandler -from cachekit.hash_utils import redact_cache_key +from cachekit.decorators.orchestrator import _redact_key_for_log +from cachekit.hash_utils import SENTINEL_KEYS, redact_cache_key from cachekit.key_generator import CacheKeyGenerator +from cachekit.logging import UltraOptimizedStructuredLogger TENANT_KEY = "ns:tenant-42-alice-secret:func:app.get_user:args:deadbeef:v1" @@ -180,3 +182,46 @@ async def test_async_get_failure_redacts_key_in_exception_text(self, caplog: pyt assert await handler.get_async(TENANT_KEY) is None _assert_redacted(caplog, TENANT_KEY) + + +class TestStructuredLoggerCacheOperationRedaction: + """``UltraOptimizedStructuredLogger.cache_operation`` is a direct sink. + + ``cache_hit``/``cache_miss``/``cache_stored`` all funnel through it, so this + one method is the whole surface. It must apply the *same* pass-through policy + as the orchestrator sink: a value that arrives already redacted, or is a known + sentinel, is emitted verbatim. Hashing it a second time would mint a different + digest for the same key and break correlation between the two sinks + (CodeRabbit PR #264). + """ + + def _emit(self, caplog: pytest.LogCaptureFixture, cache_key: str) -> str: + logger = UltraOptimizedStructuredLogger("test.cache_operation") + + with caplog.at_level(logging.INFO, logger="test.cache_operation"): + logger.cache_operation("get", cache_key, hit=True) + + records = [r for r in caplog.records if hasattr(r, "structured")] + assert records, "cache_operation emitted no structured record" + return records[-1].structured["cache_key"] + + def test_raw_key_is_redacted(self, caplog: pytest.LogCaptureFixture) -> None: + assert self._emit(caplog, TENANT_KEY) == redact_cache_key(TENANT_KEY) + + def test_already_redacted_key_passes_through(self, caplog: pytest.LogCaptureFixture) -> None: + """The digest must survive a second hop unchanged — this is the correlation contract.""" + pre_redacted = redact_cache_key(TENANT_KEY) + + assert self._emit(caplog, pre_redacted) == pre_redacted + + @pytest.mark.parametrize("sentinel", sorted(SENTINEL_KEYS)) + def test_sentinels_stay_readable(self, sentinel: str, caplog: pytest.LogCaptureFixture) -> None: + assert self._emit(caplog, sentinel) == sentinel + + def test_digest_matches_the_orchestrator_sink(self, caplog: pytest.LogCaptureFixture) -> None: + """Both sinks must render one key as one digest, or logs cannot be joined.""" + assert self._emit(caplog, TENANT_KEY) == _redact_key_for_log(TENANT_KEY) + + def test_falsy_key_emits_empty_string(self, caplog: pytest.LogCaptureFixture) -> None: + """No key means nothing to redact — must not become a digest of ``""``.""" + assert self._emit(caplog, "") == "" From b05c7eeb753aa12a09977d1e222236dd2706d9a6 Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Mon, 31 Aug 2026 04:28:18 +1000 Subject: [PATCH 8/8] fix(logging): expert-panel remediation on the shared redaction guard (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Four-agent panel (high stakes) on the previous commit. Findings applied: REGRESSION I introduced: health.py logs its checks with cache_key="system", a component label and not a key. Routing cache_operation through the guard began hashing it, so a readable operator field became and any dashboard filtering on it would have silently stopped matching after upgrade. "system" joins the sentinel set; the parametrized sentinel test reads the set, so it now covers it. Docstring told a lie: it claimed idempotency held "for a caller handing an already-redacted value straight to SimpleLogger", but provider.py's four SimpleLogger methods called bare redact_cache_key() and would double-hash. Made the claim true rather than deleting it — those four sinks now use redact_key_for_log. Same leaf module, no new import edge. Added a line steering future callers: prefer the guard at any sink, bare only where input is known-raw. Missed CWE-532 channel, pre-existing: l1_cache.py logged the raw key in the oversized-value debug line while its sibling eighteen lines above was already redacted. This is the same log cachekit-ts redacted in LAB-1768. test_digest_matches_the_orchestrator_sink was tautological — it compared logging.py's output against the very function logging.py calls, so it would pass even if the two sinks diverged, the one thing it exists to catch. It now drives FeatureOrchestrator.handle_cache_error for real and asserts both sinks emit the same digest. Cut the _redact_key_for_log alias: a leading-underscore name has no external consumers to protect, and all four callers are in-tree. SENTINEL_KEYS reverted to _SENTINEL_KEYS — public API surface on a published SDK is not worth one test's convenience; the test imports the private name, as it already does elsewhere in this repo. Panel REBUTTED CodeRabbit's keyed-HMAC demand; rationale is on the PR. Not addressed here, raised for separate triage: pymemcache exception text embeds the raw key and rides the __cause__ traceback (str(e) is redacted, the traceback is not); mask_sensitive is a dead knob since this PR removed its only reader; SECURITY.md still claims coverage broader than the sweep proves for the redis/file/cachekitio backends. --- src/cachekit/backends/provider.py | 10 +++--- src/cachekit/decorators/orchestrator.py | 10 ++---- src/cachekit/hash_utils.py | 30 ++++++++++------ src/cachekit/l1_cache.py | 2 +- tests/unit/test_error_path_key_redaction.py | 36 ++++++++++++++++--- .../unit/test_orchestrator_error_handling.py | 13 +++---- 6 files changed, 65 insertions(+), 36 deletions(-) diff --git a/src/cachekit/backends/provider.py b/src/cachekit/backends/provider.py index d8f44d8..c67fe33 100644 --- a/src/cachekit/backends/provider.py +++ b/src/cachekit/backends/provider.py @@ -9,7 +9,7 @@ from typing import TYPE_CHECKING, Optional -from cachekit.hash_utils import redact_cache_key +from cachekit.hash_utils import redact_key_for_log if TYPE_CHECKING: import redis @@ -62,20 +62,20 @@ def error(self, message: str): def cache_hit(self, key: str, source: str = "Redis"): """Log cache hits. Keys are redacted — they embed caller identifiers (CWE-532).""" - self._logger.debug(f"{source} cache hit for key: {redact_cache_key(key)}") + self._logger.debug(f"{source} cache hit for key: {redact_key_for_log(key)}") def cache_miss(self, key: str): """Log cache misses. Keys are redacted — they embed caller identifiers (CWE-532).""" - self._logger.debug(f"Cache miss for key: {redact_cache_key(key)}") + self._logger.debug(f"Cache miss for key: {redact_key_for_log(key)}") def cache_stored(self, key: str, ttl=None): """Log cache storage operations. Keys are redacted — they embed caller identifiers (CWE-532).""" ttl_info = f" with TTL {ttl}" if ttl else "" - self._logger.debug(f"Cached result for key: {redact_cache_key(key)}{ttl_info}") + self._logger.debug(f"Cached result for key: {redact_key_for_log(key)}{ttl_info}") def cache_invalidated(self, key: str, source: str = "Redis"): """Log cache invalidation. Keys are redacted — they embed caller identifiers (CWE-532).""" - self._logger.debug(f"Invalidated {source} cache for key: {redact_cache_key(key)}") + self._logger.debug(f"Invalidated {source} cache for key: {redact_key_for_log(key)}") class DefaultLoggerProvider(LoggerProvider): diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py index 8aa0b1a..cb51936 100644 --- a/src/cachekit/decorators/orchestrator.py +++ b/src/cachekit/decorators/orchestrator.py @@ -20,12 +20,6 @@ _operation_context: contextvars.ContextVar[Optional[dict[str, Any]]] = contextvars.ContextVar("operation_context", default=None) -# The redaction policy moved to hash_utils so cachekit.logging can apply the same -# pass-through rules without importing this module (both sinks must emit the same -# digest for a given key, or log correlation breaks). Alias kept for existing callers. -_redact_key_for_log = redact_key_for_log - - class FeatureOrchestrator: """Orchestrates existing reliability and monitoring features. @@ -283,7 +277,7 @@ def log_cache_operation(self, **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"]) + kwargs["key"] = redact_key_for_log(kwargs["key"]) key = kwargs.get("key", "unknown") self.log_structured("info", f"Cache operation: {operation}", cache_key=key, **kwargs) @@ -446,7 +440,7 @@ def handle_cache_error( # Redact once at the sink so every error path is covered by construction # (CWE-532) — callers pass the raw key; sentinels pass through readable. - cache_key = _redact_key_for_log(cache_key) + cache_key = redact_key_for_log(cache_key) # 1. Record exception in span and metrics if span: diff --git a/src/cachekit/hash_utils.py b/src/cachekit/hash_utils.py index 7034d1a..16007f0 100644 --- a/src/cachekit/hash_utils.py +++ b/src/cachekit/hash_utils.py @@ -27,8 +27,13 @@ def redact_cache_key(cache_key: object) -> str: return f"" -#: Key placeholders that carry no caller data and stay readable in logs. -SENTINEL_KEYS = frozenset({"unknown", ""}) +#: Placeholders that occupy the cache_key field but are not keys and carry no +#: caller data, so they stay readable. ``system`` is the label health.py logs its +#: checks under; hashing it turned a readable operator-facing field into an +#: opaque digest and silently broke any dashboard filtering on it. None of these +#: is a well-formed cache key (real keys are ``ns:...``), so nothing caller-supplied +#: can impersonate one. +_SENTINEL_KEYS = frozenset({"unknown", "", "system"}) #: Matches exactly what redact_cache_key() emits — keep the two in step. _REDACTED_KEY_RE = re.compile(r"\Z") @@ -44,17 +49,20 @@ def redact_key_for_log(cache_key: object) -> str: Matching the strict generated format makes redaction idempotent, so one key can cross several sinks — ``handle_cache_error`` into ``log_cache_operation``, or a - caller handing an already-redacted value straight to ``SimpleLogger`` — and still - emit a single digest that correlates across all of them. Re-hashing would mint a - fresh digest per hop and break that correlation, without opening a pass-through - for arbitrary angle-bracketed strings. - - Lives beside redact_cache_key() in this leaf module so both the decorator - orchestrator and ``cachekit.logging`` share one policy without importing each - other. + caller handing an already-redacted value to ``SimpleLogger`` — and still emit a + single digest that correlates across all of them. Re-hashing would mint a fresh + digest per hop and break that correlation, without opening a pass-through for + arbitrary angle-bracketed strings. + + Prefer this over :func:`redact_cache_key` at any *sink*. Reach for the bare + function only where the input is known-raw and cannot already be redacted. + + Lives beside redact_cache_key() in this leaf module so the decorator + orchestrator, ``cachekit.logging`` and the backend loggers share one policy + without importing each other. """ key_str = str(cache_key) - if key_str in SENTINEL_KEYS or _REDACTED_KEY_RE.fullmatch(key_str): + if key_str in _SENTINEL_KEYS or _REDACTED_KEY_RE.fullmatch(key_str): return key_str return redact_cache_key(key_str) diff --git a/src/cachekit/l1_cache.py b/src/cachekit/l1_cache.py index 5b67f33..c2887f8 100644 --- a/src/cachekit/l1_cache.py +++ b/src/cachekit/l1_cache.py @@ -205,7 +205,7 @@ def put( self._remove_entry(key) logger.debug( "Skipping L1 cache for key %s - value %d bytes exceeds L1 budget %d bytes (served from L2 only)", - key, + redact_cache_key(key), size, self.max_memory_bytes, ) diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index b76f5dc..ac4e8fb 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/tests/unit/test_error_path_key_redaction.py @@ -17,8 +17,8 @@ from cachekit.backends.errors import BackendError, BackendErrorType from cachekit.cache_handler import CacheInvalidator, StandardCacheHandler -from cachekit.decorators.orchestrator import _redact_key_for_log -from cachekit.hash_utils import SENTINEL_KEYS, redact_cache_key +from cachekit.decorators.orchestrator import FeatureOrchestrator +from cachekit.hash_utils import _SENTINEL_KEYS, redact_cache_key from cachekit.key_generator import CacheKeyGenerator from cachekit.logging import UltraOptimizedStructuredLogger @@ -214,13 +214,39 @@ def test_already_redacted_key_passes_through(self, caplog: pytest.LogCaptureFixt assert self._emit(caplog, pre_redacted) == pre_redacted - @pytest.mark.parametrize("sentinel", sorted(SENTINEL_KEYS)) + @pytest.mark.parametrize("sentinel", sorted(_SENTINEL_KEYS)) def test_sentinels_stay_readable(self, sentinel: str, caplog: pytest.LogCaptureFixture) -> None: + """Covers ``system`` too — health.py logs under that label, and hashing it + turned a readable operator field into an opaque digest.""" assert self._emit(caplog, sentinel) == sentinel def test_digest_matches_the_orchestrator_sink(self, caplog: pytest.LogCaptureFixture) -> None: - """Both sinks must render one key as one digest, or logs cannot be joined.""" - assert self._emit(caplog, TENANT_KEY) == _redact_key_for_log(TENANT_KEY) + """Both sinks must render one key as one digest, or logs cannot be joined. + + Drives the orchestrator sink for real rather than re-calling the shared + helper — comparing the helper against itself would pass even if the two + sinks diverged, which is the only thing this test exists to catch. + """ + from_logging_sink = self._emit(caplog, TENANT_KEY) + + caplog.clear() + orchestrator = FeatureOrchestrator( + namespace="test", + circuit_breaker_enabled=False, + backpressure_enabled=False, + ) + with caplog.at_level(logging.WARNING): + orchestrator.handle_cache_error( + error=ValueError("boom"), + operation="get", + cache_key=TENANT_KEY, + ) + + orchestrator_messages = " ".join(r.getMessage() for r in caplog.records) + assert from_logging_sink in orchestrator_messages, ( + f"sinks disagree: logging emitted {from_logging_sink!r}, orchestrator logged {orchestrator_messages!r}" + ) + assert TENANT_KEY not in orchestrator_messages def test_falsy_key_emits_empty_string(self, caplog: pytest.LogCaptureFixture) -> None: """No key means nothing to redact — must not become a digest of ``""``.""" diff --git a/tests/unit/test_orchestrator_error_handling.py b/tests/unit/test_orchestrator_error_handling.py index 1e80998..142780c 100644 --- a/tests/unit/test_orchestrator_error_handling.py +++ b/tests/unit/test_orchestrator_error_handling.py @@ -10,7 +10,8 @@ from cachekit.backends.errors import BackendError, BackendErrorType from cachekit.cache_handler import redact_cache_key -from cachekit.decorators.orchestrator import FeatureOrchestrator, _redact_key_for_log +from cachekit.decorators.orchestrator import FeatureOrchestrator +from cachekit.hash_utils import redact_key_for_log class TestErrorHandlerOrchestration: @@ -409,14 +410,14 @@ def test_angle_bracketed_raw_key_is_redacted(self, caplog: pytest.LogCaptureFixt def test_pass_through_is_strict_allow_list(self) -> None: """Only known sentinels and redact_cache_key() output pass through unredacted.""" - assert _redact_key_for_log("unknown") == "unknown" - assert _redact_key_for_log("") == "" + assert redact_key_for_log("unknown") == "unknown" + assert redact_key_for_log("") == "" already_redacted = redact_cache_key("anything") - assert _redact_key_for_log(already_redacted) == already_redacted + assert redact_key_for_log(already_redacted) == already_redacted # Arbitrary bracketed strings are NOT sentinels — they get redacted... - once = _redact_key_for_log("") + once = redact_key_for_log("") assert once == redact_cache_key("") # ...and redaction stays idempotent through a second pass. - assert _redact_key_for_log(once) == once + assert redact_key_for_log(once) == once