diff --git a/.secrets.baseline b/.secrets.baseline index 809c294..c2fb19f 100644 --- a/.secrets.baseline +++ b/.secrets.baseline @@ -222,7 +222,7 @@ "filename": "src/cachekit/cache_handler.py", "hashed_secret": "5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8", "is_verified": false, - "line_number": 430 + "line_number": 423 } ], "src/cachekit/config/decorator.py": [ @@ -887,5 +887,5 @@ } ] }, - "generated_at": "2026-08-07T16:45:43Z" + "generated_at": "2026-08-30T16:39:38Z" } diff --git a/SECURITY.md b/SECURITY.md index 008160a..4cba081 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. `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) 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/pyproject.toml b/pyproject.toml index 3860e79..4b74fa9 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -247,10 +247,11 @@ constraint-dependencies = [ "urllib3>=2.7.0", "fonttools>=4.60.2", "werkzeug>=3.1.4", - # pip is a dev-only transitive dep (pip-audit -> pip-api -> pip). 26.1.2 fixes - # PYSEC-2026-196 (entry-point path traversal), GHSA-58qw-9mgm-455v (tar/zip - # confusion) and GHSA-jp4c-xjxw-mgf9 (self-update import ordering). - "pip>=26.1.2", + # pip is a dev-only transitive dep (pip-audit -> pip-api -> pip). 26.2 fixes + # PYSEC-2026-3721; 26.1.2 fixed PYSEC-2026-196 (entry-point path traversal), + # GHSA-58qw-9mgm-455v (tar/zip confusion) and GHSA-jp4c-xjxw-mgf9 (self-update + # import ordering). + "pip>=26.2", # h2 is a transitive dep (httpx[http2] -> h2). 4.4.1 fixes # GHSA-6hr6-w5qg-qmwg (duplicate Host headers forwarded on HTTP/2 -> # HTTP/1.1 downgrade — request smuggling primitive). diff --git a/src/cachekit/backends/errors.py b/src/cachekit/backends/errors.py index 80ff1a1..82665ba 100644 --- a/src/cachekit/backends/errors.py +++ b/src/cachekit/backends/errors.py @@ -10,6 +10,8 @@ from enum import Enum from typing import Optional +from ..hash_utils import redact_cache_key + class BackendErrorType(str, Enum): """Error classification for circuit breaker and retry decisions. @@ -52,7 +54,9 @@ class BackendError(Exception): error_type: Error classification (see BackendErrorType) original_exception: The original exception that caused this error (if any) operation: The operation that failed (get, set, delete, exists) - key: The cache key involved in the operation (optional, for debugging) + key: The cache key involved in the operation (optional, for debugging). + Kept raw on the attribute for programmatic access; the formatted + exception text carries only its redacted digest (CWE-532). Example: >>> from redis import ConnectionError as RedisConnectionError @@ -99,9 +103,11 @@ def _format_message(self) -> str: if self.operation: parts.append(f"operation={self.operation}") if self.key: - # Truncate key for security/readability - key_display = self.key[:50] + "..." if len(self.key) > 50 else self.key - parts.append(f"key={key_display}") + # Redact, don't truncate: str(e) reaches log interpolation at every + # error sink, and cache keys embed caller-supplied tenant/user + # identifiers (CWE-532, LAB-304). The fixed-length digest keeps the + # message correlatable with the sinks' own redact_cache_key() output. + parts.append(f"key={redact_cache_key(self.key)}") if self.error_type: parts.append(f"type={self.error_type.value}") return " | ".join(parts) diff --git a/src/cachekit/backends/memcached/backend.py b/src/cachekit/backends/memcached/backend.py index 1f80167..d041e43 100644 --- a/src/cachekit/backends/memcached/backend.py +++ b/src/cachekit/backends/memcached/backend.py @@ -127,7 +127,10 @@ def set(self, key: str, value: bytes, ttl: Optional[int] = None) -> None: if max_size and len(value) > max_size: raise BackendError( message=( - f"Value for key {key!r} is {len(value)} bytes, which exceeds the Memcached " + # No raw key in the message — it reaches log sinks via str(e) + # (CWE-532); the key= segment _format_message appends carries + # the redacted digest for correlation. + f"Value is {len(value)} bytes, which exceeds the Memcached " f"max item size of {max_size} bytes. Memcached cannot store it. Enable " f"compression, use a larger-payload backend (Redis/SaaS/File), or raise both " f"the server's -I limit and CACHEKIT_MEMCACHED_MAX_ITEM_SIZE_BYTES." diff --git a/src/cachekit/backends/memcached/error_handler.py b/src/cachekit/backends/memcached/error_handler.py index 880ca9e..f0cd862 100644 --- a/src/cachekit/backends/memcached/error_handler.py +++ b/src/cachekit/backends/memcached/error_handler.py @@ -68,19 +68,24 @@ def classify_memcached_error( key=key, ) - # Permanent — illegal input, client errors (don't retry) + # Permanent — illegal input, client errors (don't retry). + # Only the exception TYPE goes in the message: pymemcache embeds the raw + # cache key in illegal-input error text ("Key is too long: %r"), and the + # message reaches log sinks via str(e) (CWE-532). Full details stay on + # original_exception for programmatic access. if isinstance(exc, (MemcacheIllegalInputError, MemcacheClientError)): return BackendError( - message=f"Memcached permanent error during {operation}: {exc}", + message=f"Memcached permanent error during {operation}: {type(exc).__name__}", error_type=BackendErrorType.PERMANENT, original_exception=exc, operation=operation, key=key, ) - # Unknown — safe default + # Unknown — safe default. Arbitrary exception text has unknown provenance + # and may embed the key, so only the type name goes in the message (CWE-532). return BackendError( - message=f"Memcached unknown error during {operation}: {exc}", + message=f"Memcached unknown error during {operation}: {type(exc).__name__}", error_type=BackendErrorType.UNKNOWN, original_exception=exc, operation=operation, diff --git a/src/cachekit/backends/provider.py b/src/cachekit/backends/provider.py index a6e4b07..c67fe33 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_key_for_log + 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_key_for_log(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_key_for_log(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_key_for_log(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_key_for_log(key)}") class DefaultLoggerProvider(LoggerProvider): diff --git a/src/cachekit/cache_handler.py b/src/cachekit/cache_handler.py index 1fce645..79f4d87 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 @@ -1915,12 +1908,12 @@ 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: # 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 66abbc2..cb51936 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 ..hash_utils import redact_key_for_log from ..monitoring.correlation_tracking import CorrelationTracker from ..monitoring.pool_monitor import OptimizedPoolMonitor @@ -271,9 +272,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 +418,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 +438,10 @@ def handle_cache_error( # Use orchestrator namespace if not provided namespace = namespace or self.namespace + # Redact once at the sink so every error path is covered by construction + # (CWE-532) — callers pass the raw key; sentinels pass through readable. + cache_key = redact_key_for_log(cache_key) + # 1. Record exception in span and metrics if span: self.record_exception(span, error) diff --git a/src/cachekit/decorators/wrapper.py b/src/cachekit/decorators/wrapper.py index f84847a..78bd836 100644 --- a/src/cachekit/decorators/wrapper.py +++ b/src/cachekit/decorators/wrapper.py @@ -1229,7 +1229,7 @@ def sync_wrapper(*args: Any, **kwargs: Any) -> Any: # noqa: PLR0912 raise except Exception as e: # L1 deserialization failed - invalidate and continue to L2 - logger().warning(f"L1 cache deserialization failed for {cache_key}: {e}") + logger().warning(f"L1 cache deserialization failed for {redact_cache_key(cache_key)}: {e}") _l1_cache.invalidate(cache_key) # Continue with the rest of the sync wrapper logic... @@ -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", @@ -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) @@ -1815,7 +1817,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, @@ -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 @@ -1897,7 +1901,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, @@ -1944,7 +1948,7 @@ def invalidate_cache(*args: Any, **kwargs: Any) -> None: try: _backend.delete(key) except Exception as e: - _logger.debug("Failed to delete L2 key %s: %s", key, e) + _logger.debug("Failed to delete L2 key %s: %s", redact_cache_key(key), e) continue # keep key tracked for retry _cached_keys.discard(key) return @@ -1971,7 +1975,7 @@ def invalidate_cache(*args: Any, **kwargs: Any) -> None: try: _backend.delete(cache_key) except Exception as e: - _logger.error("Failed to delete L2 interop key %s: %s", cache_key, e) + _logger.error("Failed to delete L2 interop key %s: %s", redact_cache_key(cache_key), e) else: invalidator.invalidate_cache(func, args, kwargs, namespace) @@ -2002,7 +2006,7 @@ async def ainvalidate_cache(*args: Any, **kwargs: Any) -> None: try: _backend.delete(key) except Exception as e: - _logger.debug("Failed to delete L2 key %s: %s", key, e) + _logger.debug("Failed to delete L2 key %s: %s", redact_cache_key(key), e) continue _cached_keys.discard(key) return @@ -2030,7 +2034,7 @@ async def ainvalidate_cache(*args: Any, **kwargs: Any) -> None: try: _backend.delete(cache_key) except Exception as e: - _logger.error("Failed to delete L2 interop key %s: %s", cache_key, e) + _logger.error("Failed to delete L2 interop key %s: %s", redact_cache_key(cache_key), e) else: await invalidator.invalidate_cache_async(func, args, kwargs, namespace) diff --git a/src/cachekit/hash_utils.py b/src/cachekit/hash_utils.py index 235a5be..16007f0 100644 --- a/src/cachekit/hash_utils.py +++ b/src/cachekit/hash_utils.py @@ -3,11 +3,70 @@ Uses BLAKE3 for hashing (approximately 2-3 GB/s throughput). """ +import hashlib +import re 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). + + The exact output format (````) is pinned by + ``_REDACTED_KEY_RE`` below and by ``test_pass_through_is_strict_allow_list`` + — change them together. + """ + return f"" + + +#: 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") + + +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 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): + 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/l1_cache.py b/src/cachekit/l1_cache.py index 845d4ec..c2887f8 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 @@ -199,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/src/cachekit/logging.py b/src/cachekit/logging.py index c5ccc8a..723b0f2 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_key_for_log # Configure base logger logger = logging.getLogger(__name__) @@ -251,11 +252,16 @@ 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. + # + # 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" @@ -406,12 +412,6 @@ def _get_context(self) -> dict[str, Any]: context["correlation_id"] = self._context.correlation_id return context - def _mask_sensitive_data(self, data: str) -> str: - """Mask sensitive data if enabled.""" - if self.mask_sensitive: - return mask_sensitive_patterns(data) - return data - # Compatibility methods for tests def redis_operation_failed(self, operation: str, key: str, error: Exception, **kwargs): """Log Redis operation failure.""" diff --git a/tests/critical/test_memcached_backend_critical.py b/tests/critical/test_memcached_backend_critical.py index b5d1445..6525e75 100644 --- a/tests/critical/test_memcached_backend_critical.py +++ b/tests/critical/test_memcached_backend_critical.py @@ -345,3 +345,39 @@ def compute(x: int) -> int: assert call_count == 1 # Cache hit finally: set_default_backend(original) + + +@pytest.mark.critical +def test_oversized_value_error_never_leaks_raw_key(backend, mock_hash_client): + """The oversized-value message must not embed the raw key — str(e) reaches + log sinks verbatim (CWE-532, LAB-304); the key= digest segment carries correlation.""" + tenant_key = "ns:tenant-42-alice-secret:func:app.get_user:args:deadbeef:v1" + big = b"\x00" * (1024 * 1024 + 1) + + with pytest.raises(BackendError) as exc_info: + backend.set(tenant_key, big, ttl=60) + + assert tenant_key not in str(exc_info.value) + assert "tenant-42-alice-secret" not in str(exc_info.value) + assert exc_info.value.key == tenant_key # raw on the attribute for programmatic use + + +@pytest.mark.critical +def test_classified_error_never_leaks_key_from_wrapped_exception_text(): + """pymemcache embeds the raw key in illegal-input exception text; the classified + BackendError message must carry only the exception type (CWE-532).""" + from pymemcache.exceptions import MemcacheIllegalInputError + + tenant_key = "ns:tenant-42-alice-secret:" + "x" * 300 + exc = MemcacheIllegalInputError(f"Key is too long: {tenant_key!r}") + + err = classify_memcached_error(exc, operation="set", key=tenant_key) + + assert err.error_type == BackendErrorType.PERMANENT + assert tenant_key not in str(err) + assert "tenant-42-alice-secret" not in str(err) + assert err.original_exception is exc # full detail preserved for programmatic access + + # Unknown-fallback branch: arbitrary exception text has unknown provenance + err = classify_memcached_error(RuntimeError(f"boom {tenant_key}"), operation="get", key=tenant_key) + assert "tenant-42-alice-secret" not in str(err) diff --git a/tests/integration/test_backend_error_handling.py b/tests/integration/test_backend_error_handling.py index c5bc6d9..2667aaa 100644 --- a/tests/integration/test_backend_error_handling.py +++ b/tests/integration/test_backend_error_handling.py @@ -21,6 +21,7 @@ from cachekit.backends.errors import BackendError, BackendErrorType, CapabilityNotAvailableError from cachekit.backends.redis.error_handler import classify_redis_error from cachekit.backends.redis.provider import PerRequestRedisBackend +from cachekit.hash_utils import redact_cache_key @pytest.mark.integration @@ -99,7 +100,7 @@ def test_error_repr(self): assert "transient" in repr_str def test_error_formatted_message(self): - """Test formatted message includes operation and key context.""" + """Formatted message includes operation context and the redacted key digest.""" error = BackendError( "Get failed", error_type=BackendErrorType.TRANSIENT, @@ -109,21 +110,23 @@ def test_error_formatted_message(self): msg = str(error) assert "Get failed" in msg assert "operation=get" in msg - assert "key=user:123" in msg + assert f"key={redact_cache_key('user:123')}" in msg assert "type=transient" in msg - def test_error_key_truncation(self): - """Test long keys are truncated in error messages.""" - long_key = "x" * 100 + def test_error_key_redacted_not_leaked(self): + """The raw key never appears in the exception text — only its fixed-length + digest (CWE-532, LAB-304). The attribute keeps the raw key for programmatic use.""" + tenant_key = "ns:tenant-42-alice-secret:func:app.get_user:args:deadbeef:v1" error = BackendError( "Error", error_type=BackendErrorType.TRANSIENT, - key=long_key, + key=tenant_key, ) msg = str(error) - assert "..." in msg - assert long_key not in msg - assert len(msg) < len(long_key) + assert tenant_key not in msg + assert "tenant-42-alice-secret" not in msg + assert redact_cache_key(tenant_key) in msg + assert error.key == tenant_key @pytest.mark.integration @@ -272,5 +275,6 @@ def test_error_message_composition(self): msg = str(error) assert "Operation failed" in msg assert "get" in msg - assert "cache:user:123" in msg + assert f"key={redact_cache_key('cache:user:123')}" in msg + assert "cache:user:123" not in msg assert "transient" in msg diff --git a/tests/integration/test_redis_backend.py b/tests/integration/test_redis_backend.py index 595b084..a158853 100644 --- a/tests/integration/test_redis_backend.py +++ b/tests/integration/test_redis_backend.py @@ -17,6 +17,7 @@ from cachekit.backends.base import BackendError, BaseBackend from cachekit.backends.redis import RedisBackend +from cachekit.hash_utils import redact_cache_key from ..utils.redis_test_helpers import RedisIsolationMixin @@ -486,10 +487,11 @@ def test_operation_errors_include_context(self): assert error.operation == "get" # Should include key for debugging assert error.key == "cache:user:123" - # Should include both in formatted message + # Formatted message carries the operation and the redacted key digest error_msg = str(error) assert "operation=get" in error_msg - assert "cache:user:123" in error_msg + assert redact_cache_key("cache:user:123") in error_msg + assert "cache:user:123" not in error_msg # ============================================================================= diff --git a/tests/unit/backends/test_provider.py b/tests/unit/backends/test_provider.py index 98ddf21..96e1b1a 100644 --- a/tests/unit/backends/test_provider.py +++ b/tests/unit/backends/test_provider.py @@ -25,6 +25,7 @@ LoggerProvider, SimpleLogger, ) +from cachekit.hash_utils import redact_cache_key # noqa: I001 @pytest.mark.unit @@ -117,7 +118,7 @@ def test_cache_hit_default_source(self) -> None: logger.cache_hit("key:123") - mock_logger.debug.assert_called_once_with("Redis cache hit for key: key:123") + mock_logger.debug.assert_called_once_with(f"Redis cache hit for key: {redact_cache_key('key:123')}") def test_cache_hit_custom_source(self) -> None: """Test cache hit logging with custom source.""" @@ -126,7 +127,7 @@ def test_cache_hit_custom_source(self) -> None: logger.cache_hit("key:456", source="Memcached") - mock_logger.debug.assert_called_once_with("Memcached cache hit for key: key:456") + mock_logger.debug.assert_called_once_with(f"Memcached cache hit for key: {redact_cache_key('key:456')}") def test_cache_miss(self) -> None: """Test cache miss logging.""" @@ -135,7 +136,7 @@ def test_cache_miss(self) -> None: logger.cache_miss("key:789") - mock_logger.debug.assert_called_once_with("Cache miss for key: key:789") + mock_logger.debug.assert_called_once_with(f"Cache miss for key: {redact_cache_key('key:789')}") def test_cache_stored_without_ttl(self) -> None: """Test cache storage logging without TTL.""" @@ -144,7 +145,7 @@ def test_cache_stored_without_ttl(self) -> None: logger.cache_stored("key:111") - mock_logger.debug.assert_called_once_with("Cached result for key: key:111") + mock_logger.debug.assert_called_once_with(f"Cached result for key: {redact_cache_key('key:111')}") def test_cache_stored_with_ttl(self) -> None: """Test cache storage logging with TTL.""" @@ -153,7 +154,7 @@ def test_cache_stored_with_ttl(self) -> None: logger.cache_stored("key:222", ttl=3600) - mock_logger.debug.assert_called_once_with("Cached result for key: key:222 with TTL 3600") + mock_logger.debug.assert_called_once_with(f"Cached result for key: {redact_cache_key('key:222')} with TTL 3600") def test_cache_invalidated_default_source(self) -> None: """Test cache invalidation logging with default source.""" @@ -162,7 +163,7 @@ def test_cache_invalidated_default_source(self) -> None: logger.cache_invalidated("key:333") - mock_logger.debug.assert_called_once_with("Invalidated Redis cache for key: key:333") + mock_logger.debug.assert_called_once_with(f"Invalidated Redis cache for key: {redact_cache_key('key:333')}") def test_cache_invalidated_custom_source(self) -> None: """Test cache invalidation logging with custom source.""" @@ -171,7 +172,7 @@ def test_cache_invalidated_custom_source(self) -> None: logger.cache_invalidated("key:444", source="L1") - mock_logger.debug.assert_called_once_with("Invalidated L1 cache for key: key:444") + mock_logger.debug.assert_called_once_with(f"Invalidated L1 cache for key: {redact_cache_key('key:444')}") @pytest.mark.unit diff --git a/tests/unit/test_backend_protocol.py b/tests/unit/test_backend_protocol.py index e4d1618..4db9b33 100644 --- a/tests/unit/test_backend_protocol.py +++ b/tests/unit/test_backend_protocol.py @@ -8,6 +8,7 @@ import pytest from cachekit.backends.base import BackendError, BaseBackend +from cachekit.hash_utils import redact_cache_key @pytest.mark.unit @@ -31,21 +32,22 @@ def test_error_with_operation(self): assert error.operation == "get" def test_error_with_key(self): - """BackendError should include key in formatted message.""" + """BackendError should include the redacted key digest in the formatted message.""" error = BackendError("Failed to store", operation="set", key="cache:user:123") error_msg = str(error) assert "Failed to store" in error_msg assert "operation=set" in error_msg - assert "key=cache:user:123" in error_msg - assert error.key == "cache:user:123" + assert f"key={redact_cache_key('cache:user:123')}" in error_msg + assert "cache:user:123" not in error_msg # raw key never in text (CWE-532) + assert error.key == "cache:user:123" # attribute stays raw for programmatic use - def test_error_with_long_key_truncation(self): - """BackendError should truncate long keys for readability.""" + def test_error_with_long_key_stays_fixed_length(self): + """Redaction replaces truncation: long keys become a fixed-length digest.""" long_key = "cache:" + "x" * 100 error = BackendError("Failed", operation="get", key=long_key) error_msg = str(error) - assert "..." in error_msg - assert len(error_msg) < len(long_key) + 50 # Truncated + assert long_key not in error_msg + assert redact_cache_key(long_key) in error_msg def test_error_serializability(self): """BackendError should contain only serializable types.""" @@ -276,7 +278,8 @@ def test_error_context_for_get_operation(self): assert error.operation == "get" assert error.key == "cache:user:123" assert "get" in str(error) - assert "cache:user:123" in str(error) + assert redact_cache_key("cache:user:123") in str(error) + assert "cache:user:123" not in str(error) def test_error_context_for_set_operation(self): """BackendError should capture context for set operations.""" diff --git a/tests/unit/test_error_path_key_redaction.py b/tests/unit/test_error_path_key_redaction.py new file mode 100644 index 0000000..ac4e8fb --- /dev/null +++ b/tests/unit/test_error_path_key_redaction.py @@ -0,0 +1,253 @@ +"""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.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 + +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]) + + +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) + + +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: + """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. + + 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 ``""``.""" + assert self._emit(caplog, "") == "" diff --git a/tests/unit/test_orchestrator_error_handling.py b/tests/unit/test_orchestrator_error_handling.py index bbd0ed1..142780c 100644 --- a/tests/unit/test_orchestrator_error_handling.py +++ b/tests/unit/test_orchestrator_error_handling.py @@ -4,9 +4,14 @@ actual behavior and contracts, not implementation details. """ +import logging + 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.hash_utils import redact_key_for_log class TestErrorHandlerOrchestration: @@ -271,3 +276,148 @@ 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) + + 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... + once = redact_key_for_log("") + assert once == redact_cache_key("") + # ...and redaction stays idempotent through a second pass. + assert redact_key_for_log(once) == once diff --git a/tests/unit/test_structured_logging.py b/tests/unit/test_structured_logging.py index 0aabe19..603d619 100644 --- a/tests/unit/test_structured_logging.py +++ b/tests/unit/test_structured_logging.py @@ -106,15 +106,19 @@ def test_get_context(self, logger): context = logger._get_context() assert context["trace_id"] == trace_id - def test_mask_sensitive_data(self, logger, logger_no_mask): - """Test sensitive data masking.""" - sensitive = "email@test.com" + def test_cache_key_always_redacted(self, logger, logger_no_mask): + """cache_operation redacts the key regardless of mask_sensitive (CWE-532, LAB-304).""" + from unittest.mock import patch as _patch - # With masking enabled - assert logger._mask_sensitive_data(sensitive) == "XXX@XXX.XXX" + from cachekit.hash_utils import redact_cache_key - # With masking disabled - assert logger_no_mask._mask_sensitive_data(sensitive) == sensitive + sensitive = "ns:tenant-42:func:app.f:args:email@test.com:v1" + for lg in (logger, logger_no_mask): + with _patch("cachekit.logging.logging.Logger.log") as mock_log: + lg.cache_operation("get", sensitive, hit=True) + extra = mock_log.call_args[1]["extra"]["structured"] + assert extra["cache_key"] == redact_cache_key(sensitive) + assert sensitive not in str(extra) @patch("cachekit.logging.logging.Logger.log") def test_cache_operation_logging(self, mock_log, logger): @@ -140,7 +144,9 @@ def test_cache_operation_logging(self, mock_log, logger): # Check structured context extra = call_args[1]["extra"]["structured"] assert extra["operation"] == "get" - assert extra["cache_key"] == "user:XXX@XXX.XXX" # Masked + from cachekit.hash_utils import redact_cache_key + + assert extra["cache_key"] == redact_cache_key("user:email@test.com") # Redacted digest (CWE-532) assert extra["namespace"] == "users" assert extra["serializer"] == "orjson" assert extra["duration_ms"] == 1.5 diff --git a/tests/unit/test_wrapper_lock_bare_key.py b/tests/unit/test_wrapper_lock_bare_key.py index 85c3447..d380d7f 100644 --- a/tests/unit/test_wrapper_lock_bare_key.py +++ b/tests/unit/test_wrapper_lock_bare_key.py @@ -25,6 +25,7 @@ from __future__ import annotations +import logging from collections.abc import AsyncIterator, Iterator from contextlib import asynccontextmanager from typing import Any, Optional @@ -33,6 +34,8 @@ import pytest from cachekit import cache +from cachekit.backends.errors import BackendError, BackendErrorType +from cachekit.hash_utils import redact_cache_key class _RecordingLockableBackend: @@ -196,14 +199,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 +243,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}" @@ -304,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" diff --git a/uv.lock b/uv.lock index 4f9df25..0281576 100644 --- a/uv.lock +++ b/uv.lock @@ -11,7 +11,7 @@ resolution-markers = [ constraints = [ { name = "fonttools", specifier = ">=4.60.2" }, { name = "h2", specifier = ">=4.4.1" }, - { name = "pip", specifier = ">=26.1.2" }, + { name = "pip", specifier = ">=26.2" }, { name = "urllib3", specifier = ">=2.7.0" }, { name = "werkzeug", specifier = ">=3.1.4" }, ] @@ -1283,11 +1283,11 @@ wheels = [ [[package]] name = "pip" -version = "26.1.2" +version = "26.2.1" source = { registry = "https://pypi.org/simple" } -sdist = { url = "https://files.pythonhosted.org/packages/01/91/47e7d486260f618783899587af63ccf7980fb60245c3e63dd4571c6b57ad/pip-26.1.2.tar.gz", hash = "sha256:f49cd134c61cf2fd75e0ce2676db03e4054504a5a4986d00f8299ae632dc4605", size = 1840799, upload-time = "2026-05-31T17:33:58.56Z" } +sdist = { url = "https://files.pythonhosted.org/packages/ae/15/4500e320e6b101ec3b719ae85b697d9940b6cda672bc555bd6016fc60c6f/pip-26.2.1.tar.gz", hash = "sha256:f6ad667e89a1fe78046c8f13232b247200f5258d7828f3f7883d660878e0813f", size = 1848877, upload-time = "2026-08-04T22:51:14.148Z" } wheels = [ - { url = "https://files.pythonhosted.org/packages/5d/95/6b5cb3461ea5673ba0995989746db58eb18b91b54dbf331e72f569540946/pip-26.1.2-py3-none-any.whl", hash = "sha256:382ff9f685ee3bc25864f820aa50505825f10f5458ffff07e30a6d96e5715cab", size = 1813144, upload-time = "2026-05-31T17:33:56.772Z" }, + { url = "https://files.pythonhosted.org/packages/f3/6e/1736e5b4ae2b778ef2f81c47d797de9f891d4d8acb047a24ca37a60294dd/pip-26.2.1-py3-none-any.whl", hash = "sha256:71138adf1f4ca900cdb7d289c21b7494329f2332b6d85f0e1c42108c0384ed3e", size = 1816632, upload-time = "2026-08-04T22:51:12.472Z" }, ] [[package]]