From 63d9132e38aaf1bfe204a97cd3de38f0e63900ef Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Mon, 31 Aug 2026 02:14:12 +1000 Subject: [PATCH 01/17] 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 008160a0..28f6f231 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 66abbc2b..f71b4de9 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 f84847a6..76cf0c45 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 bbd0ed14..b462176d 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 02/17] 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 809c294f..c2fb19f6 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 00000000..a4b8e2fb --- /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 a6e4b070..d8f44d80 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 1fce6455..bde63e12 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 f71b4de9..a15bcce6 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 76cf0c45..78bd8369 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 235a5be1..ec6f318c 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 845d4ec8..5b67f335 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 98ddf218..96e1b1a0 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 85c34471..f7096c00 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 03/17] 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 a4b8e2fb..00000000 --- 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 04/17] 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 3860e791..4b74fa95 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 bde63e12..79f4d87c 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 00000000..b187ed30 --- /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 4f9df255..0281576a 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 05/17] =?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 80ff1a11..82665bab 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 a15bcce6..c0edcce2 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 c5bc6d95..2667aaa6 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 595b0840..a158853e 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 e4d1618b..4db9b331 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 b187ed30..acb3f685 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 b462176d..4fcaadf9 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 f7096c00..d380d7f7 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 06/17] 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 28f6f231..4cba081f 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 1f801674..d041e432 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 880ca9e6..f0cd862d 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 ec6f318c..355db80c 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 c5ccc8a2..45d32de1 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 b5d14450..6525e755 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 4fcaadf9..1e809988 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 0aabe192..603d6192 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 07/17] 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 c0edcce2..8aa0b1ac 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 355db80c..7034d1aa 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 45d32de1..723b0f2c 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 acb3f685..b76f5dc9 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 08/17] 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 d8f44d80..c67fe336 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 8aa0b1ac..cb51936d 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 7034d1aa..16007f05 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 5b67f335..c2887f8d 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 b76f5dc9..ac4e8fbb 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 1e809988..142780c2 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 From 551d50e1e6d36607f557fa1aa13b59921691df99 Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Thu, 3 Sep 2026 21:09:34 +1000 Subject: [PATCH 09/17] fix(logging): scope the CWE-532 guarantee and guard it with an architecture test (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Expert-panel findings on b05c7ee (1 blocking, 2 major), applied: BLOCKER — SECURITY.md claimed keys "never reach logs verbatim". False for the flagship backend: CachekitIO addresses entries by key in the request path and httpx logs every request line at INFO on its own logger, so any app enabling INFO globally sees raw keys on the happy path. The claim is now scoped to the SDK's own loggers, with an httpx paragraph telling operators to raise that logger's level (mirrors the lock-token paragraph's reasoning). The SDK does not mute a third-party logger on the user's behalf. MAJOR — unkeyed blake2b was undocumented. Panel's own follow-up corrected my first draft: the digest is as guessable as the key material, and that holds for GENERATED keys too — the args hash is deterministic blake2b(msgpack(args)), so a get_user(user_id) cache is enumerable from its digest either way (verified: 1M ids in 0.01s). SECURITY.md "Digest strength" + the redact_cache_key docstring now say exactly that: correlation id, never a secret. MAJOR — ~30 hand-edited log lines with nothing stopping the next one from leaking. tests/unit/test_log_redaction_architecture.py walks every logging call in the package (logger.*, get_logger().*, logger().*, getLogger(...).*, getattr(logger, level)(), warnings) and fails if a key-shaped Name/Attribute/ subscript reaches it outside a redactor call. Panel mutation-tested the first cut and found it blind to get_logger().warning(...) — the ONLY shape in cache_handler.py — so receiver matching was widened and a 13-case self-test pins every shape it must flag or allow. Known blind spot (pre-built message variables) is documented in the module docstring and in SECURITY.md. orchestrator.py:471 now redacts inline (idempotent) so its safety is visible to the guard rather than depending on a rebinding 28 lines up. Out of scope, filed separately: the unquoted raw key in the CachekitIO URL path is also a path-traversal surface for attacker-influenced custom keys. --- SECURITY.md | 14 +- src/cachekit/decorators/orchestrator.py | 2 +- src/cachekit/hash_utils.py | 4 + tests/unit/test_log_redaction_architecture.py | 141 ++++++++++++++++++ 4 files changed, 159 insertions(+), 2 deletions(-) create mode 100644 tests/unit/test_log_redaction_architecture.py diff --git a/SECURITY.md b/SECURITY.md index 4cba081f..4df899c5 100644 --- a/SECURITY.md +++ b/SECURITY.md @@ -189,7 +189,19 @@ 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. `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. +Cache keys can embed caller-supplied tenant/user identifiers, so **the SDK's own loggers** (`cachekit.*`) never emit them verbatim ([CWE-532][cwe-532]). Every cachekit log path — decorator error handling (structured and backwards-compat), cache-operation logs, and SWR/TTL-refresh debug logs — replaces the key with a fixed-length blake2b digest (``), keeping log lines correlatable without leaking the key. Error paths are covered centrally at the shared error sink (`FeatureOrchestrator.handle_cache_error` / `log_cache_operation`), so new call sites are redacted by construction. `BackendError` redacts 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. An architecture test (`tests/unit/test_log_redaction_architecture.py`) walks every logging call in the package — `logger.*()`, `get_logger().*()`, `getattr(logger, level)()` — and fails CI if a key-shaped value reaches one unredacted in the message, `%s` arguments, or `extra=`, so the guarantee does not depend on the next contributor remembering it. It is flow-insensitive: build log lines inline, not via a pre-formatted variable, or the guard cannot see them. + +**Scope — transport logs are not covered.** The CachekitIO backend addresses entries by key in the request path (`GET /v1/cache/{key}`), and `httpx` logs every request line — method, full URL, status — at `INFO` on its own `httpx` logger. An application that enables `INFO` globally (`logging.basicConfig(level=logging.INFO)`) will therefore see raw keys in *httpx's* output on every operation, exactly as it would see any REST resource path. cachekit does not mute a third-party logger on your behalf; if your keys carry identifiers, silence or raise the level of that logger in your logging config: + +```python +import logging + +logging.getLogger("httpx").setLevel(logging.WARNING) +``` + +The same applies to any HTTP-layer capture between the SDK and `api.cachekit.io` — see the lock-token paragraph below for why path/query content is treated as logged. + +**Digest strength.** The redaction digest is *unkeyed* blake2b, so it is exactly as hard to reverse as the key material is to guess — and the key material is deterministic from the call: `[ns:{ns}:]func:{mod.fn}:args:{blake2b(args)}` for generated keys, or whatever you return from `@cache(key=...)`. Namespace and function name are static application config, so a cache on `get_user(user_id)` is enumerable from its digest by iterating plausible IDs, whether the key was generated (hash the candidate args) or hand-built (`default:user:1234`). A per-installation secret was considered and rejected for a public library (unset it is theatre; set it breaks cross-process log correlation, the property the digest exists for). Treat the digest as a correlation ID, never as a secret: if a log reader must not be able to confirm *which* user an entry belongs to, do not grant that reader the logs. ### Lock Token Transport (CWE-532) diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py index cb51936d..ae3f1f66 100644 --- a/src/cachekit/decorators/orchestrator.py +++ b/src/cachekit/decorators/orchestrator.py @@ -469,5 +469,5 @@ def handle_cache_error( logger_instance = get_logger_provider().get_logger(__name__) logger_instance.warning( - f"Cache operation '{operation}' failed for key '{cache_key}': {error!s} ({type(error).__name__})" + f"Cache operation '{operation}' failed for key '{redact_key_for_log(cache_key)}': {error!s} ({type(error).__name__})" ) diff --git a/src/cachekit/hash_utils.py b/src/cachekit/hash_utils.py index 16007f05..99605aa6 100644 --- a/src/cachekit/hash_utils.py +++ b/src/cachekit/hash_utils.py @@ -17,6 +17,10 @@ def redact_cache_key(cache_key: object) -> str: 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. + Unkeyed by design — cross-process correlation is the point. The digest is as guessable + as the key material (function args or a custom key), so it is a correlation id, not a + secret (see SECURITY.md, "Digest strength"). + Lives in this leaf module so backend/L1 modules can use it without importing cache_handler (which imports them). diff --git a/tests/unit/test_log_redaction_architecture.py b/tests/unit/test_log_redaction_architecture.py new file mode 100644 index 00000000..eb437caf --- /dev/null +++ b/tests/unit/test_log_redaction_architecture.py @@ -0,0 +1,141 @@ +"""Architecture test: no stdlib logger call may receive a raw cache key (CWE-532, LAB-304). + +The redaction sweep on PR #264 hand-edited ~30 log lines. Nothing stopped the +next ``logger.debug(f"... {key}")`` from landing with CI green — this does. + +For every logging call under ``src/cachekit`` — receiver a logger name +(``logger``, ``_logger``, ``self._logger``, ``logger_instance``, ``logging``, +``warnings``), a logger factory call (``get_logger()``, ``logger()``, +``logging.getLogger(...)``), or ``getattr(logger, level)(...)`` — any Name, +Attribute, or ``d["..."]`` subscript whose identifier is key-shaped (``key``, +``cache_key``, ``lock_key``, ``e.key``, ``kwargs["key"]`` ...) must be wrapped +in ``redact_cache_key`` / ``redact_key_for_log`` somewhere between it and the +call: in the message f-string, in ``%s`` arguments, or in ``extra=``. + +Known blind spot (flow-insensitive): a message pre-built into a variable +(``msg = f"miss {key}"; logger.debug(msg)``) is not traced. Build log lines +inline so the guard can see them. Sink-central redaction is not exempted: the +sinks' own stdlib calls satisfy the rule; callers passing raw keys *into* +``handle_cache_error`` / ``log_cache_operation`` / ``SimpleLogger.cache_*`` are +covered by those sinks' contract tests, not here. +""" + +from __future__ import annotations + +import ast +import re +from pathlib import Path + +SRC = Path(__file__).resolve().parents[2] / "src" / "cachekit" + +LOG_METHODS = frozenset({"debug", "info", "warning", "warn", "error", "critical", "exception", "log"}) +LOGGER_NAME_RE = re.compile(r"logg(?:er|ing)|^warnings$") # logger, _logger, logger_instance, logging, warnings +LOGGER_FACTORIES = frozenset({"get_logger", "logger", "getLogger", "get_structured_logger"}) +REDACTORS = frozenset({"redact_cache_key", "redact_key_for_log"}) +KEY_NAME_RE = re.compile(r"(?:^|_)key$") + + +def _call_name(node: ast.Call) -> str: + func = node.func + if isinstance(func, ast.Name): + return func.id + if isinstance(func, ast.Attribute): + return func.attr + return "" + + +def _call_args(node: ast.Call) -> list[ast.expr]: + return [*node.args, *(kw.value for kw in node.keywords)] + + +def _is_logger_receiver(node: ast.AST) -> bool: + if isinstance(node, ast.Name): + return bool(LOGGER_NAME_RE.search(node.id)) + if isinstance(node, ast.Attribute): # self.logger / self._logger + return bool(LOGGER_NAME_RE.search(node.attr)) + if isinstance(node, ast.Call): # get_logger().warning(...) / logging.getLogger(__name__).info(...) + return _call_name(node) in LOGGER_FACTORIES + return False + + +def _is_logger_call(node: ast.Call) -> bool: + func = node.func + if isinstance(func, ast.Attribute): + return func.attr in LOG_METHODS and _is_logger_receiver(func.value) + # getattr(logger, level.lower())(message, ...) + return isinstance(func, ast.Call) and _call_name(func) == "getattr" and bool(func.args) and _is_logger_receiver(func.args[0]) + + +def _key_identifier(node: ast.AST) -> str | None: + if isinstance(node, ast.Name) and KEY_NAME_RE.search(node.id): + return node.id + if isinstance(node, ast.Attribute) and KEY_NAME_RE.search(node.attr): + return ast.unparse(node) + if isinstance(node, ast.Subscript) and isinstance(node.slice, ast.Constant) and KEY_NAME_RE.search(str(node.slice.value)): + return ast.unparse(node) + return None + + +def _raw_keys(node: ast.AST) -> list[str]: + """Key-shaped identifiers under ``node`` not enclosed by a redactor call.""" + ident = _key_identifier(node) + if ident is not None: + return [ident] + found: list[str] = [] + if isinstance(node, ast.Call): + # The callee's own name is never a key (``redact_cache_key`` ends in ``_key``); + # only its receiver chain (``obj.key.method()``) can carry one. + if isinstance(node.func, ast.Attribute): + found.extend(_raw_keys(node.func.value)) + if _call_name(node) not in REDACTORS: + for child in _call_args(node): + found.extend(_raw_keys(child)) + return found + if isinstance(node, ast.IfExp): + # ``redact(key) if key else "unknown"`` — the test is a truthiness check, it never renders. + return _raw_keys(node.body) + _raw_keys(node.orelse) + for child in ast.iter_child_nodes(node): + found.extend(_raw_keys(child)) + return found + + +def _violations(root: Path) -> list[str]: + out: list[str] = [] + for path in sorted(root.rglob("*.py")): + tree = ast.parse(path.read_text(encoding="utf-8"), filename=str(path)) + for node in ast.walk(tree): + if not isinstance(node, ast.Call) or not _is_logger_call(node): + continue + leaks = [k for arg in _call_args(node) for k in _raw_keys(arg)] + if leaks: + out.append(f"{path.relative_to(root.parents[1])}:{node.lineno} logs raw {', '.join(sorted(set(leaks)))}") + return out + + +def test_no_raw_cache_key_reaches_a_logger_call() -> None: + violations = _violations(SRC) + assert not violations, "Raw cache keys reach a logger call (wrap in redact_key_for_log):\n " + "\n ".join(violations) + + +def test_detector_catches_the_shapes_it_claims_to() -> None: + """The guard is only as good as its detector — pin the shapes it must flag and must allow.""" + cases = [ + ("logger.debug(f'hit {key}')", True), # f-string + ("logger.debug('miss %s', cache_key)", True), # %-args + ("self._logger.warning('x', extra={'k': e.key})", True), # attribute in extra= + ("get_logger().error(f'set failed for {cache_key}')", True), # factory-call receiver (cache_handler.py style) + ("logger().warning(f'{lock_key}')", True), # module-level factory (wrapper.py style) + ("logging.getLogger(__name__).info('%s', kwargs['key'])", True), # getLogger + subscript + ("getattr(logger, level.lower())(f'{cache_key}')", True), # orchestrator.log_structured style + ("logger_instance.warning(f'{cache_key}')", True), # any *logger-suffixed receiver + ("logger.info('ok %s', redact_key_for_log(key))", False), # redacted %-arg + ("logger.info(f'{redact_cache_key(lock_key)}')", False), # redacted f-string + ("logger.debug('%d keys', len(expired_keys))", False), # plural: not a key + ("get_logger().warning(f\"{redact_cache_key(cache_key) if cache_key else 'unknown'}\")", False), # truthiness test + ("client.get(key)", False), # not a logger + ] + for src, expected in cases: + tree = ast.parse(src) + calls = [n for n in ast.walk(tree) if isinstance(n, ast.Call) and _is_logger_call(n)] + flagged = any(_raw_keys(a) for c in calls for a in _call_args(c)) + assert flagged is expected, f"{src!r}: expected flagged={expected}, got {flagged}" From 545f335888890ad7333f172833962b435da2a4fd Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Thu, 3 Sep 2026 22:16:24 +1000 Subject: [PATCH 10/17] fix(logging): sanitise exception text on error sinks; extend logger detector (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Close the residual CWE-532 channels a fresh review found on PR #264: - error_handler: TIMEOUT/TRANSIENT branches now emit only type(exc).__name__ (were interpolating raw {exc}), matching the PERMANENT/UNKNOWN branches. - l1_cache: both put() diagnostics use redact_key_for_log (idempotent sink policy) instead of the bare redact_cache_key. - redact_error_for_log(): render exceptions key-free for logs — BackendError is self-sanitising so it passes verbatim, every other exception collapses to its type name (str() has unknown provenance and may echo the raw key). Applied at handle_cache_error (both sinks) and redis_operation_failed. - LOGGER_NAME_RE now matches bare log/_log receivers so the architecture guard cannot be bypassed by log.warning(f"{key}"); detector + arch tests updated. CodeRabbit-Resolved: orchestrator.py:472:Sanitise exception values before logging CodeRabbit-Resolved: l1_cache.py:208:Use redact_key_for_log for both L1 diagnostic CodeRabbit-Resolved: test_log_redaction_architecture.py:32:Detect _log and log rec --- .../backends/memcached/error_handler.py | 13 +++++--- src/cachekit/decorators/orchestrator.py | 13 +++++--- src/cachekit/hash_utils.py | 22 +++++++++++++ src/cachekit/l1_cache.py | 6 ++-- src/cachekit/logging.py | 6 ++-- tests/unit/test_error_path_key_redaction.py | 31 +++++++++++++++++++ tests/unit/test_log_redaction_architecture.py | 8 ++++- tests/unit/test_structured_logging.py | 8 +++-- 8 files changed, 90 insertions(+), 17 deletions(-) diff --git a/src/cachekit/backends/memcached/error_handler.py b/src/cachekit/backends/memcached/error_handler.py index f0cd862d..c64f1907 100644 --- a/src/cachekit/backends/memcached/error_handler.py +++ b/src/cachekit/backends/memcached/error_handler.py @@ -48,20 +48,25 @@ def classify_memcached_error( MemcacheUnexpectedCloseError, ) - # Timeout — socket.timeout or OSError with ETIMEDOUT + # Timeout — socket.timeout or OSError with ETIMEDOUT. + # Only the exception TYPE goes in the message: wrapped provider text has + # unknown provenance and may echo the raw cache key, and the message reaches + # log sinks via str(e) (CWE-532). Full details stay on original_exception. if isinstance(exc, (socket.timeout, TimeoutError)): return BackendError( - message=f"Memcached timeout during {operation}: {exc}", + message=f"Memcached timeout during {operation}: {type(exc).__name__}", error_type=BackendErrorType.TIMEOUT, original_exception=exc, operation=operation, key=key, ) - # Transient — connection closed, server errors (retriable) + # Transient — connection closed, server errors (retriable). Type-only message: + # pymemcache close/server errors can echo the raw key, and str(e) reaches log + # sinks (CWE-532). Detail stays on original_exception. if isinstance(exc, (MemcacheUnexpectedCloseError, MemcacheServerError, ConnectionError, OSError)): return BackendError( - message=f"Memcached transient error during {operation}: {exc}", + message=f"Memcached transient error during {operation}: {type(exc).__name__}", error_type=BackendErrorType.TRANSIENT, original_exception=exc, operation=operation, diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py index ae3f1f66..e663e0ec 100644 --- a/src/cachekit/decorators/orchestrator.py +++ b/src/cachekit/decorators/orchestrator.py @@ -3,7 +3,7 @@ import uuid from typing import Any, Optional -from ..hash_utils import redact_key_for_log +from ..hash_utils import redact_error_for_log, redact_key_for_log from ..monitoring.correlation_tracking import CorrelationTracker from ..monitoring.pool_monitor import OptimizedPoolMonitor @@ -457,17 +457,22 @@ def handle_cache_error( operation=f"{operation}_failed", key=cache_key, namespace=namespace, - error=str(error), + # Key-free error text (CWE-532): an arbitrary exception's str() may echo + # the raw key, so only BackendError (self-sanitising) is logged verbatim. + error=redact_error_for_log(error), error_type=type(error).__name__, duration_ms=duration_ms, correlation_id=correlation_id, **extra_context, ) - # 5. Also log via standard logger for backwards compatibility + # 5. Also log via standard logger for backwards compatibility. Redact the key + # inline (idempotent: it is already redacted above, but the flow-insensitive + # architecture guard requires the wrapper on the logged expression) and keep + # the exception text key-free with redact_error_for_log (CWE-532). from ..cache_handler import get_logger_provider logger_instance = get_logger_provider().get_logger(__name__) logger_instance.warning( - f"Cache operation '{operation}' failed for key '{redact_key_for_log(cache_key)}': {error!s} ({type(error).__name__})" + f"Cache operation '{operation}' failed for key '{redact_key_for_log(cache_key)}': {redact_error_for_log(error)}" ) diff --git a/src/cachekit/hash_utils.py b/src/cachekit/hash_utils.py index 99605aa6..6b073fcc 100644 --- a/src/cachekit/hash_utils.py +++ b/src/cachekit/hash_utils.py @@ -71,6 +71,28 @@ def redact_key_for_log(cache_key: object) -> str: return redact_cache_key(key_str) +def redact_error_for_log(error: object) -> str: + """Render an exception for a log/error message without leaking cache keys. + + ``str(error)`` reaches log interpolation at every cache-error sink, and an + arbitrary exception's text has unknown provenance — a backend/serialization + error can echo the raw cache key (CWE-532, issue #163). So only ``BackendError`` + (which formats itself key-free: the message is the exception type name and any + key is emitted as a redacted digest — see ``BackendError._format_message``) is + logged verbatim; every other exception is reduced to its bare type name, with + the full detail left on the exception object for programmatic access. + + Sits beside redact_key_for_log() so both log sinks share one error policy. + ``BackendError`` is imported lazily to keep this leaf module free of a + back-edge to ``backends.errors`` (which imports this module). + """ + from cachekit.backends.errors import BackendError + + if isinstance(error, BackendError): + return str(error) + return type(error).__name__ + + 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 c2887f8d..b24f9130 100644 --- a/src/cachekit/l1_cache.py +++ b/src/cachekit/l1_cache.py @@ -12,7 +12,7 @@ from dataclasses import dataclass from typing import Any, Optional -from cachekit.hash_utils import redact_cache_key +from cachekit.hash_utils import redact_key_for_log logger = logging.getLogger(__name__) @@ -186,7 +186,7 @@ def put( 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)", - redact_cache_key(key), + redact_key_for_log(key), expiry, ) return @@ -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)", - redact_cache_key(key), + redact_key_for_log(key), size, self.max_memory_bytes, ) diff --git a/src/cachekit/logging.py b/src/cachekit/logging.py index 723b0f2c..75b4d386 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_key_for_log +from cachekit.hash_utils import redact_error_for_log, redact_key_for_log # Configure base logger logger = logging.getLogger(__name__) @@ -414,8 +414,8 @@ def _get_context(self) -> dict[str, Any]: # Compatibility methods for tests def redis_operation_failed(self, operation: str, key: str, error: Exception, **kwargs): - """Log Redis operation failure.""" - self.cache_operation(operation, key, error=str(error), error_type=type(error).__name__, **kwargs) + """Log Redis operation failure. Error text is key-free (CWE-532).""" + self.cache_operation(operation, key, error=redact_error_for_log(error), error_type=type(error).__name__, **kwargs) def cache_hit(self, key: str, **kwargs): """Log cache hit.""" diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index ac4e8fbb..ce7d560f 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/tests/unit/test_error_path_key_redaction.py @@ -251,3 +251,34 @@ def test_digest_matches_the_orchestrator_sink(self, caplog: pytest.LogCaptureFix 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, "") == "" + + +class TestRedactErrorForLog: + """Pin the two-branch contract of ``redact_error_for_log`` (CWE-532). + + BackendError formats itself key-free (type name + redacted key digest), so it is + logged verbatim; any other exception's ``str()`` has unknown provenance and may + echo the raw key, so it collapses to the bare type name. + """ + + def test_backenderror_passes_through_key_free(self) -> None: + from cachekit.hash_utils import redact_error_for_log + + err = BackendError( + message="Redis timeout during get: TimeoutError", + error_type=BackendErrorType.TIMEOUT, + operation="get", + key=TENANT_KEY, + ) + rendered = redact_error_for_log(err) + assert rendered == str(err) + assert TENANT_KEY not in rendered + assert redact_cache_key(TENANT_KEY) in rendered # key present only as its digest + + def test_arbitrary_exception_reduced_to_type_name(self) -> None: + from cachekit.hash_utils import redact_error_for_log + + # A raw provider exception whose text embeds the key must not leak it. + rendered = redact_error_for_log(ValueError(f"bad key: {TENANT_KEY}")) + assert rendered == "ValueError" + assert TENANT_KEY not in rendered diff --git a/tests/unit/test_log_redaction_architecture.py b/tests/unit/test_log_redaction_architecture.py index eb437caf..56b27807 100644 --- a/tests/unit/test_log_redaction_architecture.py +++ b/tests/unit/test_log_redaction_architecture.py @@ -29,7 +29,10 @@ SRC = Path(__file__).resolve().parents[2] / "src" / "cachekit" LOG_METHODS = frozenset({"debug", "info", "warning", "warn", "error", "critical", "exception", "log"}) -LOGGER_NAME_RE = re.compile(r"logg(?:er|ing)|^warnings$") # logger, _logger, logger_instance, logging, warnings +# logger, _logger, logger_instance, logging, warnings — plus bare log / _log receivers. +# The (?:^|_)log(?:ger|ging)?(?:_|$) arm anchors on a word boundary so key-shaped names +# that merely contain "log" (catalog, dialog, backlog) are not treated as loggers. +LOGGER_NAME_RE = re.compile(r"(?:^|_)log(?:ger|ging)?(?:_|$)|^warnings$") LOGGER_FACTORIES = frozenset({"get_logger", "logger", "getLogger", "get_structured_logger"}) REDACTORS = frozenset({"redact_cache_key", "redact_key_for_log"}) KEY_NAME_RE = re.compile(r"(?:^|_)key$") @@ -128,6 +131,9 @@ def test_detector_catches_the_shapes_it_claims_to() -> None: ("logging.getLogger(__name__).info('%s', kwargs['key'])", True), # getLogger + subscript ("getattr(logger, level.lower())(f'{cache_key}')", True), # orchestrator.log_structured style ("logger_instance.warning(f'{cache_key}')", True), # any *logger-suffixed receiver + ("_log.warning('cache failure: %s', cache_key)", True), # bare _log receiver + ("log.warning(f'{cache_key}')", True), # bare log receiver + ("catalog.get(key)", False), # 'log' substring is not a logger ("logger.info('ok %s', redact_key_for_log(key))", False), # redacted %-arg ("logger.info(f'{redact_cache_key(lock_key)}')", False), # redacted f-string ("logger.debug('%d keys', len(expired_keys))", False), # plural: not a key diff --git a/tests/unit/test_structured_logging.py b/tests/unit/test_structured_logging.py index 603d6192..5d46ee2e 100644 --- a/tests/unit/test_structured_logging.py +++ b/tests/unit/test_structured_logging.py @@ -171,14 +171,18 @@ def test_cache_operation_error_logging(self, mock_log, logger): @patch("cachekit.logging.logging.Logger.log") def test_redis_operation_failed_override(self, mock_log, logger): - """Test redis_operation_failed override.""" + """redis_operation_failed emits a key-free error representation (CWE-532). + + A non-BackendError's str() has unknown provenance and may echo the raw cache + key, so only its type name reaches the log; error_type still carries the type. + """ error = ValueError("Test error") logger.redis_operation_failed("get", "test_key", error) mock_log.assert_called_once() extra = mock_log.call_args[1]["extra"]["structured"] assert extra["operation"] == "get" - assert extra["error"] == "Test error" + assert extra["error"] == "ValueError" # not the raw "Test error" message assert extra["error_type"] == "ValueError" @patch("cachekit.logging.logging.Logger.log") From f2a7e5a1c77305850b1d8f98778019fd70fbb6b5 Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Thu, 3 Sep 2026 22:26:52 +1000 Subject: [PATCH 11/17] fix(logging): close redis/http BackendError.message key leak (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Expert-panel finding (CRITICAL, confirmed by bug-hunter + security independently): redact_error_for_log logs str(BackendError) verbatim on the premise "BackendError is key-free by construction", but only the memcached classifier had been hardened. The redis classifier/backend and the cachekit.io HTTP classifier still interpolated raw provider exception text into BackendError.message, which _format_message emits verbatim — so on the flagship backend the "trusted" branch surfaced exactly the untrusted provider text (redis ACL "NOPERM ... keys", WRONGTYPE, httpx request URL) that can echo the raw cache key. The trust assumption was unsound; the leak stayed open (CWE-532). Root-cause fix — make the invariant true tree-wide, mirroring the memcached branches: - redis/error_handler.py: every branch message is type(exc).__name__ only. - redis/backend.py: the five GET/SET/DELETE/EXISTS/client-create messages likewise. - cachekitio/error_handler.py: timeout/connect/unknown branches likewise (httpx text carries the URL, which embeds the key in its path). - Detail stays on original_exception; the key rides the .key attribute, redacted by _format_message. Tests: TestClassifierMessagesAreKeyFree asserts str(classify_*(exc_echoing_key, key)) contains the digest, never the raw key — covers the wrapped-BackendError path the logger-call architecture test cannot see. hash_utils module docstring now names it as the redaction-policy leaf home. CodeRabbit-Resolved: redis/error_handler.py:107:BackendError.message leaks raw exc text CodeRabbit-Resolved: cachekitio/error_handler.py:105:httpx exc text leaks key via URL --- .../backends/cachekitio/error_handler.py | 17 ++++--- src/cachekit/backends/redis/backend.py | 10 ++--- src/cachekit/backends/redis/error_handler.py | 19 +++++--- src/cachekit/hash_utils.py | 7 ++- tests/unit/test_error_path_key_redaction.py | 45 +++++++++++++++++++ 5 files changed, 79 insertions(+), 19 deletions(-) diff --git a/src/cachekit/backends/cachekitio/error_handler.py b/src/cachekit/backends/cachekitio/error_handler.py index 243752eb..fdb15cbf 100644 --- a/src/cachekit/backends/cachekitio/error_handler.py +++ b/src/cachekit/backends/cachekitio/error_handler.py @@ -99,29 +99,34 @@ def classify_http_error( key=key, ) - # TIMEOUT: Request exceeded time limit + # TIMEOUT: Request exceeded time limit. + # Only the exception TYPE goes in the message: httpx exception text embeds the + # request URL, which carries the raw cache key in its path, and the message reaches + # log sinks via str(e) (CWE-532, LAB-304). Detail stays on original_exception. if isinstance(exc, httpx.TimeoutException): return BackendError( - f"Request timeout: {exc}", + f"Request timeout: {type(exc).__name__}", error_type=BackendErrorType.TIMEOUT, original_exception=exc, operation=operation, key=key, ) - # TRANSIENT: Connection failures (retry) + # TRANSIENT: Connection failures (retry). Type-only message — httpx text can echo + # the request URL (raw key in path), and str(e) reaches log sinks (CWE-532). if isinstance(exc, (httpx.ConnectError, httpx.NetworkError)): return BackendError( - f"Connection failed: {exc}", + f"Connection failed: {type(exc).__name__}", error_type=BackendErrorType.TRANSIENT, original_exception=exc, operation=operation, key=key, ) - # UNKNOWN: Unclassified error + # UNKNOWN: Unclassified error. Type-only message (CWE-532): arbitrary httpx text + # can echo the request URL, which carries the raw key. Detail on original_exception. return BackendError( - f"Unknown HTTP error: {exc}", + f"Unknown HTTP error: {type(exc).__name__}", error_type=BackendErrorType.UNKNOWN, original_exception=exc, operation=operation, diff --git a/src/cachekit/backends/redis/backend.py b/src/cachekit/backends/redis/backend.py index 2e3850fe..9c8de517 100644 --- a/src/cachekit/backends/redis/backend.py +++ b/src/cachekit/backends/redis/backend.py @@ -113,7 +113,7 @@ def _get_client(self) -> redis.Redis: return self._client_provider.get_sync_client() except Exception as e: raise BackendError( - message=f"Failed to create Redis client: {e}", + message=f"Failed to create Redis client: {type(e).__name__}", operation="get_client", ) from e @@ -139,7 +139,7 @@ def get(self, key: str) -> Optional[bytes]: return value if isinstance(value, bytes) else None except Exception as e: raise BackendError( - message=f"Redis GET failed: {e}", + message=f"Redis GET failed: {type(e).__name__}", operation="get", key=key, ) from e @@ -165,7 +165,7 @@ def set(self, key: str, value: bytes, ttl: Optional[int] = None) -> None: client.set(key, value) except Exception as e: raise BackendError( - message=f"Redis SET failed: {e}", + message=f"Redis SET failed: {type(e).__name__}", operation="set", key=key, ) from e @@ -195,7 +195,7 @@ def delete(self, key: str) -> bool: return result > 0 except Exception as e: raise BackendError( - message=f"Redis DELETE failed: {e}", + message=f"Redis DELETE failed: {type(e).__name__}", operation="delete", key=key, ) from e @@ -225,7 +225,7 @@ def exists(self, key: str) -> bool: return result > 0 except Exception as e: raise BackendError( - message=f"Redis EXISTS failed: {e}", + message=f"Redis EXISTS failed: {type(e).__name__}", operation="exists", key=key, ) from e diff --git a/src/cachekit/backends/redis/error_handler.py b/src/cachekit/backends/redis/error_handler.py index bd7b4e28..245b2353 100644 --- a/src/cachekit/backends/redis/error_handler.py +++ b/src/cachekit/backends/redis/error_handler.py @@ -85,6 +85,11 @@ def classify_redis_error( - ReadOnlyError, ClusterDownError: TRANSIENT (temporary cluster state) - All others: UNKNOWN (log and investigate) """ + # Every branch below puts only type(exc).__name__ in the message, never the raw + # exception text: redis-py surfaces the offending key in ResponseError/NoPermission + # text ("NOPERM ... keys used as arguments", "WRONGTYPE ... key ..."), and the + # message reaches log sinks via str(e) (CWE-532, LAB-304). Full detail stays on + # original_exception; the key is on the .key attribute (redacted by _format_message). # Import here to avoid circular dependency and handle missing redis try: from redis.exceptions import ( @@ -104,7 +109,7 @@ def classify_redis_error( except ImportError: # Redis not installed - treat as unknown error return BackendError( - f"Redis error (redis-py not installed): {exc!s}", + f"Redis error (redis-py not installed): {type(exc).__name__}", error_type=BackendErrorType.UNKNOWN, original_exception=exc, operation=operation, @@ -114,7 +119,7 @@ def classify_redis_error( # AUTHENTICATION: Credential/auth issues (check FIRST - subclass of ConnectionError) if isinstance(exc, (AuthenticationError, NoPermissionError)): return BackendError( - f"Redis authentication error: {exc!s}", + f"Redis authentication error: {type(exc).__name__}", error_type=BackendErrorType.AUTHENTICATION, original_exception=exc, operation=operation, @@ -124,7 +129,7 @@ def classify_redis_error( # TIMEOUT: Operation exceeded time limit if isinstance(exc, RedisTimeoutError): return BackendError( - f"Redis timeout: {exc!s}", + f"Redis timeout: {type(exc).__name__}", error_type=BackendErrorType.TIMEOUT, original_exception=exc, operation=operation, @@ -134,7 +139,7 @@ def classify_redis_error( # TRANSIENT: Temporary failures, retry with exponential backoff if isinstance(exc, (RedisConnectionError, BusyLoadingError, ReadOnlyError)): return BackendError( - f"Transient Redis error: {exc!s}", + f"Transient Redis error: {type(exc).__name__}", error_type=BackendErrorType.TRANSIENT, original_exception=exc, operation=operation, @@ -144,7 +149,7 @@ def classify_redis_error( # PERMANENT: Unfixable errors (data format, protocol errors) if isinstance(exc, (ResponseError, DataError)): return BackendError( - f"Permanent Redis error: {exc!s}", + f"Permanent Redis error: {type(exc).__name__}", error_type=BackendErrorType.PERMANENT, original_exception=exc, operation=operation, @@ -157,7 +162,7 @@ def classify_redis_error( if isinstance(exc, ClusterDownError): return BackendError( - f"Redis cluster down: {exc!s}", + f"Redis cluster down: {type(exc).__name__}", error_type=BackendErrorType.TRANSIENT, original_exception=exc, operation=operation, @@ -168,7 +173,7 @@ def classify_redis_error( # UNKNOWN: Unclassified error - log for investigation return BackendError( - f"Unknown Redis error: {exc!s}", + f"Unknown Redis error: {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 6b073fcc..04412497 100644 --- a/src/cachekit/hash_utils.py +++ b/src/cachekit/hash_utils.py @@ -1,6 +1,11 @@ -"""Standardized hashing utilities for cachekit. +"""Standardized hashing and log-redaction utilities for cachekit. Uses BLAKE3 for hashing (approximately 2-3 GB/s throughput). + +This is also the leaf home for the log-redaction policy — ``redact_cache_key``, +``redact_key_for_log`` and ``redact_error_for_log`` (CWE-532). It lives here, not in +``cache_handler`` or ``backends.errors``, so backend/L1 modules can share one policy +without an import cycle (``backends.errors`` imports this module). """ import hashlib diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index ce7d560f..1c8cc07c 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/tests/unit/test_error_path_key_redaction.py @@ -282,3 +282,48 @@ def test_arbitrary_exception_reduced_to_type_name(self) -> None: rendered = redact_error_for_log(ValueError(f"bad key: {TENANT_KEY}")) assert rendered == "ValueError" assert TENANT_KEY not in rendered + + +class TestClassifierMessagesAreKeyFree: + """Every backend classifier must build a key-free BackendError.message (CWE-532). + + This is the invariant ``redact_error_for_log`` relies on when it logs a BackendError + verbatim: provider exception text (redis ACL/WRONGTYPE, httpx URL, pymemcache) can + echo the raw key, so no classifier may interpolate ``str(exc)`` into the message — + only ``type(exc).__name__``. Detail stays on ``original_exception``; the key rides + the ``.key`` attribute, which ``_format_message`` redacts. Guards against the wrapped + path the logger-call architecture test cannot see (a BackendError construction, not a + logger call). + """ + + def test_redis_classifier_does_not_leak_key(self) -> None: + redis_exc = pytest.importorskip("redis.exceptions") + from cachekit.backends.redis.error_handler import classify_redis_error + + # redis-py ResponseError text echoes the offending key verbatim (ACL/WRONGTYPE); + # ResponseError classifies PERMANENT — a real branch, not the UNKNOWN fallback. + exc = redis_exc.ResponseError(f"WRONGTYPE Operation against key {TENANT_KEY}") + err = classify_redis_error(exc, operation="get", key=TENANT_KEY) + assert TENANT_KEY not in str(err) + assert redact_cache_key(TENANT_KEY) in str(err) # key present only as its digest + + def test_http_classifier_does_not_leak_key(self) -> None: + import httpx + + from cachekit.backends.cachekitio.error_handler import classify_http_error + + # httpx exception text carries the request URL, which embeds the raw key in its path. + exc = httpx.ConnectError(f"Connection refused to https://api.cachekit.io/v1/cache/{TENANT_KEY}") + err = classify_http_error(exc, operation="get", key=TENANT_KEY) + assert TENANT_KEY not in str(err) + assert redact_cache_key(TENANT_KEY) in str(err) + + def test_memcached_classifier_does_not_leak_key(self) -> None: + from cachekit.backends.memcached.error_handler import classify_memcached_error + + # TIMEOUT/TRANSIENT branches previously interpolated raw {exc}. socket.timeout is + # an alias of TimeoutError (3.10+), which the TIMEOUT branch matches. + exc = TimeoutError(f"timed out serving key {TENANT_KEY}") + err = classify_memcached_error(exc, operation="get", key=TENANT_KEY) + assert TENANT_KEY not in str(err) + assert redact_cache_key(TENANT_KEY) in str(err) From a8241a3b8f762adddf6d0c4d834f4325979e50c9 Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Thu, 3 Sep 2026 22:42:45 +1000 Subject: [PATCH 12/17] fix(logging): redact_error_for_log renders BackendError structurally, never its message (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CodeRabbit (round 2) correctly pushed past the classifier fixes: redact_error_for_log still *trusted* str(BackendError), so a future BackendError(f"...{raw_key}...", key=...) would leak — _format_message copies the free-form .message verbatim. Trusting the key-free invariant is not the same as enforcing it. Defense-in-depth: the helper now logs NO free-form exception text. A BackendError is rendered from allow-listed non-key fields only — the Python type plus the BackendErrorType classification (e.g. "BackendError(timeout)"); .message and raw .key are never read. The redacted key digest is already emitted in the separate `key` log field. Every other exception still collapses to its type name. The classifier message fixes (previous commit) remain necessary — ~30 other sinks interpolate str(BackendError)/{e} directly and rely on .message being key-free — so both layers stand: classifiers keep .message clean for the direct-str sinks, this helper never reads .message for the sinks it controls. Tests: added a regression with a key-bearing BackendError.message (CodeRabbit's ask) — redact_error_for_log must not leak it; updated the passthrough test to the structured representation. CodeRabbit-Resolved: hash_utils.py:97:Do not trust every BackendError as key-safe CodeRabbit-Resolved: test_error_path_key_redaction.py:274:regression for key-bearing message --- src/cachekit/hash_utils.py | 28 +++++++++++++-------- tests/unit/test_error_path_key_redaction.py | 23 ++++++++++++----- 2 files changed, 34 insertions(+), 17 deletions(-) diff --git a/src/cachekit/hash_utils.py b/src/cachekit/hash_utils.py index 04412497..be3dc274 100644 --- a/src/cachekit/hash_utils.py +++ b/src/cachekit/hash_utils.py @@ -77,24 +77,30 @@ def redact_key_for_log(cache_key: object) -> str: def redact_error_for_log(error: object) -> str: - """Render an exception for a log/error message without leaking cache keys. + """Render an exception for a log/error message without leaking cache keys (CWE-532). - ``str(error)`` reaches log interpolation at every cache-error sink, and an - arbitrary exception's text has unknown provenance — a backend/serialization - error can echo the raw cache key (CWE-532, issue #163). So only ``BackendError`` - (which formats itself key-free: the message is the exception type name and any - key is emitted as a redacted digest — see ``BackendError._format_message``) is - logged verbatim; every other exception is reduced to its bare type name, with - the full detail left on the exception object for programmatic access. + An exception's ``str()`` reaches log interpolation at every cache-error sink and has + unknown provenance: it can echo the raw cache key directly (a redis ResponseError + naming the key) or transitively (a ``BackendError`` whose free-form ``.message`` was + built with the key). So this helper logs **no free-form exception text at all** — it + does not trust that ``.message`` is key-free, it structurally cannot include it: + + - ``BackendError`` is rendered from its allow-listed, non-key fields only — the Python + type plus the ``BackendErrorType`` classification (``.error_type``, an enum of fixed + verbs). Its ``.message`` and raw ``.key`` are never read here; the redacted key digest + is already emitted in the separate ``key`` log field, and full detail stays on the + exception object for programmatic access. + - Every other exception collapses to its bare type name. Sits beside redact_key_for_log() so both log sinks share one error policy. - ``BackendError`` is imported lazily to keep this leaf module free of a - back-edge to ``backends.errors`` (which imports this module). + ``BackendError`` is imported lazily to keep this leaf module free of a back-edge to + ``backends.errors`` (which imports this module). """ from cachekit.backends.errors import BackendError if isinstance(error, BackendError): - return str(error) + error_type = getattr(error.error_type, "value", error.error_type) + return f"{type(error).__name__}({error_type})" return type(error).__name__ diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index 1c8cc07c..31a3ec6d 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/tests/unit/test_error_path_key_redaction.py @@ -256,12 +256,12 @@ def test_falsy_key_emits_empty_string(self, caplog: pytest.LogCaptureFixture) -> class TestRedactErrorForLog: """Pin the two-branch contract of ``redact_error_for_log`` (CWE-532). - BackendError formats itself key-free (type name + redacted key digest), so it is - logged verbatim; any other exception's ``str()`` has unknown provenance and may - echo the raw key, so it collapses to the bare type name. + It logs NO free-form exception text: a BackendError renders from allow-listed + non-key fields (type + BackendErrorType classification), never its .message; every + other exception collapses to its bare type name. """ - def test_backenderror_passes_through_key_free(self) -> None: + def test_backenderror_renders_type_and_classification(self) -> None: from cachekit.hash_utils import redact_error_for_log err = BackendError( @@ -270,10 +270,21 @@ def test_backenderror_passes_through_key_free(self) -> None: operation="get", key=TENANT_KEY, ) + assert redact_error_for_log(err) == "BackendError(timeout)" + + def test_backenderror_with_key_bearing_message_does_not_leak(self) -> None: + """Defense-in-depth: even a BackendError whose .message embeds the raw key + (a construction-site mistake) must not leak it — the message is never read.""" + from cachekit.hash_utils import redact_error_for_log + + err = BackendError( + message=f"provider failure for {TENANT_KEY}", # poisoned message + error_type=BackendErrorType.UNKNOWN, + key=TENANT_KEY, + ) rendered = redact_error_for_log(err) - assert rendered == str(err) assert TENANT_KEY not in rendered - assert redact_cache_key(TENANT_KEY) in rendered # key present only as its digest + assert rendered == "BackendError(unknown)" def test_arbitrary_exception_reduced_to_type_name(self) -> None: from cachekit.hash_utils import redact_error_for_log From 6d4d421b10de5e17f36995c2f42684daa9863f12 Mon Sep 17 00:00:00 2001 From: Mark S Date: Sat, 12 Sep 2026 16:03:35 +1000 Subject: [PATCH 13/17] fix(logging): render exceptions structurally at every log sink; guard it by AST (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CodeRabbit r3995269772 / r3995291342 / r3995291346 and Kody r3995268105 on 1810c57, all converging on one gap: redact_error_for_log (a8241a3) was applied at the orchestrator and cachekit.logging sinks only. ~80 direct logger calls in cache_handler, wrapper, l1_cache, the redis and cachekitio backends, the serializers, reliability and hiredis_compat still interpolated the exception verbatim — and BackendError._format_message keeps the caller's free-form message, so a WRONGTYPE ResponseError or a pymemcache illegal-input error rode {e} into the log with the key in it. SECURITY.md said str(e) was safe at any sink. It was not. Every logging call in the package now renders the exception through redact_error_for_log: type name, plus the BackendErrorType classification for BackendError. Provider message text stays on the exception object (.message / original_exception) for programmatic use and is gone from the log line — the accepted cost, stated in SECURITY.md. Applied uniformly, including modules that can never see a key (hiredis shim, Prometheus errors): an allow-list of "modules that don't touch keys" is a fact that changes silently; one rule the guard can enforce does not. tests/unit/test_log_redaction_architecture.py now flags, in any logging call: an exception-shaped identifier — every name bound by `except ... as` in the file, plus conventional names and *_err suffixes — or an attribute of one, outside redact_error_for_log; and any traceback emission (logger.exception, exc_info=). Expert panel (4 agents, high stakes) mutation-tested the first cut and found the regex anchored to bare names, leaving {hook_err} and two {del_err} sinks in cache_handler live while the guard reported clean — the except-handler capture is the name-agnostic fix, and those three sites are now wrapped. Panel also had two more regex misfires reverted (raise ConfigurationError messages are not log lines), three now-uninformative lines given key correlation (store_result, double-check-after-lock, interop deserialize), the redaction test matrix consolidated onto one ERRORS list so set/delete/TTL/invalidation all run key-bearing exception shapes, and the BackendError rationale comment corrected. Kody's other three threads are rejected on the PR with reasons: two read the removal of caller-side redact_cache_key() as a leak when redaction moved to the handle_cache_error sink (pinned by test_orchestrator_error_handling), and the fourth repeat of 'no assert for validation' fires on pytest test files. --- .secrets.baseline | 4 +- SECURITY.md | 2 +- src/cachekit/backends/cachekitio/backend.py | 3 +- src/cachekit/backends/errors.py | 9 +- src/cachekit/backends/redis/provider.py | 5 +- src/cachekit/cache_handler.py | 104 +++++++------ src/cachekit/decorators/wrapper.py | 58 +++++--- src/cachekit/hiredis_compat.py | 8 +- src/cachekit/l1_cache.py | 4 +- src/cachekit/logging.py | 2 +- src/cachekit/reliability/async_metrics.py | 6 +- .../reliability/metrics_collection.py | 10 +- src/cachekit/serializers/__init__.py | 3 +- src/cachekit/serializers/auto_serializer.py | 5 +- tests/unit/test_error_path_key_redaction.py | 43 +++--- tests/unit/test_l2_decrypt_observability.py | 5 +- tests/unit/test_log_redaction_architecture.py | 138 +++++++++++++----- 17 files changed, 265 insertions(+), 144 deletions(-) diff --git a/.secrets.baseline b/.secrets.baseline index 8e41a3c1..01bc84bd 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": 445 + "line_number": 447 } ], "src/cachekit/config/decorator.py": [ @@ -887,5 +887,5 @@ } ] }, - "generated_at": "2026-09-11T11:26:15Z" + "generated_at": "2026-09-12T06:03:16Z" } diff --git a/SECURITY.md b/SECURITY.md index c716492b..35ae30d2 100644 --- a/SECURITY.md +++ b/SECURITY.md @@ -189,7 +189,7 @@ See [SSRF Protection](docs/features/ssrf-protection.md) for full details, includ ### Cache Key Redaction in Logs (CWE-532) -Cache keys can embed caller-supplied tenant/user identifiers, so **the SDK's own loggers** (`cachekit.*`) never emit them verbatim ([CWE-532][cwe-532]). Every cachekit log path — decorator error handling (structured and backwards-compat), cache-operation logs, and SWR/TTL-refresh debug logs — replaces the key with a fixed-length blake2b digest (``), keeping log lines correlatable without leaking the key. Error paths are covered centrally at the shared error sink (`FeatureOrchestrator.handle_cache_error` / `log_cache_operation`), so new call sites are redacted by construction. `BackendError` redacts 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. An architecture test (`tests/unit/test_log_redaction_architecture.py`) walks every logging call in the package — `logger.*()`, `get_logger().*()`, `getattr(logger, level)()` — and fails CI if a key-shaped value reaches one unredacted in the message, `%s` arguments, or `extra=`, so the guarantee does not depend on the next contributor remembering it. It is flow-insensitive: build log lines inline, not via a pre-formatted variable, or the guard cannot see them. +Cache keys can embed caller-supplied tenant/user identifiers, so **the SDK's own loggers** (`cachekit.*`) never emit them verbatim ([CWE-532][cwe-532]). Every cachekit log path — decorator error handling (structured and backwards-compat), cache-operation logs, and SWR/TTL-refresh debug logs — replaces the key with a fixed-length blake2b digest (``), keeping log lines correlatable without leaking the key. Error paths are covered centrally at the shared error sink (`FeatureOrchestrator.handle_cache_error` / `log_cache_operation`), so new call sites are redacted by construction. `BackendError` redacts its `key` at construction, but its free-form `message` is caller-supplied and third-party exception text (a redis `ResponseError` naming the key, a pymemcache illegal-input error echoing it) has unknown provenance — so **no cachekit log line renders `str(e)`**. Every logging call that mentions an exception goes through `redact_error_for_log`, which emits only the exception type plus, for `BackendError`, its `BackendErrorType` classification; the full exception stays on the object (`original_exception`, `.message`) for programmatic access. Operators lose the provider's message text in the log line and keep it on the exception. An architecture test (`tests/unit/test_log_redaction_architecture.py`) walks every logging call in the package — `logger.*()`, `get_logger().*()`, `getattr(logger, level)()` — and fails CI if a key-shaped value reaches one unredacted in the message, `%s` arguments, or `extra=`; if an exception — any name bound by `except ... as`, a conventional name (`e`, `exc`, `err`, `error`, `*_err`), or an attribute of one — reaches one outside `redact_error_for_log`; or if a call emits a traceback (`logger.exception`, `exc_info=`). The guarantee does not depend on the next contributor remembering it. It is flow-insensitive: build log lines inline, not via a pre-formatted variable, and bind exceptions with `except ... as` or a conventional name (an `Exception`-typed parameter called `failure` is invisible to it), or the guard cannot see them. **Scope — transport logs are not covered.** The CachekitIO backend addresses entries by key in the request path (`GET /v1/cache/{key}`), and `httpx` logs every request line — method, full URL, status — at `INFO` on its own `httpx` logger. An application that enables `INFO` globally (`logging.basicConfig(level=logging.INFO)`) will therefore see raw keys in *httpx's* output on every operation, exactly as it would see any REST resource path. cachekit does not mute a third-party logger on your behalf; if your keys carry identifiers, silence or raise the level of that logger in your logging config: diff --git a/src/cachekit/backends/cachekitio/backend.py b/src/cachekit/backends/cachekitio/backend.py index d817c4de..213211f3 100644 --- a/src/cachekit/backends/cachekitio/backend.py +++ b/src/cachekit/backends/cachekitio/backend.py @@ -19,6 +19,7 @@ from cachekit.backends.cachekitio.error_handler import classify_http_error from cachekit.backends.errors import BackendError, BackendErrorType from cachekit.decorators.stats_context import get_current_function_stats +from cachekit.hash_utils import redact_error_for_log from cachekit.logging import get_structured_logger if TYPE_CHECKING: @@ -159,7 +160,7 @@ def _inject_metrics_headers(stats: _FunctionStats | None) -> dict[str, str]: except Exception as e: # Session header generation failed - continue without session headers # This ensures backend requests never fail due to session tracking issues - _logger.debug(f"Session header generation failed: {e}") + _logger.debug(f"Session header generation failed: {redact_error_for_log(e)}") session_headers = {} # Build metrics headers diff --git a/src/cachekit/backends/errors.py b/src/cachekit/backends/errors.py index 82665bab..27e04112 100644 --- a/src/cachekit/backends/errors.py +++ b/src/cachekit/backends/errors.py @@ -103,10 +103,11 @@ def _format_message(self) -> str: if self.operation: parts.append(f"operation={self.operation}") if self.key: - # 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. + # Redact, don't truncate: cachekit's own sinks never render str(e) + # (they go through redact_error_for_log), but application code may + # log it, and cache keys embed caller-supplied tenant/user identifiers + # (CWE-532, LAB-304). The fixed-length digest keeps that text + # 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}") diff --git a/src/cachekit/backends/redis/provider.py b/src/cachekit/backends/redis/provider.py index 901f98e2..c891e93f 100644 --- a/src/cachekit/backends/redis/provider.py +++ b/src/cachekit/backends/redis/provider.py @@ -23,6 +23,7 @@ from cachekit.backends.base import BaseBackend from cachekit.backends.errors import BackendError from cachekit.backends.redis.error_handler import classify_redis_error +from cachekit.hash_utils import redact_error_for_log logger = logging.getLogger(__name__) @@ -387,7 +388,7 @@ async def acquire_lock( await asyncio.to_thread(lock.release) except Exception as e: # Lock may have expired - log but don't fail - logger.debug("Error releasing Redis lock (may have expired): %s", e) + logger.debug("Error releasing Redis lock (may have expired): %s", redact_error_for_log(e)) except Exception as exc: raise classify_redis_error(exc, operation="acquire_lock", key=key) from exc @@ -498,4 +499,4 @@ def close(self) -> None: self._pool.disconnect() except Exception as e: # Best effort cleanup - log but don't raise - logger.debug("Error closing Redis connection pool: %s", e) + logger.debug("Error closing Redis connection pool: %s", redact_error_for_log(e)) diff --git a/src/cachekit/cache_handler.py b/src/cachekit/cache_handler.py index d27111ec..91d937e3 100644 --- a/src/cachekit/cache_handler.py +++ b/src/cachekit/cache_handler.py @@ -31,7 +31,7 @@ # 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.hash_utils import redact_cache_key, redact_error_for_log from cachekit.interop import InteropError from cachekit.key_generator import CacheKeyGenerator from cachekit.serializers.base import ( @@ -166,10 +166,12 @@ def handle_decrypt_failure(error: Exception, *, tier: str, cache_key: str, fail_ if fail_closed and isinstance(error, DecryptionAuthenticationError): get_logger().error( f"{tier.upper()} cache decrypt AUTHENTICATION failure for {redact_cache_key(cache_key)}; " - f"failing closed (encryption.fail_closed=True): {error}" + f"failing closed (encryption.fail_closed=True): {redact_error_for_log(error)}" ) raise error - get_logger().warning(f"{tier.upper()} cache decrypt/integrity failure ({reason}) for {redact_cache_key(cache_key)}: {error}") + get_logger().warning( + f"{tier.upper()} cache decrypt/integrity failure ({reason}) for {redact_cache_key(cache_key)}: {redact_error_for_log(error)}" + ) return reason @@ -333,7 +335,7 @@ def _get_cached_serializer_class(serializer_name: str, import_path: str): return serializer_class except (ImportError, AttributeError) as e: - get_logger().warning(f"Failed to import serializer {import_path}: {e}") + get_logger().warning(f"Failed to import serializer {import_path}: {redact_error_for_log(e)}") raise @@ -743,7 +745,7 @@ def _get_deterministic_deployment_uuid(self, provided_uuid: Optional[str]) -> st get_logger().info(f"Generated and persisted new deployment UUID: {new_uuid} at {deployment_uuid_file}") except Exception as e: get_logger().error( - f"Failed to persist deployment UUID to {deployment_uuid_file}: {e}. " + f"Failed to persist deployment UUID to {deployment_uuid_file}: {redact_error_for_log(e)}. " "UUID will be regenerated on next restart (cache will be invalidated)." ) @@ -930,7 +932,7 @@ def serialize_data( raise except Exception as e: # Don't silently fallback - log error and raise to prevent data loss - get_logger().error(f"Serialization failed with {self.serializer_name}: {e}") + get_logger().error(f"Serialization failed with {self.serializer_name}: {redact_error_for_log(e)}") raise SerializationError(f"Failed to serialize data with {self.serializer_name}: {e}") from e # L2 oversized-entry ceiling (issue #163): every L2 write flows through here, @@ -1159,7 +1161,7 @@ def deserialize_data(self, data: str | bytes | memoryview, cache_key: str = "") # SerializationError/EncryptionError: let the outer handler log and handle raise except Exception as e: - get_logger().error(f"Deserialization failed with {self.serializer_name}: {e}") + get_logger().error(f"Deserialization failed with {self.serializer_name}: {redact_error_for_log(e)}") raise SerializationError(f"Failed to deserialize data with {self.serializer_name}: {e}") from e def _deserialize_interop(self, data: str | bytes | memoryview, cache_key: str) -> Any: @@ -1204,7 +1206,7 @@ def _deserialize_interop(self, data: str | bytes | memoryview, cache_key: str) - except (ValueError, SerializationError): raise except Exception as e: - get_logger().error(f"Interop deserialization failed: {e}") + get_logger().error(f"Interop deserialization failed for {redact_cache_key(cache_key)}: {redact_error_for_log(e)}") raise SerializationError(f"Failed to deserialize interop cache entry: {e}") from e @@ -1271,7 +1273,9 @@ 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 {redact_cache_key(cache_key)}: {hook_err}") + get_logger().warning( + f"on_deserialize_error hook failed for {redact_cache_key(cache_key)}: {redact_error_for_log(hook_err)}" + ) def get_cache_key( self, @@ -1331,7 +1335,9 @@ def _handle_l2_read_error(self, e: SerializationError, cache_key: str) -> None: if self._cache_handler is not None: self._cache_handler.delete(cache_key) except Exception as del_err: # best-effort eviction; never mask the miss/recompute - get_logger().warning(f"Failed to evict poisoned L2 entry {redact_cache_key(cache_key)}: {del_err}") + get_logger().warning( + f"Failed to evict poisoned L2 entry {redact_cache_key(cache_key)}: {redact_error_for_log(del_err)}" + ) self._notify_deserialize_error(e, cache_key) async def _handle_l2_read_error_async(self, e: SerializationError, cache_key: str) -> None: @@ -1341,7 +1347,9 @@ async def _handle_l2_read_error_async(self, e: SerializationError, cache_key: st if self._cache_handler is not None: await self._cache_handler.delete_async(cache_key) except Exception as del_err: # best-effort eviction; never mask the miss/recompute - get_logger().warning(f"Failed to evict poisoned L2 entry {redact_cache_key(cache_key)}: {del_err}") + get_logger().warning( + f"Failed to evict poisoned L2 entry {redact_cache_key(cache_key)}: {redact_error_for_log(del_err)}" + ) self._notify_deserialize_error(e, cache_key) def get_cached_value(self, cache_key: str, refresh_ttl: Optional[int] = None) -> Optional[Any]: @@ -1397,7 +1405,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 {redact_cache_key(cache_key)}: {e}") + get_logger().warning(f"Backend operation failed for get on {redact_cache_key(cache_key)}: {redact_error_for_log(e)}") return None def get_cached_value_with_freshness(self, cache_key: str) -> Optional[tuple[tuple[bool, Any], bool, Optional[int]]]: @@ -1441,7 +1449,7 @@ def get_cached_value_with_freshness(self, cache_key: str) -> Optional[tuple[tupl 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 {redact_cache_key(cache_key)}: {e}") + get_logger().warning(f"Backend operation failed for get on {redact_cache_key(cache_key)}: {redact_error_for_log(e)}") return None async def get_cached_value_with_freshness_async( @@ -1482,7 +1490,7 @@ async def get_cached_value_with_freshness_async( 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 {redact_cache_key(cache_key)}: {e}") + get_logger().warning(f"Backend operation failed for get on {redact_cache_key(cache_key)}: {redact_error_for_log(e)}") return None async def get_cached_value_async(self, cache_key: str, refresh_ttl: Optional[int] = None) -> Optional[Any]: @@ -1529,7 +1537,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 {redact_cache_key(cache_key)}: {e}") + get_logger().warning(f"Backend operation failed for get on {redact_cache_key(cache_key)}: {redact_error_for_log(e)}") return None def store_result( @@ -1604,7 +1612,9 @@ def store_result( # silently never cached" (spec-mandated; matches cachekit-ts). raise except Exception as e: - get_logger().warning(f"Failed to store in backend cache: {e}") + get_logger().warning( + f"Failed to store in backend cache for {redact_cache_key(cache_key)}: {redact_error_for_log(e)}" + ) return None async def store_result_async( @@ -1670,7 +1680,9 @@ async def store_result_async( # silently never cached" (spec-mandated; matches cachekit-ts). raise except Exception as e: - get_logger().warning(f"Failed to store in backend cache: {e}") + get_logger().warning( + f"Failed to store in backend cache for {redact_cache_key(cache_key)}: {redact_error_for_log(e)}" + ) return None def set_cache_handler(self, handler: CacheHandlerStrategy): @@ -1741,9 +1753,11 @@ 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 {redact_cache_key(cache_key)}: {e}") + get_logger().error( + f"Backend operation failed for invalidation on {redact_cache_key(cache_key)}: {redact_error_for_log(e)}" + ) except Exception as e: - get_logger().error(f"Unexpected error invalidating {redact_cache_key(cache_key)}: {e}") + get_logger().error(f"Unexpected error invalidating {redact_cache_key(cache_key)}: {redact_error_for_log(e)}") async def invalidate_cache_async( self, @@ -1773,9 +1787,11 @@ 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 {redact_cache_key(cache_key)}: {e}") + get_logger().error( + f"Backend operation failed for invalidation on {redact_cache_key(cache_key)}: {redact_error_for_log(e)}" + ) except Exception as e: - get_logger().error(f"Unexpected error invalidating {redact_cache_key(cache_key)}: {e}") + get_logger().error(f"Unexpected error invalidating {redact_cache_key(cache_key)}: {redact_error_for_log(e)}") @runtime_checkable @@ -1949,7 +1965,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 {redact_cache_key(key)}: {e}") + get_logger().debug(f"Failed to refresh TTL for {redact_cache_key(key)}: {redact_error_for_log(e)}") def get(self, key: str, refresh_ttl: Optional[int] = None) -> Optional[bytes]: """Get value from cache using backend. @@ -1970,10 +1986,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 {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error getting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return None except Exception as e: - get_logger().error(f"Unexpected error getting key {redact_cache_key(key)}: {e}") + get_logger().error(f"Unexpected error getting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return None def get_buffer(self, key: str) -> Optional[BufferHandle]: @@ -1987,10 +2003,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 {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error mmapping key {redact_cache_key(key)}: {redact_error_for_log(e)}") return None except Exception as e: - get_logger().error(f"Unexpected error mmapping key {redact_cache_key(key)}: {e}") + get_logger().error(f"Unexpected error mmapping key {redact_cache_key(key)}: {redact_error_for_log(e)}") return None def get_with_freshness(self, key: str) -> Optional[tuple[bytes, bool, Optional[int]]]: @@ -2007,10 +2023,10 @@ def get_with_freshness(self, key: str) -> Optional[tuple[bytes, bool, Optional[i try: return _normalize_freshness_hit(self._with_backpressure_and_timeout(self.backend.get_with_freshness, key)) except BackendError as e: - get_logger().error(f"Backend error getting key {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error getting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return None except Exception as e: - get_logger().error(f"Unexpected error getting key {redact_cache_key(key)}: {e}") + get_logger().error(f"Unexpected error getting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return None async def get_with_freshness_async(self, key: str) -> Optional[tuple[bytes, bool, Optional[int]]]: @@ -2023,10 +2039,10 @@ async def get_with_freshness_async(self, key: str) -> Optional[tuple[bytes, bool await self._with_backpressure_and_timeout_async(self.backend.get_with_freshness, key) ) except BackendError as e: - get_logger().error(f"Backend error getting key {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error getting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return None except Exception as e: - get_logger().error(f"Unexpected error getting key {redact_cache_key(key)}: {e}") + get_logger().error(f"Unexpected error getting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return None def set( @@ -2056,10 +2072,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 {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error setting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False except Exception as e: - get_logger().error(f"Unexpected error setting key {redact_cache_key(key)}: {e}") + get_logger().error(f"Unexpected error setting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False def set_streaming(self, key: str, write_payload: Callable[[BinaryIO], None], ttl: Optional[int] = None) -> Optional[bool]: @@ -2078,12 +2094,12 @@ def set_streaming(self, key: str, write_payload: Callable[[BinaryIO], None], ttl self._with_backpressure_and_timeout(self.backend.set_streaming, key, write_payload, ttl) return True except BackendError as e: - get_logger().error(f"Backend error streaming key {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error streaming key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False except Exception as e: # Producer-side failure (serialization error, max_value_size budget): the backend # already discarded its partial write; surface the real cause, not a backend error. - get_logger().error(f"Streaming serialization failed for key {redact_cache_key(key)}: {e}") + get_logger().error(f"Streaming serialization failed for key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False async def set_streaming_async( @@ -2097,10 +2113,10 @@ async def set_streaming_async( await self._with_backpressure_and_timeout_async(self.backend.set_streaming, key, write_payload, ttl) return True except BackendError as e: - get_logger().error(f"Backend error streaming key {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error streaming key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False except Exception as e: - get_logger().error(f"Streaming serialization failed for key {redact_cache_key(key)}: {e}") + get_logger().error(f"Streaming serialization failed for key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False def delete(self, key: str) -> bool: @@ -2115,10 +2131,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 {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error deleting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False except Exception as e: - get_logger().error(f"Unexpected error deleting key {redact_cache_key(key)}: {e}") + get_logger().error(f"Unexpected error deleting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False async def _with_backpressure_and_timeout_async(self, operation, *args, **kwargs): @@ -2152,10 +2168,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 {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error getting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return None except Exception as e: - get_logger().error(f"Unexpected error getting key {redact_cache_key(key)}: {e}") + get_logger().error(f"Unexpected error getting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return None async def set_async( @@ -2179,10 +2195,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 {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error setting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False except Exception as e: - get_logger().error(f"Unexpected error setting key {redact_cache_key(key)}: {e}") + get_logger().error(f"Unexpected error setting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False async def delete_async(self, key: str) -> bool: @@ -2194,8 +2210,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 {redact_cache_key(key)}: {e}") + get_logger().error(f"Backend error deleting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False except Exception as e: - get_logger().error(f"Unexpected error deleting key {redact_cache_key(key)}: {e}") + get_logger().error(f"Unexpected error deleting key {redact_cache_key(key)}: {redact_error_for_log(e)}") return False diff --git a/src/cachekit/decorators/wrapper.py b/src/cachekit/decorators/wrapper.py index 1d1130e4..9bf2c8d1 100644 --- a/src/cachekit/decorators/wrapper.py +++ b/src/cachekit/decorators/wrapper.py @@ -12,6 +12,8 @@ from collections.abc import Callable from typing import TYPE_CHECKING, Any, NamedTuple, TypeVar, Union +from cachekit.hash_utils import redact_error_for_log + from ..backends.errors import BackendError, BackendErrorType from ..cache_handler import ( CacheInvalidator, @@ -73,7 +75,7 @@ def _ttl_refresh_done_callback(task: asyncio.Task, cache_key: str) -> None: try: exc = task.exception() if exc is not None: - _logger.debug("Background TTL refresh failed for %s: %s", redact_cache_key(cache_key), exc) + _logger.debug("Background TTL refresh failed for %s: %s", redact_cache_key(cache_key), redact_error_for_log(exc)) except asyncio.CancelledError: # Task was cancelled (e.g., during shutdown) - this is expected, don't log pass @@ -844,7 +846,7 @@ async def _l2_swr_revalidate_async(cache_key: str, call_args: tuple[Any, ...], c else: await _l2_swr_recompute_store_async(cache_key, call_args, call_kwargs) except Exception as exc: # noqa: BLE001 — spec: revalidation failure must never surface to callers - _logger.debug("SWR revalidation failed for %s: %s", redact_cache_key(cache_key), exc) + _logger.debug("SWR revalidation failed for %s: %s", redact_cache_key(cache_key), redact_error_for_log(exc)) finally: _l2_swr_end(cache_key) @@ -866,7 +868,7 @@ def _l2_swr_revalidate_sync(cache_key: str, call_args: tuple[Any, ...], call_kwa ) _put_l1(cache_key, serialized_data) except Exception as exc: # noqa: BLE001 — spec: revalidation failure must never surface to callers - _logger.debug("SWR revalidation failed for %s: %s", redact_cache_key(cache_key), exc) + _logger.debug("SWR revalidation failed for %s: %s", redact_cache_key(cache_key), redact_error_for_log(exc)) finally: _l2_swr_end(cache_key) @@ -887,7 +889,11 @@ def _l2_swr_schedule(cache_key: str, call_args: tuple[Any, ...], call_kwargs: di call_args, call_kwargs = copy.deepcopy((call_args, call_kwargs)) except Exception as exc: _l2_swr_end(cache_key) - _logger.debug("SWR revalidation skipped for %s: arguments not deep-copyable: %s", redact_cache_key(cache_key), exc) + _logger.debug( + "SWR revalidation skipped for %s: arguments not deep-copyable: %s", + redact_cache_key(cache_key), + redact_error_for_log(exc), + ) return try: if is_async: @@ -909,7 +915,9 @@ def _l2_swr_schedule(cache_key: str, call_args: tuple[Any, ...], call_kwargs: di ).start() except Exception as exc: # e.g. Thread.start() RuntimeError under resource pressure _l2_swr_end(cache_key) - _logger.debug("SWR revalidation could not be scheduled for %s: %s", redact_cache_key(cache_key), exc) + _logger.debug( + "SWR revalidation could not be scheduled for %s: %s", redact_cache_key(cache_key), redact_error_for_log(exc) + ) # Create per-function statistics tracker with lazy session ID generation # Session ID format: "{process_uuid}:{module}.{function_name}" @@ -984,7 +992,9 @@ def _l1_swr_acquire( _l1_swr_slots.release() _object_cache.cancel_refresh(cache_key, version) _logger.debug( - "L1-only SWR refresh skipped for %s: arguments not deep-copyable: %s", redact_cache_key(cache_key), exc + "L1-only SWR refresh skipped for %s: arguments not deep-copyable: %s", + redact_cache_key(cache_key), + redact_error_for_log(exc), ) return None @@ -1021,7 +1031,9 @@ def _l1_swr_refresh_sync(cache_key: str, version: int, call_args: tuple[Any, ... result = func(*call_args, **call_kwargs) except Exception as exc: _object_cache.cancel_refresh(cache_key, version) # let a later call retry - _logger.debug("L1-only SWR background refresh failed for %s: %s", redact_cache_key(cache_key), exc) + _logger.debug( + "L1-only SWR background refresh failed for %s: %s", redact_cache_key(cache_key), redact_error_for_log(exc) + ) return _object_cache.complete_refresh(cache_key, version, result, ttl=ttl) finally: @@ -1292,7 +1304,9 @@ 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 {redact_cache_key(cache_key)}: {e}") + logger().warning( + f"L1 cache deserialization failed for {redact_cache_key(cache_key)}: {redact_error_for_log(e)}" + ) _l1_cache.invalidate(cache_key) # Continue with the rest of the sync wrapper logic... @@ -1648,7 +1662,9 @@ 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 {redact_cache_key(cache_key)}: {e}") + logger().warning( + f"L1 cache deserialization failed for {redact_cache_key(cache_key)}: {redact_error_for_log(e)}" + ) _l1_cache.invalidate(cache_key) # Initialize backend only when needed (lazy init for performance) @@ -1731,7 +1747,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", redact_cache_key(cache_key), e) + _logger.debug("TTL refresh failed for %s: %s", redact_cache_key(cache_key), redact_error_for_log(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. @@ -1806,7 +1822,11 @@ async def async_wrapper(*args: Any, **kwargs: Any) -> Any: raise except Exception as e: # If double-check fails, continue to execute function - _logger.debug("Double-check cache failed after lock acquisition: %s", e) + _logger.debug( + "Double-check cache failed after lock acquisition for %s: %s", + redact_cache_key(cache_key), + redact_error_for_log(e), + ) else: # Lock timeout - double-check cache before giving up # Another request may have populated it while we waited @@ -1907,7 +1927,9 @@ 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 {redact_cache_key(cache_key)}, executing without lock: {e}") + logger().warning( + f"Lock operation failed for {redact_cache_key(cache_key)}, executing without lock: {redact_error_for_log(e)}" + ) # Fall through to execute without locking # Execute without locking (either backend doesn't support it or lock failed) @@ -1989,7 +2011,7 @@ def invalidate_cache(*args: Any, **kwargs: Any) -> None: _backend = get_backend_provider().get_backend() except Exception as e: # If backend creation fails, can't invalidate L2 - _logger.debug("Failed to get backend for invalidation: %s", e) + _logger.debug("Failed to get backend for invalidation: %s", redact_error_for_log(e)) # Fix #59: When called with no args on a parameterized function, # invalidate ALL cached entries for this function. @@ -2007,7 +2029,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", redact_cache_key(key), e) + _logger.debug("Failed to delete L2 key %s: %s", redact_cache_key(key), redact_error_for_log(e)) continue # keep key tracked for retry _cached_keys.discard(key) return @@ -2034,7 +2056,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", redact_cache_key(cache_key), e) + _logger.error("Failed to delete L2 interop key %s: %s", redact_cache_key(cache_key), redact_error_for_log(e)) else: invalidator.invalidate_cache(func, args, kwargs, namespace) @@ -2049,7 +2071,7 @@ async def ainvalidate_cache(*args: Any, **kwargs: Any) -> None: _backend = get_backend_provider().get_backend() except Exception as e: # If backend creation fails, can't invalidate L2 - _logger.debug("Failed to get backend for async invalidation: %s", e) + _logger.debug("Failed to get backend for async invalidation: %s", redact_error_for_log(e)) # Fix #59: When called with no args on a parameterized function, # invalidate ALL cached entries for this function. @@ -2065,7 +2087,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", redact_cache_key(key), e) + _logger.debug("Failed to delete L2 key %s: %s", redact_cache_key(key), redact_error_for_log(e)) continue _cached_keys.discard(key) return @@ -2093,7 +2115,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", redact_cache_key(cache_key), e) + _logger.error("Failed to delete L2 interop key %s: %s", redact_cache_key(cache_key), redact_error_for_log(e)) else: await invalidator.invalidate_cache_async(func, args, kwargs, namespace) diff --git a/src/cachekit/hiredis_compat.py b/src/cachekit/hiredis_compat.py index 8a3ada3c..47c1bd46 100644 --- a/src/cachekit/hiredis_compat.py +++ b/src/cachekit/hiredis_compat.py @@ -7,6 +7,8 @@ import logging import sys +from cachekit.hash_utils import redact_error_for_log + logger = logging.getLogger(__name__) @@ -22,7 +24,7 @@ def _get_disable_hiredis_setting() -> bool: redis_config = RedisBackendConfig.from_env() return redis_config.disable_hiredis except Exception as e: - logger.debug(f"Could not load Redis config for hiredis setting: {e}") + logger.debug(f"Could not load Redis config for hiredis setting: {redact_error_for_log(e)}") return False @@ -63,7 +65,7 @@ def configure_hiredis_for_free_threading(): ) return _disable_hiredis() except Exception as e: - logger.debug(f"Could not determine GIL status: {e}") + logger.debug(f"Could not determine GIL status: {redact_error_for_log(e)}") # If we can't determine GIL status, continue with default behavior return False @@ -85,7 +87,7 @@ def _disable_hiredis(): return True except Exception as e: - logger.warning(f"Failed to disable hiredis: {e}. GIL warnings may appear.") + logger.warning(f"Failed to disable hiredis: {redact_error_for_log(e)}. GIL warnings may appear.") return False diff --git a/src/cachekit/l1_cache.py b/src/cachekit/l1_cache.py index aca70562..0e6eec36 100644 --- a/src/cachekit/l1_cache.py +++ b/src/cachekit/l1_cache.py @@ -12,7 +12,7 @@ from dataclasses import dataclass from typing import Any, Optional -from cachekit.hash_utils import redact_key_for_log +from cachekit.hash_utils import redact_error_for_log, redact_key_for_log # Default L1 entry lifetime when the caller supplies no TTL. Shared with the # decorator's LAB-557 backfill bound: the server's Fresh-For may only ever @@ -424,7 +424,7 @@ def cleanup_worker(): logger.debug("Background cleanup removed %d expired entries", total_cleaned) except Exception as e: - logger.error("Error in background cleanup: %s", e) + logger.error("Error in background cleanup: %s", redact_error_for_log(e)) logger.info("L1 cache background cleanup stopped") diff --git a/src/cachekit/logging.py b/src/cachekit/logging.py index 75b4d386..ad4ea278 100644 --- a/src/cachekit/logging.py +++ b/src/cachekit/logging.py @@ -133,7 +133,7 @@ def run(self): self._write_batch(entries) except Exception as e: - logger.error(f"Error in async log writer: {e}") + logger.error(f"Error in async log writer: {redact_error_for_log(e)}") def stop(self): """Stop the writer thread.""" diff --git a/src/cachekit/reliability/async_metrics.py b/src/cachekit/reliability/async_metrics.py index af8ee48c..05f38ecf 100644 --- a/src/cachekit/reliability/async_metrics.py +++ b/src/cachekit/reliability/async_metrics.py @@ -11,6 +11,8 @@ from collections import defaultdict from typing import Any, Optional, Union +from cachekit.hash_utils import redact_error_for_log + logger = logging.getLogger(__name__) try: @@ -247,7 +249,7 @@ def _worker_loop(self): last_flush = time.time() except Exception as e: - logger.error(f"Error in metrics worker: {e}") + logger.error(f"Error in metrics worker: {redact_error_for_log(e)}") # Force flush if too much time has passed if batch and (time.time() - last_flush) > self.flush_interval: @@ -296,7 +298,7 @@ def _flush_batch(self, batch: list[dict[str, Any]]): histograms[name].append((metric["value"], labels_key)) except Exception as e: - logger.error(f"Error processing metric: {e}") + logger.error(f"Error processing metric: {redact_error_for_log(e)}") finally: # Return metric data to pool for reuse self._return_to_pool(metric) diff --git a/src/cachekit/reliability/metrics_collection.py b/src/cachekit/reliability/metrics_collection.py index 3b75c57c..928441c7 100644 --- a/src/cachekit/reliability/metrics_collection.py +++ b/src/cachekit/reliability/metrics_collection.py @@ -10,6 +10,8 @@ from collections import defaultdict from typing import Any, ClassVar, Optional +from cachekit.hash_utils import redact_error_for_log + logger = logging.getLogger(__name__) # Thread-safe metrics storage @@ -188,7 +190,7 @@ def _worker_loop(self): continue except Exception as e: # Log error but keep worker running - logger.error(f"Error processing metric in worker thread: {e}") + logger.error(f"Error processing metric in worker thread: {redact_error_for_log(e)}") def _process_metric(self, metric_data: dict): """Process a single metric.""" @@ -211,7 +213,7 @@ def _process_metric(self, metric_data: dict): self._metrics[name][key] = value except Exception as e: - logger.debug(f"Failed to process metric {metric_data.get('name', 'unknown')}: {e}") + logger.debug(f"Failed to process metric {metric_data.get('name', 'unknown')}: {redact_error_for_log(e)}") def _try_prometheus_metric(self, metric_type: str, name: str, value: float, labels: dict) -> bool: """Try to record using Prometheus metrics if available.""" @@ -232,7 +234,7 @@ def _try_prometheus_metric(self, metric_type: str, name: str, value: float, labe return False except (ImportError, AttributeError, Exception) as e: - logger.debug(f"Prometheus metric not available for {name}: {e}") + logger.debug(f"Prometheus metric not available for {name}: {redact_error_for_log(e)}") return False @@ -369,7 +371,7 @@ def get_or_create_metric(cls, metric_class, name: str, description: str = "", la cls._registry[name] = metric except Exception as e: # If Prometheus metric creation fails, return a compatible mock - logger.warning(f"Failed to create Prometheus metric {name}: {e}") + logger.warning(f"Failed to create Prometheus metric {name}: {redact_error_for_log(e)}") cls._registry[name] = MetricsCollector(name) return cls._registry[name] diff --git a/src/cachekit/serializers/__init__.py b/src/cachekit/serializers/__init__.py index d4a80f1c..34bf769b 100644 --- a/src/cachekit/serializers/__init__.py +++ b/src/cachekit/serializers/__init__.py @@ -5,6 +5,7 @@ from typing import TYPE_CHECKING, Any from cachekit._rust_serializer import ByteStorage +from cachekit.hash_utils import redact_error_for_log from .auto_serializer import AutoSerializer from .base import ( @@ -179,7 +180,7 @@ def benchmark_serializers() -> dict[str, Any]: try: serializers[name] = get_serializer(name) except Exception as e: - logger.warning(f"Failed to instantiate {name} serializer: {e}") + logger.warning(f"Failed to instantiate {name} serializer: {redact_error_for_log(e)}") return serializers diff --git a/src/cachekit/serializers/auto_serializer.py b/src/cachekit/serializers/auto_serializer.py index 1dcd25ce..65faa41a 100644 --- a/src/cachekit/serializers/auto_serializer.py +++ b/src/cachekit/serializers/auto_serializer.py @@ -59,6 +59,7 @@ ArrowSerializer = None # type: ignore[assignment,misc] from cachekit._rust_serializer import ByteStorage +from cachekit.hash_utils import redact_error_for_log from .base import SerializationError, SerializationFormat, SerializationMetadata @@ -598,7 +599,9 @@ def deserialize(self, data: bytes | memoryview, metadata: Optional[Serialization raise except Exception as e: # If Rust envelope parsing fails for other reasons, try Python-only deserialization - logger.debug(f"Rust envelope parsing failed, falling back to Python-only deserialization: {e}") + logger.debug( + f"Rust envelope parsing failed, falling back to Python-only deserialization: {redact_error_for_log(e)}" + ) # Check for Arrow IPC format before msgpack fall-through # Arrow data may have xxHash3-64 checksum prefix (8 bytes) or be direct Arrow IPC diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index 31a3ec6d..87bdba53 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/tests/unit/test_error_path_key_redaction.py @@ -24,6 +24,19 @@ TENANT_KEY = "ns:tenant-42-alice-secret:func:app.get_user:args:deadbeef:v1" +# Every sink is driven with four exception shapes. The first two prove the KEY field is +# redacted; the last two prove the EXCEPTION TEXT is too — a BackendError whose free-form +# ``message`` embeds the key (``_format_message`` preserves it verbatim) and a provider +# exception that echoes it (redis ResponseError style). A sink that interpolates ``{e}`` +# raw passes the first two and fails the last two. +ERRORS = [ + BackendError("backend down", error_type=BackendErrorType.TRANSIENT), + ValueError("unexpected"), + BackendError(f"WRONGTYPE for {TENANT_KEY}", error_type=BackendErrorType.TRANSIENT, operation="get"), + ValueError(f"illegal input: {TENANT_KEY}"), +] +ERROR_IDS = ["backend_error", "unexpected_error", "backenderror_key_in_message", "provider_key_in_text"] + class _FailingBackend: """Minimal BaseBackend whose mutating operations raise a configured error.""" @@ -68,16 +81,13 @@ def _assert_redacted(caplog: pytest.LogCaptureFixture, raw_key: str) -> None: 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}" + assert not any(TENANT_KEY in m for m in messages), f"key-bearing exception text 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"], - ) + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) def test_set_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: handler = StandardCacheHandler(backend=_FailingBackend(error)) @@ -86,11 +96,7 @@ def test_set_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptu _assert_redacted(caplog, TENANT_KEY) - @pytest.mark.parametrize( - "error", - [BackendError("backend down", error_type=BackendErrorType.TRANSIENT), ValueError("unexpected")], - ids=["backend_error", "unexpected_error"], - ) + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) def test_delete_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: handler = StandardCacheHandler(backend=_FailingBackend(error)) @@ -99,9 +105,10 @@ def test_delete_failure_redacts_key(self, error: Exception, caplog: pytest.LogCa _assert_redacted(caplog, TENANT_KEY) - async def test_ttl_refresh_failure_redacts_key(self, caplog: pytest.LogCaptureFixture) -> None: + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) + async def test_ttl_refresh_failure_redacts_key(self, error: Exception, 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"))) + handler = StandardCacheHandler(backend=_FailingTTLBackend(error)) with caplog.at_level(logging.DEBUG): await handler._maybe_refresh_ttl(TENANT_KEY, refresh_ttl=300) @@ -116,11 +123,7 @@ def _invalidator(self, error: Exception) -> tuple[CacheInvalidator, _FailingBack 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"], - ) + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) def test_sync_invalidation_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: invalidator, backend = self._invalidator(error) @@ -133,11 +136,7 @@ def cached_func(user: str) -> str: 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"], - ) + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) async def test_async_invalidation_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: invalidator, backend = self._invalidator(error) diff --git a/tests/unit/test_l2_decrypt_observability.py b/tests/unit/test_l2_decrypt_observability.py index 4334e58e..6a43cafc 100644 --- a/tests/unit/test_l2_decrypt_observability.py +++ b/tests/unit/test_l2_decrypt_observability.py @@ -64,7 +64,10 @@ def test_encryption_error_logs_warning(self, caplog: pytest.LogCaptureFixture) - assert result is None assert any("decrypt/integrity failure" in r.message for r in caplog.records) - assert any("GCM tag mismatch" in r.message for r in caplog.records) + # The exception is rendered by redact_error_for_log (CWE-532, LAB-304): the log + # names the type, never the provider's free-form message text. + assert any("EncryptionError" in r.message for r in caplog.records) + assert not any("GCM tag mismatch" in r.message for r in caplog.records) def test_generic_exception_does_not_trigger_decrypt_warning(self, caplog: pytest.LogCaptureFixture) -> None: """Non-SerializationError (e.g. ConnectionError) uses the generic warning.""" diff --git a/tests/unit/test_log_redaction_architecture.py b/tests/unit/test_log_redaction_architecture.py index 56b27807..e63d6e0b 100644 --- a/tests/unit/test_log_redaction_architecture.py +++ b/tests/unit/test_log_redaction_architecture.py @@ -1,4 +1,4 @@ -"""Architecture test: no stdlib logger call may receive a raw cache key (CWE-532, LAB-304). +"""Architecture test: no logging call may receive a raw cache key or raw exception text (CWE-532, LAB-304). The redaction sweep on PR #264 hand-edited ~30 log lines. Nothing stopped the next ``logger.debug(f"... {key}")`` from landing with CI green — this does. @@ -6,24 +6,37 @@ For every logging call under ``src/cachekit`` — receiver a logger name (``logger``, ``_logger``, ``self._logger``, ``logger_instance``, ``logging``, ``warnings``), a logger factory call (``get_logger()``, ``logger()``, -``logging.getLogger(...)``), or ``getattr(logger, level)(...)`` — any Name, -Attribute, or ``d["..."]`` subscript whose identifier is key-shaped (``key``, -``cache_key``, ``lock_key``, ``e.key``, ``kwargs["key"]`` ...) must be wrapped -in ``redact_cache_key`` / ``redact_key_for_log`` somewhere between it and the -call: in the message f-string, in ``%s`` arguments, or in ``extra=``. - -Known blind spot (flow-insensitive): a message pre-built into a variable -(``msg = f"miss {key}"; logger.debug(msg)``) is not traced. Build log lines -inline so the guard can see them. Sink-central redaction is not exempted: the -sinks' own stdlib calls satisfy the rule; callers passing raw keys *into* -``handle_cache_error`` / ``log_cache_operation`` / ``SimpleLogger.cache_*`` are -covered by those sinks' contract tests, not here. +``logging.getLogger(...)``), or ``getattr(logger, level)(...)``: + +* **Keys.** Any Name, Attribute, or ``d["..."]`` subscript whose identifier is + key-shaped (``key``, ``cache_key``, ``lock_key``, ``e.key``, ``kwargs["key"]``) + must be wrapped in ``redact_cache_key`` / ``redact_key_for_log`` somewhere + between it and the call: in the message f-string, ``%s`` arguments, or ``extra=``. +* **Exceptions.** An exception's ``str()`` has unknown provenance (a redis + ResponseError naming the key, a ``BackendError`` whose free-form message was + built with it). Any exception-shaped identifier — every name bound by an + ``except ... as `` in the same file, plus the conventional names + ``e``/``ex``/``exc``/``err``/``error``/``exception`` and any ``*_err``-style + suffix, for parameters such as ``error: Exception`` — or an attribute of one, + must be wrapped in ``redact_error_for_log``. ``type(e).__name__`` is allowed. +* **Tracebacks.** ``logger.exception(...)`` and ``exc_info=`` are flagged + outright: the traceback carries the raw exception text whatever the message says. + +Known blind spots (flow-insensitive): a message pre-built into a variable +(``msg = f"miss {key}"; logger.debug(msg)``) is not traced, and an exception +held in a parameter with an unconventional name (``failure: Exception``) is not +recognised. Build log lines inline, and bind exceptions with ``except ... as`` +or a conventional name, so the guard can see them. Sink-central redaction is not +exempted: the sinks' own stdlib calls satisfy the rule; callers passing raw keys +*into* ``handle_cache_error`` / ``log_cache_operation`` / ``SimpleLogger.cache_*`` +are covered by those sinks' contract tests, not here. """ from __future__ import annotations import ast import re +from collections.abc import Callable from pathlib import Path SRC = Path(__file__).resolve().parents[2] / "src" / "cachekit" @@ -34,8 +47,10 @@ # that merely contain "log" (catalog, dialog, backlog) are not treated as loggers. LOGGER_NAME_RE = re.compile(r"(?:^|_)log(?:ger|ging)?(?:_|$)|^warnings$") LOGGER_FACTORIES = frozenset({"get_logger", "logger", "getLogger", "get_structured_logger"}) -REDACTORS = frozenset({"redact_cache_key", "redact_key_for_log"}) +KEY_REDACTORS = frozenset({"redact_cache_key", "redact_key_for_log"}) +ERROR_REDACTORS = frozenset({"redact_error_for_log", "type"}) # type(e).__name__ is key-free KEY_NAME_RE = re.compile(r"(?:^|_)key$") +EXC_NAME_RE = re.compile(r"(?:^|_)(?:e|ex|exc|err|error|exception)$") def _call_name(node: ast.Call) -> str: @@ -79,50 +94,88 @@ def _key_identifier(node: ast.AST) -> str | None: return None -def _raw_keys(node: ast.AST) -> list[str]: - """Key-shaped identifiers under ``node`` not enclosed by a redactor call.""" - ident = _key_identifier(node) - if ident is not None: - return [ident] +def _exception_identifier(bound: frozenset[str]) -> Callable[[ast.AST], str | None]: + """Predicate for exception-shaped roots: names bound by ``except ... as`` in this file, or conventional names.""" + + def ident(node: ast.AST) -> str | None: + root = node + while isinstance(root, (ast.Attribute, ast.Subscript)): # e.message, e.args[0] + root = root.value + if isinstance(root, ast.Name) and (root.id in bound or EXC_NAME_RE.search(root.id)): + return root.id + return None + + return ident + + +def _unredacted(node: ast.AST, ident: Callable[[ast.AST], str | None], redactors: frozenset[str]) -> list[str]: + """Identifiers matching ``ident`` under ``node`` that are not enclosed by a call to one of ``redactors``.""" + found_here = ident(node) + if found_here is not None: + return [found_here] found: list[str] = [] if isinstance(node, ast.Call): # The callee's own name is never a key (``redact_cache_key`` ends in ``_key``); # only its receiver chain (``obj.key.method()``) can carry one. if isinstance(node.func, ast.Attribute): - found.extend(_raw_keys(node.func.value)) - if _call_name(node) not in REDACTORS: + found.extend(_unredacted(node.func.value, ident, redactors)) + if _call_name(node) not in redactors: for child in _call_args(node): - found.extend(_raw_keys(child)) + found.extend(_unredacted(child, ident, redactors)) return found if isinstance(node, ast.IfExp): # ``redact(key) if key else "unknown"`` — the test is a truthiness check, it never renders. - return _raw_keys(node.body) + _raw_keys(node.orelse) + return _unredacted(node.body, ident, redactors) + _unredacted(node.orelse, ident, redactors) for child in ast.iter_child_nodes(node): - found.extend(_raw_keys(child)) + found.extend(_unredacted(child, ident, redactors)) return found +def _emits_traceback(node: ast.Call) -> bool: + if isinstance(node.func, ast.Attribute) and node.func.attr == "exception": + return True + return any(kw.arg == "exc_info" for kw in node.keywords) + + +def _except_names(tree: ast.AST) -> frozenset[str]: + return frozenset(h.name for h in ast.walk(tree) if isinstance(h, ast.ExceptHandler) and h.name) + + +def _violations_in(tree: ast.AST, where: str) -> list[str]: + out: list[str] = [] + exc_ident = _exception_identifier(_except_names(tree)) + for node in ast.walk(tree): + if not isinstance(node, ast.Call) or not _is_logger_call(node): + continue + loc = f"{where}:{node.lineno}" + keys = [k for arg in _call_args(node) for k in _unredacted(arg, _key_identifier, KEY_REDACTORS)] + if keys: + out.append(f"{loc} logs raw {', '.join(sorted(set(keys)))}") + excs = [k for arg in _call_args(node) for k in _unredacted(arg, exc_ident, ERROR_REDACTORS)] + if excs: + out.append(f"{loc} logs raw exception text {', '.join(sorted(set(excs)))} (wrap in redact_error_for_log)") + if _emits_traceback(node): + out.append(f"{loc} emits a traceback (logger.exception / exc_info) — raw exception text") + return out + + def _violations(root: Path) -> list[str]: out: list[str] = [] for path in sorted(root.rglob("*.py")): tree = ast.parse(path.read_text(encoding="utf-8"), filename=str(path)) - for node in ast.walk(tree): - if not isinstance(node, ast.Call) or not _is_logger_call(node): - continue - leaks = [k for arg in _call_args(node) for k in _raw_keys(arg)] - if leaks: - out.append(f"{path.relative_to(root.parents[1])}:{node.lineno} logs raw {', '.join(sorted(set(leaks)))}") + out.extend(_violations_in(tree, str(path.relative_to(root.parents[1])))) return out -def test_no_raw_cache_key_reaches_a_logger_call() -> None: +def test_no_raw_key_or_exception_text_reaches_a_logger_call() -> None: violations = _violations(SRC) - assert not violations, "Raw cache keys reach a logger call (wrap in redact_key_for_log):\n " + "\n ".join(violations) + assert not violations, "Raw cache keys or exception text reach a logger call:\n " + "\n ".join(violations) def test_detector_catches_the_shapes_it_claims_to() -> None: """The guard is only as good as its detector — pin the shapes it must flag and must allow.""" cases = [ + # keys ("logger.debug(f'hit {key}')", True), # f-string ("logger.debug('miss %s', cache_key)", True), # %-args ("self._logger.warning('x', extra={'k': e.key})", True), # attribute in extra= @@ -139,9 +192,24 @@ def test_detector_catches_the_shapes_it_claims_to() -> None: ("logger.debug('%d keys', len(expired_keys))", False), # plural: not a key ("get_logger().warning(f\"{redact_cache_key(cache_key) if cache_key else 'unknown'}\")", False), # truthiness test ("client.get(key)", False), # not a logger + # exception text + ("logger.warning(f'set failed for {redact_cache_key(cache_key)}: {e}')", True), # f-string {e} + ("_logger.debug('TTL refresh failed for %s: %s', redact_cache_key(cache_key), exc)", True), # %-arg exc + ("logger.error(f'decrypt failed: {error!s}')", True), # !s conversion + ("logger.error(f'failed: {e.message}')", True), # attribute of an exception + ("logger.warning(f'evict failed: {del_err}')", True), # *_err suffix + ("logger.debug('x: %s', import_err)", True), # *_err suffix, %-arg + ( + "try:\n pass\nexcept ValueError as failure:\n logger.error(f'{failure}')", + True, + ), # except-bound, unconventional name + ("logger.error('failed', exc_info=True)", True), # traceback + ("logger.exception('failed')", True), # traceback + ("logger.warning(f'failed: {redact_error_for_log(e)}')", False), # redacted + ("logger.warning('failed: %s', redact_error_for_log(exc))", False), # redacted %-arg + ("logger.warning(f'failed: {type(e).__name__}')", False), # type name is key-free + ("def f(failure):\n logger.error(f'{failure}')", False), # unconventional parameter: documented blind spot ] for src, expected in cases: - tree = ast.parse(src) - calls = [n for n in ast.walk(tree) if isinstance(n, ast.Call) and _is_logger_call(n)] - flagged = any(_raw_keys(a) for c in calls for a in _call_args(c)) + flagged = bool(_violations_in(ast.parse(src), "")) assert flagged is expected, f"{src!r}: expected flagged={expected}, got {flagged}" From acbc605742d0c4c74d535bbc81ff866b973d64d9 Mon Sep 17 00:00:00 2001 From: Mark S Date: Sat, 12 Sep 2026 16:22:53 +1000 Subject: [PATCH 14/17] fix(logging): guard directly-imported logging functions; cover the async L2 read sinks (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CodeRabbit on 6d4d421: the architecture test ignored an ast.Name callee, so `from logging import warning; warning('%s', cache_key)` bypassed it. The guard now tracks names imported from logging/warnings (aliases mapped back to their originals, so an aliased `exception` still counts as a traceback emitter) and module aliases (`import logging as lg`), with seven pinned detector cases. SECURITY.md now says explicitly that BackendError.key stays raw for programmatic use — only the formatted text carries the digest. codecov/patch on 6d4d421 read 75% of the diff: the sweep touched exception branches that were already uncovered. The two that are cache-key sinks — CacheOperationHandler.get_cached_value_async and get_cached_value_with_freshness_async — now run the full key-bearing error matrix. The remaining uncovered changed lines are infrastructure failure branches (hiredis shim, Prometheus registry, log-writer thread, L1 cleanup thread) and provider-internal paths; left as they were. Kody's fifth 'no assert in tests' thread rejected on the PR with the same reason as the first four. --- SECURITY.md | 2 +- tests/unit/test_error_path_key_redaction.py | 27 +++++++++- tests/unit/test_log_redaction_architecture.py | 51 ++++++++++++++++--- 3 files changed, 71 insertions(+), 9 deletions(-) diff --git a/SECURITY.md b/SECURITY.md index 35ae30d2..22dd6aee 100644 --- a/SECURITY.md +++ b/SECURITY.md @@ -189,7 +189,7 @@ See [SSRF Protection](docs/features/ssrf-protection.md) for full details, includ ### Cache Key Redaction in Logs (CWE-532) -Cache keys can embed caller-supplied tenant/user identifiers, so **the SDK's own loggers** (`cachekit.*`) never emit them verbatim ([CWE-532][cwe-532]). Every cachekit log path — decorator error handling (structured and backwards-compat), cache-operation logs, and SWR/TTL-refresh debug logs — replaces the key with a fixed-length blake2b digest (``), keeping log lines correlatable without leaking the key. Error paths are covered centrally at the shared error sink (`FeatureOrchestrator.handle_cache_error` / `log_cache_operation`), so new call sites are redacted by construction. `BackendError` redacts its `key` at construction, but its free-form `message` is caller-supplied and third-party exception text (a redis `ResponseError` naming the key, a pymemcache illegal-input error echoing it) has unknown provenance — so **no cachekit log line renders `str(e)`**. Every logging call that mentions an exception goes through `redact_error_for_log`, which emits only the exception type plus, for `BackendError`, its `BackendErrorType` classification; the full exception stays on the object (`original_exception`, `.message`) for programmatic access. Operators lose the provider's message text in the log line and keep it on the exception. An architecture test (`tests/unit/test_log_redaction_architecture.py`) walks every logging call in the package — `logger.*()`, `get_logger().*()`, `getattr(logger, level)()` — and fails CI if a key-shaped value reaches one unredacted in the message, `%s` arguments, or `extra=`; if an exception — any name bound by `except ... as`, a conventional name (`e`, `exc`, `err`, `error`, `*_err`), or an attribute of one — reaches one outside `redact_error_for_log`; or if a call emits a traceback (`logger.exception`, `exc_info=`). The guarantee does not depend on the next contributor remembering it. It is flow-insensitive: build log lines inline, not via a pre-formatted variable, and bind exceptions with `except ... as` or a conventional name (an `Exception`-typed parameter called `failure` is invisible to it), or the guard cannot see them. +Cache keys can embed caller-supplied tenant/user identifiers, so **the SDK's own loggers** (`cachekit.*`) never emit them verbatim ([CWE-532][cwe-532]). Every cachekit log path — decorator error handling (structured and backwards-compat), cache-operation logs, and SWR/TTL-refresh debug logs — replaces the key with a fixed-length blake2b digest (``), keeping log lines correlatable without leaking the key. Error paths are covered centrally at the shared error sink (`FeatureOrchestrator.handle_cache_error` / `log_cache_operation`), so new call sites are redacted by construction. `BackendError` redacts the key in its formatted text (`str(e)` carries `key=`), while the `.key` attribute keeps the raw caller-supplied key for programmatic use — never log `e.key`. Its free-form `message` is caller-supplied and third-party exception text (a redis `ResponseError` naming the key, a pymemcache illegal-input error echoing it) has unknown provenance — so **no cachekit log line renders `str(e)`**. Every logging call that mentions an exception goes through `redact_error_for_log`, which emits only the exception type plus, for `BackendError`, its `BackendErrorType` classification; the full exception stays on the object (`original_exception`, `.message`) for programmatic access. Operators lose the provider's message text in the log line and keep it on the exception. An architecture test (`tests/unit/test_log_redaction_architecture.py`) walks every logging call in the package — `logger.*()`, `get_logger().*()`, `getattr(logger, level)()` — and fails CI if a key-shaped value reaches one unredacted in the message, `%s` arguments, or `extra=`; if an exception — any name bound by `except ... as`, a conventional name (`e`, `exc`, `err`, `error`, `*_err`), or an attribute of one — reaches one outside `redact_error_for_log`; or if a call emits a traceback (`logger.exception`, `exc_info=`). The guarantee does not depend on the next contributor remembering it. It is flow-insensitive: build log lines inline, not via a pre-formatted variable, and bind exceptions with `except ... as` or a conventional name (an `Exception`-typed parameter called `failure` is invisible to it), or the guard cannot see them. **Scope — transport logs are not covered.** The CachekitIO backend addresses entries by key in the request path (`GET /v1/cache/{key}`), and `httpx` logs every request line — method, full URL, status — at `INFO` on its own `httpx` logger. An application that enables `INFO` globally (`logging.basicConfig(level=logging.INFO)`) will therefore see raw keys in *httpx's* output on every operation, exactly as it would see any REST resource path. cachekit does not mute a third-party logger on your behalf; if your keys carry identifiers, silence or raise the level of that logger in your logging config: diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index 87bdba53..4af719e1 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/tests/unit/test_error_path_key_redaction.py @@ -12,11 +12,12 @@ import logging from typing import Any, Optional +from unittest.mock import MagicMock import pytest from cachekit.backends.errors import BackendError, BackendErrorType -from cachekit.cache_handler import CacheInvalidator, StandardCacheHandler +from cachekit.cache_handler import CacheInvalidator, CacheOperationHandler, StandardCacheHandler from cachekit.decorators.orchestrator import FeatureOrchestrator from cachekit.hash_utils import _SENTINEL_KEYS, redact_cache_key from cachekit.key_generator import CacheKeyGenerator @@ -105,6 +106,30 @@ def test_delete_failure_redacts_key(self, error: Exception, caplog: pytest.LogCa _assert_redacted(caplog, TENANT_KEY) + @staticmethod + def _operation_handler(error: Exception) -> CacheOperationHandler: + # Serialization is never reached: the L2 read raises first. The real strategy + # over the failing backend is what routes the exception into the L2 read sinks. + return CacheOperationHandler( + MagicMock(), CacheKeyGenerator(), cache_handler=StandardCacheHandler(backend=_FailingBackend(error)) + ) + + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) + async def test_async_get_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + """The async L2 read sink (CacheOperationHandler.get_cached_value_async).""" + with caplog.at_level(logging.WARNING): + assert await self._operation_handler(error).get_cached_value_async(TENANT_KEY) is None + + _assert_redacted(caplog, TENANT_KEY) + + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) + async def test_async_freshness_get_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + """The SWR freshness read sink (CacheOperationHandler.get_cached_value_with_freshness_async).""" + with caplog.at_level(logging.WARNING): + assert await self._operation_handler(error).get_cached_value_with_freshness_async(TENANT_KEY) is None + + _assert_redacted(caplog, TENANT_KEY) + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) async def test_ttl_refresh_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: """get_ttl raising must not fail the operation — and must log only the digest.""" diff --git a/tests/unit/test_log_redaction_architecture.py b/tests/unit/test_log_redaction_architecture.py index e63d6e0b..15047c0a 100644 --- a/tests/unit/test_log_redaction_architecture.py +++ b/tests/unit/test_log_redaction_architecture.py @@ -6,7 +6,9 @@ For every logging call under ``src/cachekit`` — receiver a logger name (``logger``, ``_logger``, ``self._logger``, ``logger_instance``, ``logging``, ``warnings``), a logger factory call (``get_logger()``, ``logger()``, -``logging.getLogger(...)``), or ``getattr(logger, level)(...)``: +``logging.getLogger(...)``), a function imported directly from ``logging`` / +``warnings`` (``from logging import warning``, aliases included), an aliased +module (``import logging as lg``), or ``getattr(logger, level)(...)``: * **Keys.** Any Name, Attribute, or ``d["..."]`` subscript whose identifier is key-shaped (``key``, ``cache_key``, ``lock_key``, ``e.key``, ``kwargs["key"]``) @@ -76,10 +78,34 @@ def _is_logger_receiver(node: ast.AST) -> bool: return False -def _is_logger_call(node: ast.Call) -> bool: +LOG_MODULES = frozenset({"logging", "warnings"}) + + +def _direct_log_names(tree: ast.AST) -> tuple[dict[str, str], frozenset[str]]: + """Names bound by importing from the logging modules directly. + + Returns (functions, module_aliases): ``from logging import warning as w`` binds the + function ``w`` (mapped back to ``warning``); ``import logging as lg`` binds the module + alias ``lg`` — a receiver the name regex would otherwise miss. + """ + funcs: dict[str, str] = {} + modules: set[str] = set() + for node in ast.walk(tree): + if isinstance(node, ast.ImportFrom) and node.module in LOG_MODULES: + funcs.update({a.asname or a.name: a.name for a in node.names if a.name in LOG_METHODS | {"getLogger"}}) + elif isinstance(node, ast.Import): + modules.update(a.asname or a.name for a in node.names if a.name in LOG_MODULES) + return funcs, frozenset(modules) + + +def _is_logger_call(node: ast.Call, direct: dict[str, str] | None = None, aliases: frozenset[str] = frozenset()) -> bool: func = node.func + if isinstance(func, ast.Name): # from logging import warning; warning("%s", key) + return func.id in (direct or {}) if isinstance(func, ast.Attribute): - return func.attr in LOG_METHODS and _is_logger_receiver(func.value) + receiver = func.value + aliased = isinstance(receiver, ast.Name) and receiver.id in aliases # import logging as lg; lg.warning(...) + return func.attr in LOG_METHODS and (aliased or _is_logger_receiver(receiver)) # getattr(logger, level.lower())(message, ...) return isinstance(func, ast.Call) and _call_name(func) == "getattr" and bool(func.args) and _is_logger_receiver(func.args[0]) @@ -131,8 +157,11 @@ def _unredacted(node: ast.AST, ident: Callable[[ast.AST], str | None], redactors return found -def _emits_traceback(node: ast.Call) -> bool: - if isinstance(node.func, ast.Attribute) and node.func.attr == "exception": +def _emits_traceback(node: ast.Call, direct: dict[str, str] | None = None) -> bool: + func = node.func + if isinstance(func, ast.Attribute) and func.attr == "exception": + return True + if isinstance(func, ast.Name) and (direct or {}).get(func.id) == "exception": # from logging import exception as x return True return any(kw.arg == "exc_info" for kw in node.keywords) @@ -144,8 +173,9 @@ def _except_names(tree: ast.AST) -> frozenset[str]: def _violations_in(tree: ast.AST, where: str) -> list[str]: out: list[str] = [] exc_ident = _exception_identifier(_except_names(tree)) + direct, aliases = _direct_log_names(tree) for node in ast.walk(tree): - if not isinstance(node, ast.Call) or not _is_logger_call(node): + if not isinstance(node, ast.Call) or not _is_logger_call(node, direct, aliases): continue loc = f"{where}:{node.lineno}" keys = [k for arg in _call_args(node) for k in _unredacted(arg, _key_identifier, KEY_REDACTORS)] @@ -154,7 +184,7 @@ def _violations_in(tree: ast.AST, where: str) -> list[str]: excs = [k for arg in _call_args(node) for k in _unredacted(arg, exc_ident, ERROR_REDACTORS)] if excs: out.append(f"{loc} logs raw exception text {', '.join(sorted(set(excs)))} (wrap in redact_error_for_log)") - if _emits_traceback(node): + if _emits_traceback(node, direct): out.append(f"{loc} emits a traceback (logger.exception / exc_info) — raw exception text") return out @@ -192,6 +222,13 @@ def test_detector_catches_the_shapes_it_claims_to() -> None: ("logger.debug('%d keys', len(expired_keys))", False), # plural: not a key ("get_logger().warning(f\"{redact_cache_key(cache_key) if cache_key else 'unknown'}\")", False), # truthiness test ("client.get(key)", False), # not a logger + ("from logging import warning\nwarning('%s', cache_key)", True), # directly imported function + ("from logging import error as log_err\nlog_err(f'{cache_key}')", True), # aliased direct import + ("from warnings import warn\nwarn(f'{cache_key}')", True), # warnings.warn imported directly + ("import logging as lg\nlg.warning('%s', cache_key)", True), # aliased module receiver + ("from logging import getLogger\ngetLogger(__name__).info('%s', cache_key)", True), # direct getLogger factory + ("from logging import exception\nexception('boom')", True), # directly imported traceback emitter + ("def warning(msg): pass\nwarning(f'{cache_key}')", False), # same name, not imported from logging # exception text ("logger.warning(f'set failed for {redact_cache_key(cache_key)}: {e}')", True), # f-string {e} ("_logger.debug('TTL refresh failed for %s: %s', redact_cache_key(cache_key), exc)", True), # %-arg exc From fd65fe24a2f556a489555f6b300ae53da6b26e18 Mon Sep 17 00:00:00 2001 From: Mark S Date: Sat, 12 Sep 2026 19:34:58 +1000 Subject: [PATCH 15/17] test(logging): drive the L2 read sinks and wrapper error paths for real (LAB-304) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit codecov/patch on acbc605 read 75.4% against the 80% target. The two async L2 read sinks it flagged — CacheOperationHandler.get_cached_value_async and get_cached_value_with_freshness_async — had tests that never reached them: the failing backend's exception was swallowed by StandardCacheHandler's own sink one layer down, whose digest satisfied the assertion. The handler stub now raises from the cache handler itself, so the sinks the docstrings name are the ones that log. The other cache-path sinks the PR touched get their first driver: the serializer import / serialize / interop-deserialize failures and both set_streaming_async branches in cache_handler; L1 deserialization failure (sync and async), the post-lock double-check failure, provider failure on invalidation, and interop L2 delete failure in the wrapper; and the no-key branch of the orchestrator's structured operation log. Each asserts the digest appears and neither the raw key nor the exception text does. Infrastructure failure branches (hiredis shim, Prometheus registry, log-writer and cleanup threads, provider-internal paths) stay uncovered by the earlier call on acbc605. Patch coverage lands at 104/118 lines (88%) locally. LAB-3432. --- tests/unit/test_error_path_key_redaction.py | 275 +++++++++++++++++- .../unit/test_orchestrator_error_handling.py | 7 + 2 files changed, 276 insertions(+), 6 deletions(-) diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index 4af719e1..b62ce181 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/tests/unit/test_error_path_key_redaction.py @@ -11,17 +11,27 @@ from __future__ import annotations import logging +from collections.abc import AsyncIterator +from contextlib import asynccontextmanager from typing import Any, Optional from unittest.mock import MagicMock import pytest +from cachekit import cache from cachekit.backends.errors import BackendError, BackendErrorType -from cachekit.cache_handler import CacheInvalidator, CacheOperationHandler, StandardCacheHandler +from cachekit.cache_handler import ( + CacheInvalidator, + CacheOperationHandler, + CacheSerializationHandler, + StandardCacheHandler, + _get_cached_serializer_class, +) 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 +from cachekit.serializers.base import SerializationError TENANT_KEY = "ns:tenant-42-alice-secret:func:app.get_user:args:deadbeef:v1" @@ -65,6 +75,56 @@ def health_check(self) -> tuple[bool, dict[str, Any]]: return True, {"backend_type": "failing"} +class _RaisingCacheHandler: + """CacheHandlerStrategy stand-in whose async reads raise (see _operation_handler).""" + + def __init__(self, error: Exception) -> None: + self._error = error + + async def get_async(self, key: str, refresh_ttl: Optional[int] = None) -> Optional[bytes]: + raise self._error + + async def get_with_freshness_async(self, key: str) -> Optional[tuple[bytes, bool, Optional[int]]]: + raise self._error + + +class _DictBackend: + """Transparent in-memory BaseBackend; ``delete_error`` makes delete raise.""" + + key_prefix = "" # interop compatibility contract (ensure_interop_backend_compatible) + + def __init__(self) -> None: + self.store: dict[str, bytes] = {} + self.delete_error: Optional[Exception] = None + + def get(self, key: str) -> Optional[bytes]: + return self.store.get(key) + + def set(self, key: str, value: bytes, ttl: Optional[int] = None) -> None: + self.store[key] = bytes(value) + + def delete(self, key: str) -> bool: + if self.delete_error is not None: + raise self.delete_error + return self.store.pop(key, None) is not None + + def exists(self, key: str) -> bool: + return key in self.store + + def health_check(self) -> tuple[bool, dict[str, Any]]: + return True, {"backend_type": "dict"} + + +class _LockingDictBackend(_DictBackend): + """Adds the LockableBackend protocol so the async wrapper takes the stampede-lock branch.""" + + @asynccontextmanager + async def acquire_lock( + self, key: str, timeout: float = 10.0, blocking_timeout: Optional[float] = None + ) -> AsyncIterator[bool]: + yield True + + class _FailingTTLBackend(_FailingBackend): """Adds TTL inspection so supports_ttl_inspection() passes; get_ttl raises.""" @@ -76,6 +136,14 @@ async def refresh_ttl(self, key: str, ttl: int) -> bool: raise self._error +def _assert_error_text_redacted(caplog: pytest.LogCaptureFixture, error: Exception) -> None: + """The exception renders as its type name only; its free-form text (which may echo a key) never does.""" + messages = [r.getMessage() for r in caplog.records] + assert str(error), "test bug: a blank message would match every record" + assert any(type(error).__name__ in m for m in messages), f"expected {type(error).__name__} in logs; got {messages!r}" + assert not any(str(error) in m for m in messages), f"exception text leaked into logs: {messages!r}" + + 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) @@ -108,11 +176,10 @@ def test_delete_failure_redacts_key(self, error: Exception, caplog: pytest.LogCa @staticmethod def _operation_handler(error: Exception) -> CacheOperationHandler: - # Serialization is never reached: the L2 read raises first. The real strategy - # over the failing backend is what routes the exception into the L2 read sinks. - return CacheOperationHandler( - MagicMock(), CacheKeyGenerator(), cache_handler=StandardCacheHandler(backend=_FailingBackend(error)) - ) + # StandardCacheHandler swallows backend errors at its OWN sink and returns None, so a + # failing backend never reaches the CacheOperationHandler sinks these tests pin. The + # exception has to come from the cache handler itself. + return CacheOperationHandler(MagicMock(), CacheKeyGenerator(), cache_handler=_RaisingCacheHandler(error)) # type: ignore[arg-type] @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) async def test_async_get_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: @@ -362,3 +429,199 @@ def test_memcached_classifier_does_not_leak_key(self) -> None: err = classify_memcached_error(exc, operation="get", key=TENANT_KEY) assert TENANT_KEY not in str(err) assert redact_cache_key(TENANT_KEY) in str(err) + + +class TestSerializationSinksRedaction: + """cache_handler.py serialization sinks: exception text renders as a type name only.""" + + @pytest.mark.parametrize( + "import_path", + ["cachekit.no_such_module.Nope", "cachekit.cache_handler.NoSuchClass"], + ids=["import_error", "attribute_error"], + ) + def test_serializer_import_failure(self, import_path: str, caplog: pytest.LogCaptureFixture) -> None: + with caplog.at_level(logging.WARNING), pytest.raises((ImportError, AttributeError)) as exc_info: + _get_cached_serializer_class("lab304-bogus", import_path) + + _assert_error_text_redacted(caplog, exc_info.value) + + def test_serialize_failure(self, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture) -> None: + handler = CacheSerializationHandler(serializer_name="default", encryption=False) + error = RuntimeError(f"serializer exploded on {TENANT_KEY}") + monkeypatch.setattr(handler._base_serializer, "serialize", MagicMock(side_effect=error)) + + with caplog.at_level(logging.ERROR), pytest.raises(SerializationError): + handler.serialize_data({"a": 1}, cache_key=TENANT_KEY) + + _assert_error_text_redacted(caplog, error) + + def test_interop_deserialize_failure_redacts_key( + self, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture + ) -> None: + handler = CacheSerializationHandler(serializer_name="default", encryption=False, interop_mode=True) + error = RuntimeError(f"decoder exploded on {TENANT_KEY}") + monkeypatch.setattr(handler._base_serializer, "deserialize", MagicMock(side_effect=error)) + + with caplog.at_level(logging.ERROR), pytest.raises(SerializationError): + handler.deserialize_data(b"\x81\xa1a\x01", TENANT_KEY) + + _assert_redacted(caplog, TENANT_KEY) + _assert_error_text_redacted(caplog, error) + + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) + async def test_async_streaming_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + """set_streaming_async: the BackendError sink and the producer-failure sink.""" + backend = MagicMock() + backend.set_streaming.side_effect = error + handler = StandardCacheHandler(backend=backend) + + with caplog.at_level(logging.ERROR): + assert await handler.set_streaming_async(TENANT_KEY, lambda sink: None) is False + + _assert_redacted(caplog, TENANT_KEY) + + +class TestDecoratorWrapperRedaction: + """Direct logger calls in decorators/wrapper.py that bypass the orchestrator sink.""" + + @staticmethod + def _poison_deserialize(monkeypatch: pytest.MonkeyPatch, error: Exception) -> None: + # Class-level patch: the wrapper reaches deserialize_data through the handler instance + # it built at decoration time, so an instance patch has nothing to attach to. + monkeypatch.setattr(CacheSerializationHandler, "deserialize_data", MagicMock(side_effect=error)) + + def test_sync_l1_deserialization_failure_redacts_key( + self, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture + ) -> None: + backend = _DictBackend() + + @cache(backend=backend, ttl=300, l1_enabled=True, namespace="lab304-l1-sync") + def get_user(user_id: int) -> dict[str, int]: + return {"id": user_id} + + assert get_user(1) == {"id": 1} # populates L1 and L2 + (cache_key,) = backend.store + error = RuntimeError(f"corrupt entry for {cache_key}") + self._poison_deserialize(monkeypatch, error) + + with caplog.at_level(logging.WARNING, logger="cachekit"): + assert get_user(1) == {"id": 1} # L1 hit fails, L2 fails, function recomputes + + _assert_redacted(caplog, cache_key) + _assert_error_text_redacted(caplog, error) + + async def test_async_l1_deserialization_failure_redacts_key( + self, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture + ) -> None: + backend = _DictBackend() + + @cache(backend=backend, ttl=300, l1_enabled=True, namespace="lab304-l1-async") + async def get_user(user_id: int) -> dict[str, int]: + return {"id": user_id} + + assert await get_user(1) == {"id": 1} + (cache_key,) = backend.store + error = RuntimeError(f"corrupt entry for {cache_key}") + self._poison_deserialize(monkeypatch, error) + + with caplog.at_level(logging.WARNING, logger="cachekit"): + assert await get_user(1) == {"id": 1} + + _assert_redacted(caplog, cache_key) + _assert_error_text_redacted(caplog, error) + + async def test_async_double_check_failure_redacts_key( + self, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture + ) -> None: + """Post-lock double-check read raises: logged at debug, function still recomputes.""" + backend = _LockingDictBackend() + error = RuntimeError(f"double-check exploded on {TENANT_KEY}") + real_get = CacheOperationHandler.get_cached_value_async + calls: list[str] = [] + + async def second_call_raises(self: CacheOperationHandler, cache_key: str, *args: Any, **kwargs: Any) -> Any: + calls.append(cache_key) + if len(calls) == 2: # 1st = pre-lock read (miss), 2nd = post-lock double-check + raise error + return await real_get(self, cache_key, *args, **kwargs) + + monkeypatch.setattr(CacheOperationHandler, "get_cached_value_async", second_call_raises) + + @cache(backend=backend, ttl=300, l1_enabled=False, namespace="lab304-dc") + async def get_user(user_id: int) -> dict[str, int]: + return {"id": user_id} + + with caplog.at_level(logging.DEBUG, logger="cachekit"): + assert await get_user(1) == {"id": 1} + + assert len(calls) == 2 + _assert_redacted(caplog, calls[1]) + _assert_error_text_redacted(caplog, error) + + @staticmethod + def _failing_provider(monkeypatch: pytest.MonkeyPatch, error: Exception) -> None: + provider = MagicMock() + provider.get_backend.side_effect = error + monkeypatch.setattr("cachekit.decorators.wrapper.get_backend_provider", lambda: provider) + + def test_sync_invalidate_provider_failure(self, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture) -> None: + @cache(ttl=300, namespace="lab304-inv-sync") + def get_user(user_id: int) -> dict[str, int]: + return {"id": user_id} + + error = RuntimeError(f"provider exploded for {TENANT_KEY}") + self._failing_provider(monkeypatch, error) + + with caplog.at_level(logging.DEBUG, logger="cachekit"): + get_user.invalidate_cache(1) # no L2 to clear; must not raise + + _assert_error_text_redacted(caplog, error) + + async def test_async_invalidate_provider_failure( + self, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture + ) -> None: + @cache(ttl=300, namespace="lab304-inv-async") + async def get_user(user_id: int) -> dict[str, int]: + return {"id": user_id} + + error = RuntimeError(f"provider exploded for {TENANT_KEY}") + self._failing_provider(monkeypatch, error) + + with caplog.at_level(logging.DEBUG, logger="cachekit"): + await get_user.invalidate_cache(1) + + _assert_error_text_redacted(caplog, error) + + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) + def test_sync_interop_delete_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + backend = _DictBackend() + + @cache(backend=backend, l1_enabled=False, interop="get_user", namespace="users") + def get_user(user_id: int) -> dict[str, int]: + return {"id": user_id} + + get_user(1) + (interop_key,) = backend.store + backend.delete_error = error + + with caplog.at_level(logging.ERROR): + get_user.invalidate_cache(1) + + _assert_redacted(caplog, interop_key) + + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) + async def test_async_interop_delete_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + backend = _DictBackend() + + @cache(backend=backend, l1_enabled=False, interop="get_user", namespace="users") + async def get_user(user_id: int) -> dict[str, int]: + return {"id": user_id} + + await get_user(1) + (interop_key,) = backend.store + backend.delete_error = error + + with caplog.at_level(logging.ERROR): + await get_user.invalidate_cache(1) + + _assert_redacted(caplog, interop_key) diff --git a/tests/unit/test_orchestrator_error_handling.py b/tests/unit/test_orchestrator_error_handling.py index 142780c2..e4186199 100644 --- a/tests/unit/test_orchestrator_error_handling.py +++ b/tests/unit/test_orchestrator_error_handling.py @@ -367,6 +367,13 @@ def test_structured_log_cache_operation_redacts_key(self, caplog: pytest.LogCapt if structured is not None: assert self.TENANT_KEY not in str(structured) + def test_structured_log_cache_operation_without_key(self, caplog: pytest.LogCaptureFixture) -> None: + """No ``key`` kwarg: nothing to redact, the ``unknown`` sentinel stands in.""" + with caplog.at_level(logging.INFO): + self._orchestrator().log_cache_operation(operation="circuit_breaker_open") + + assert any("Cache operation: circuit_breaker_open" in record.getMessage() for record in caplog.records) + 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. From c48643f3011c4726bd4983a511ded515ec3649c5 Mon Sep 17 00:00:00 2001 From: Mark S Date: Sat, 12 Sep 2026 20:07:04 +1000 Subject: [PATCH 16/17] =?UTF-8?q?test(logging):=20pin=20the=20L1=20sink=20?= =?UTF-8?q?and=20harden=20the=20redaction=20helpers=20=E2=80=94=20panel=20?= =?UTF-8?q?remediation=20(LAB-304)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Expert panel on fd65fe2 (bug-hunter, security, craftsman, catchphrase), all surviving findings applied: - The two L1-deserialization tests were satisfied by the L2 read sink's identical `: RuntimeError` line — the same wrong-target class fd65fe2 fixed for the async L2 reads. L2 is now emptied before the poisoned L1 hit and the "L1 cache deserialization failed for " prefix is asserted, so wrapper.py:1307/1665 are the only sinks that can pass them. - _assert_error_text_redacted now also asserts TENANT_KEY is absent, and both helpers read record.structured alongside the message: a key hidden in the structured extra is still a leak. - Interop-delete tests run one key-bearing shape per sink (a single `except Exception`; four shapes proved what one does) and now pin the exception-text redaction they previously left unchecked. - Serializer-import test keeps one shape (one except clause); the double-check stub returns None instead of a pass-through that always returned None; the lock stub takes **kwargs; _DictBackend drops key_prefix/exists/health_check (nothing on the decorator path reads them); the orchestrator no-key test asserts the "unknown" sentinel it names; docstrings say which sinks the file pins. tests/unit + tests/critical -m "not slow": 2382 passed, 13 skipped. Patch coverage unchanged at 104/118 (88%). LAB-3432. --- tests/unit/test_error_path_key_redaction.py | 120 +++++++++--------- .../unit/test_orchestrator_error_handling.py | 6 +- 2 files changed, 65 insertions(+), 61 deletions(-) diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py index b62ce181..95507e55 100644 --- a/tests/unit/test_error_path_key_redaction.py +++ b/tests/unit/test_error_path_key_redaction.py @@ -1,17 +1,18 @@ """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. +``TestCacheKeyRedaction``: that file pins ``FeatureOrchestrator.handle_cache_error``; +this file pins every direct logger sink outside the orchestrator — in +``cache_handler.py`` (backend set/get/delete, streaming, serialization, TTL +refresh) and ``decorators/wrapper.py`` (L1 deserialization, post-lock double +check, invalidation). Each test drives a real failure and asserts the +tenant-identifying key appears only as its blake2b digest, never verbatim, and +the exception renders as a type name, never its text. """ from __future__ import annotations import logging -from collections.abc import AsyncIterator from contextlib import asynccontextmanager from typing import Any, Optional from unittest.mock import MagicMock @@ -89,9 +90,7 @@ async def get_with_freshness_async(self, key: str) -> Optional[tuple[bytes, bool class _DictBackend: - """Transparent in-memory BaseBackend; ``delete_error`` makes delete raise.""" - - key_prefix = "" # interop compatibility contract (ensure_interop_backend_compatible) + """Transparent in-memory backend; ``delete_error`` makes delete raise.""" def __init__(self) -> None: self.store: dict[str, bytes] = {} @@ -108,20 +107,12 @@ def delete(self, key: str) -> bool: raise self.delete_error return self.store.pop(key, None) is not None - def exists(self, key: str) -> bool: - return key in self.store - - def health_check(self) -> tuple[bool, dict[str, Any]]: - return True, {"backend_type": "dict"} - class _LockingDictBackend(_DictBackend): - """Adds the LockableBackend protocol so the async wrapper takes the stampede-lock branch.""" + """Adds ``acquire_lock`` so the async wrapper takes the stampede-lock branch.""" @asynccontextmanager - async def acquire_lock( - self, key: str, timeout: float = 10.0, blocking_timeout: Optional[float] = None - ) -> AsyncIterator[bool]: + async def acquire_lock(self, key: str, **_: Any): yield True @@ -136,18 +127,24 @@ async def refresh_ttl(self, key: str, ttl: int) -> bool: raise self._error +def _messages(caplog: pytest.LogCaptureFixture) -> list[str]: + """Message text plus the structured ``extra`` payload — a key hidden in ``record.structured`` is still a leak.""" + return [r.getMessage() + str(getattr(r, "structured", "")) for r in caplog.records] + + def _assert_error_text_redacted(caplog: pytest.LogCaptureFixture, error: Exception) -> None: """The exception renders as its type name only; its free-form text (which may echo a key) never does.""" - messages = [r.getMessage() for r in caplog.records] + messages = _messages(caplog) assert str(error), "test bug: a blank message would match every record" assert any(type(error).__name__ in m for m in messages), f"expected {type(error).__name__} in logs; got {messages!r}" assert not any(str(error) in m for m in messages), f"exception text leaked into logs: {messages!r}" + assert not any(TENANT_KEY in m for m in messages), f"raw key leaked into logs: {messages!r}" 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] + messages = _messages(caplog) 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}" assert not any(TENANT_KEY in m for m in messages), f"key-bearing exception text leaked into logs: {messages!r}" @@ -174,6 +171,18 @@ def test_delete_failure_redacts_key(self, error: Exception, caplog: pytest.LogCa _assert_redacted(caplog, TENANT_KEY) + @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) + async def test_async_streaming_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + """set_streaming_async: both except branches (BackendError / generic), driven from the backend.""" + backend = MagicMock() + backend.set_streaming.side_effect = error + handler = StandardCacheHandler(backend=backend) + + with caplog.at_level(logging.ERROR): + assert await handler.set_streaming_async(TENANT_KEY, lambda sink: None) is False + + _assert_redacted(caplog, TENANT_KEY) + @staticmethod def _operation_handler(error: Exception) -> CacheOperationHandler: # StandardCacheHandler swallows backend errors at its OWN sink and returns None, so a @@ -434,14 +443,9 @@ def test_memcached_classifier_does_not_leak_key(self) -> None: class TestSerializationSinksRedaction: """cache_handler.py serialization sinks: exception text renders as a type name only.""" - @pytest.mark.parametrize( - "import_path", - ["cachekit.no_such_module.Nope", "cachekit.cache_handler.NoSuchClass"], - ids=["import_error", "attribute_error"], - ) - def test_serializer_import_failure(self, import_path: str, caplog: pytest.LogCaptureFixture) -> None: - with caplog.at_level(logging.WARNING), pytest.raises((ImportError, AttributeError)) as exc_info: - _get_cached_serializer_class("lab304-bogus", import_path) + def test_serializer_import_failure(self, caplog: pytest.LogCaptureFixture) -> None: + with caplog.at_level(logging.WARNING), pytest.raises(ImportError) as exc_info: + _get_cached_serializer_class("lab304-bogus", "cachekit.no_such_module.Nope") _assert_error_text_redacted(caplog, exc_info.value) @@ -463,23 +467,11 @@ def test_interop_deserialize_failure_redacts_key( monkeypatch.setattr(handler._base_serializer, "deserialize", MagicMock(side_effect=error)) with caplog.at_level(logging.ERROR), pytest.raises(SerializationError): - handler.deserialize_data(b"\x81\xa1a\x01", TENANT_KEY) + handler.deserialize_data(b"irrelevant", TENANT_KEY) # the patched decoder raises before reading them _assert_redacted(caplog, TENANT_KEY) _assert_error_text_redacted(caplog, error) - @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) - async def test_async_streaming_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: - """set_streaming_async: the BackendError sink and the producer-failure sink.""" - backend = MagicMock() - backend.set_streaming.side_effect = error - handler = StandardCacheHandler(backend=backend) - - with caplog.at_level(logging.ERROR): - assert await handler.set_streaming_async(TENANT_KEY, lambda sink: None) is False - - _assert_redacted(caplog, TENANT_KEY) - class TestDecoratorWrapperRedaction: """Direct logger calls in decorators/wrapper.py that bypass the orchestrator sink.""" @@ -490,6 +482,13 @@ def _poison_deserialize(monkeypatch: pytest.MonkeyPatch, error: Exception) -> No # it built at decoration time, so an instance patch has nothing to attach to. monkeypatch.setattr(CacheSerializationHandler, "deserialize_data", MagicMock(side_effect=error)) + @staticmethod + def _assert_l1_sink(caplog: pytest.LogCaptureFixture, cache_key: str, error: Exception) -> None: + _assert_redacted(caplog, cache_key) + _assert_error_text_redacted(caplog, error) + prefix = f"L1 cache deserialization failed for {redact_cache_key(cache_key)}" + assert any(m.startswith(prefix) for m in _messages(caplog)), f"L1 sink did not fire: {_messages(caplog)!r}" + def test_sync_l1_deserialization_failure_redacts_key( self, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture ) -> None: @@ -501,14 +500,14 @@ def get_user(user_id: int) -> dict[str, int]: assert get_user(1) == {"id": 1} # populates L1 and L2 (cache_key,) = backend.store + backend.store.clear() # L2 misses, so the L1 sink is the only one that can emit the digest error = RuntimeError(f"corrupt entry for {cache_key}") self._poison_deserialize(monkeypatch, error) with caplog.at_level(logging.WARNING, logger="cachekit"): - assert get_user(1) == {"id": 1} # L1 hit fails, L2 fails, function recomputes + assert get_user(1) == {"id": 1} # L1 hit fails, L2 misses, function recomputes - _assert_redacted(caplog, cache_key) - _assert_error_text_redacted(caplog, error) + self._assert_l1_sink(caplog, cache_key, error) async def test_async_l1_deserialization_failure_redacts_key( self, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture @@ -521,14 +520,14 @@ async def get_user(user_id: int) -> dict[str, int]: assert await get_user(1) == {"id": 1} (cache_key,) = backend.store + backend.store.clear() error = RuntimeError(f"corrupt entry for {cache_key}") self._poison_deserialize(monkeypatch, error) with caplog.at_level(logging.WARNING, logger="cachekit"): assert await get_user(1) == {"id": 1} - _assert_redacted(caplog, cache_key) - _assert_error_text_redacted(caplog, error) + self._assert_l1_sink(caplog, cache_key, error) async def test_async_double_check_failure_redacts_key( self, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture @@ -536,14 +535,12 @@ async def test_async_double_check_failure_redacts_key( """Post-lock double-check read raises: logged at debug, function still recomputes.""" backend = _LockingDictBackend() error = RuntimeError(f"double-check exploded on {TENANT_KEY}") - real_get = CacheOperationHandler.get_cached_value_async calls: list[str] = [] - async def second_call_raises(self: CacheOperationHandler, cache_key: str, *args: Any, **kwargs: Any) -> Any: + async def second_call_raises(self: CacheOperationHandler, cache_key: str, *_: Any, **__: Any) -> None: calls.append(cache_key) - if len(calls) == 2: # 1st = pre-lock read (miss), 2nd = post-lock double-check + if len(calls) == 2: # 1st = pre-lock read (a miss: the store is empty), 2nd = post-lock double-check raise error - return await real_get(self, cache_key, *args, **kwargs) monkeypatch.setattr(CacheOperationHandler, "get_cached_value_async", second_call_raises) @@ -592,8 +589,14 @@ async def get_user(user_id: int) -> dict[str, int]: _assert_error_text_redacted(caplog, error) - @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) - def test_sync_interop_delete_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + @staticmethod + def _arm_delete_failure(backend: _DictBackend) -> tuple[str, Exception]: + """One shape suffices: the sink is a single ``except Exception``; the text carries the key.""" + (interop_key,) = backend.store + backend.delete_error = ValueError(f"illegal input: {interop_key}") + return interop_key, backend.delete_error + + def test_sync_interop_delete_failure_redacts_key(self, caplog: pytest.LogCaptureFixture) -> None: backend = _DictBackend() @cache(backend=backend, l1_enabled=False, interop="get_user", namespace="users") @@ -601,16 +604,15 @@ def get_user(user_id: int) -> dict[str, int]: return {"id": user_id} get_user(1) - (interop_key,) = backend.store - backend.delete_error = error + interop_key, error = self._arm_delete_failure(backend) with caplog.at_level(logging.ERROR): get_user.invalidate_cache(1) _assert_redacted(caplog, interop_key) + _assert_error_text_redacted(caplog, error) - @pytest.mark.parametrize("error", ERRORS, ids=ERROR_IDS) - async def test_async_interop_delete_failure_redacts_key(self, error: Exception, caplog: pytest.LogCaptureFixture) -> None: + async def test_async_interop_delete_failure_redacts_key(self, caplog: pytest.LogCaptureFixture) -> None: backend = _DictBackend() @cache(backend=backend, l1_enabled=False, interop="get_user", namespace="users") @@ -618,10 +620,10 @@ async def get_user(user_id: int) -> dict[str, int]: return {"id": user_id} await get_user(1) - (interop_key,) = backend.store - backend.delete_error = error + interop_key, error = self._arm_delete_failure(backend) with caplog.at_level(logging.ERROR): await get_user.invalidate_cache(1) _assert_redacted(caplog, interop_key) + _assert_error_text_redacted(caplog, error) diff --git a/tests/unit/test_orchestrator_error_handling.py b/tests/unit/test_orchestrator_error_handling.py index e4186199..a430603b 100644 --- a/tests/unit/test_orchestrator_error_handling.py +++ b/tests/unit/test_orchestrator_error_handling.py @@ -368,11 +368,13 @@ def test_structured_log_cache_operation_redacts_key(self, caplog: pytest.LogCapt assert self.TENANT_KEY not in str(structured) def test_structured_log_cache_operation_without_key(self, caplog: pytest.LogCaptureFixture) -> None: - """No ``key`` kwarg: nothing to redact, the ``unknown`` sentinel stands in.""" + """No ``key`` kwarg: the redaction branch is skipped and the ``unknown`` sentinel stands in.""" with caplog.at_level(logging.INFO): self._orchestrator().log_cache_operation(operation="circuit_breaker_open") - assert any("Cache operation: circuit_breaker_open" in record.getMessage() for record in caplog.records) + records = [r for r in caplog.records if "Cache operation: circuit_breaker_open" in r.getMessage()] + assert records + assert all(getattr(record, "structured", {}).get("cache_key") == "unknown" for record in records) 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. From 9c76386e4329c3c0ee3e9d332ac895e6e44b77b0 Mon Sep 17 00:00:00 2001 From: Ray Walker Date: Sat, 12 Sep 2026 22:12:01 +1000 Subject: [PATCH 17/17] =?UTF-8?q?fix:=20address=20coderabbit=20review=20?= =?UTF-8?q?=E2=80=94=20propagate=20log=20aliases=20through=20nested=20rece?= =?UTF-8?q?ivers?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit _is_logger_receiver did not receive the direct/aliases collections, so the redaction architecture detector missed getattr(lg, level)(...) on an aliased module and gl(__name__).warning(...) on an aliased getLogger factory — both could carry a raw cache key past the guard. Thread both collections through _is_logger_receiver in every branch and pin the two forms with detector cases. CodeRabbit-Resolved: tests/unit/test_log_redaction_architecture.py:108:Propagate import aliases through nested logger receivers --- tests/unit/test_log_redaction_architecture.py | 31 ++++++++++++------- 1 file changed, 20 insertions(+), 11 deletions(-) diff --git a/tests/unit/test_log_redaction_architecture.py b/tests/unit/test_log_redaction_architecture.py index 15047c0a..01068f77 100644 --- a/tests/unit/test_log_redaction_architecture.py +++ b/tests/unit/test_log_redaction_architecture.py @@ -68,13 +68,14 @@ def _call_args(node: ast.Call) -> list[ast.expr]: return [*node.args, *(kw.value for kw in node.keywords)] -def _is_logger_receiver(node: ast.AST) -> bool: - if isinstance(node, ast.Name): - return bool(LOGGER_NAME_RE.search(node.id)) +def _is_logger_receiver(node: ast.AST, direct: dict[str, str] | None = None, aliases: frozenset[str] = frozenset()) -> bool: + if isinstance(node, ast.Name): # logger / self... and ``import logging as lg`` module aliases + return bool(LOGGER_NAME_RE.search(node.id)) or node.id in aliases if isinstance(node, ast.Attribute): # self.logger / self._logger return bool(LOGGER_NAME_RE.search(node.attr)) - if isinstance(node, ast.Call): # get_logger().warning(...) / logging.getLogger(__name__).info(...) - return _call_name(node) in LOGGER_FACTORIES + if isinstance(node, ast.Call): # get_logger().warning(...) / getLogger(__name__).info(...), incl. aliased factories + name = _call_name(node) + return name in LOGGER_FACTORIES or (direct or {}).get(name) == "getLogger" return False @@ -102,12 +103,15 @@ def _is_logger_call(node: ast.Call, direct: dict[str, str] | None = None, aliase func = node.func if isinstance(func, ast.Name): # from logging import warning; warning("%s", key) return func.id in (direct or {}) - if isinstance(func, ast.Attribute): - receiver = func.value - aliased = isinstance(receiver, ast.Name) and receiver.id in aliases # import logging as lg; lg.warning(...) - return func.attr in LOG_METHODS and (aliased or _is_logger_receiver(receiver)) - # getattr(logger, level.lower())(message, ...) - return isinstance(func, ast.Call) and _call_name(func) == "getattr" and bool(func.args) and _is_logger_receiver(func.args[0]) + if isinstance(func, ast.Attribute): # lg.warning(...), get_logger().info(...), gl(__name__).warning(...) + return func.attr in LOG_METHODS and _is_logger_receiver(func.value, direct, aliases) + # getattr(logger, level.lower())(message, ...) — receiver may be a module alias (getattr(lg, level)) + return ( + isinstance(func, ast.Call) + and _call_name(func) == "getattr" + and bool(func.args) + and _is_logger_receiver(func.args[0], direct, aliases) + ) def _key_identifier(node: ast.AST) -> str | None: @@ -227,6 +231,11 @@ def test_detector_catches_the_shapes_it_claims_to() -> None: ("from warnings import warn\nwarn(f'{cache_key}')", True), # warnings.warn imported directly ("import logging as lg\nlg.warning('%s', cache_key)", True), # aliased module receiver ("from logging import getLogger\ngetLogger(__name__).info('%s', cache_key)", True), # direct getLogger factory + ( + "from logging import getLogger as gl\ngl(__name__).warning(f'{cache_key}')", + True, + ), # aliased getLogger factory receiver + ("import logging as lg\ngetattr(lg, 'warning')(f'{cache_key}')", True), # getattr on an aliased module receiver ("from logging import exception\nexception('boom')", True), # directly imported traceback emitter ("def warning(msg): pass\nwarning(f'{cache_key}')", False), # same name, not imported from logging # exception text