diff --git a/.secrets.baseline b/.secrets.baseline index ddd47d12..4e41319f 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": 455 + "line_number": 448 } ], "src/cachekit/config/decorator.py": [ @@ -887,5 +887,5 @@ } ] }, - "generated_at": "2026-09-13T12:55:39Z" + "generated_at": "2026-09-14T08:02:35Z" } diff --git a/SECURITY.md b/SECURITY.md index 1fd3dac9..22dd6aee 100644 --- a/SECURITY.md +++ b/SECURITY.md @@ -187,6 +187,22 @@ 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 **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: + +```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) 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/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/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/errors.py b/src/cachekit/backends/errors.py index 80ff1a11..27e04112 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,12 @@ 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: 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}") return " | ".join(parts) 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..c64f1907 100644 --- a/src/cachekit/backends/memcached/error_handler.py +++ b/src/cachekit/backends/memcached/error_handler.py @@ -48,39 +48,49 @@ 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, 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 a6e4b070..c67fe336 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/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/backends/redis/provider.py b/src/cachekit/backends/redis/provider.py index 707b738e..8e562427 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__) @@ -400,7 +401,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 @@ -511,4 +512,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 0f47dfcd..0c35f5cf 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, redact_error_for_log from cachekit.interop import InteropError from cachekit.key_generator import CacheKeyGenerator from cachekit.serializers.base import ( @@ -77,16 +80,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 @@ -174,11 +167,11 @@ 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): {bounded_error(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)}: {bounded_error(error)}" + f"{tier.upper()} cache decrypt/integrity failure ({reason}) for {redact_cache_key(cache_key)}: {redact_error_for_log(error)}" ) return reason @@ -343,7 +336,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 @@ -753,7 +746,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)." ) @@ -940,7 +933,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, @@ -1169,7 +1162,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}: {bounded_error(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}: {bounded_error(e)}") from e def _deserialize_interop(self, data: str | bytes | memoryview, cache_key: str) -> Any: @@ -1214,7 +1207,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: {bounded_error(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: {bounded_error(e)}") from e @@ -1281,7 +1274,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 {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, @@ -1341,7 +1336,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: @@ -1351,7 +1348,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]: @@ -1407,7 +1406,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)}: {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]]]: @@ -1451,7 +1450,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( @@ -1492,7 +1491,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]: @@ -1539,7 +1538,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)}: {redact_error_for_log(e)}") return None def store_result( @@ -1614,7 +1613,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( @@ -1680,7 +1681,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): @@ -1751,9 +1754,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 {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 {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, @@ -1783,9 +1788,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 {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 {cache_key}: {e}") + get_logger().error(f"Unexpected error invalidating {redact_cache_key(cache_key)}: {redact_error_for_log(e)}") @runtime_checkable @@ -1954,12 +1961,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)}: {redact_error_for_log(e)}") def get(self, key: str, refresh_ttl: Optional[int] = None) -> Optional[bytes]: """Get value from cache using backend. @@ -1980,10 +1987,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)}: {redact_error_for_log(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)}: {redact_error_for_log(e)}") return None def get_buffer(self, key: str) -> Optional[BufferHandle]: @@ -1997,10 +2004,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)}: {redact_error_for_log(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)}: {redact_error_for_log(e)}") return None def get_with_freshness(self, key: str) -> Optional[tuple[bytes, bool, Optional[int]]]: @@ -2017,10 +2024,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]]]: @@ -2033,10 +2040,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( @@ -2066,10 +2073,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)}: {redact_error_for_log(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)}: {redact_error_for_log(e)}") return False def set_streaming(self, key: str, write_payload: Callable[[BinaryIO], None], ttl: Optional[int] = None) -> Optional[bool]: @@ -2088,12 +2095,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( @@ -2107,10 +2114,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: @@ -2125,10 +2132,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)}: {redact_error_for_log(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)}: {redact_error_for_log(e)}") return False async def _with_backpressure_and_timeout_async(self, operation, *args, **kwargs): @@ -2162,10 +2169,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)}: {redact_error_for_log(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)}: {redact_error_for_log(e)}") return None async def set_async( @@ -2189,10 +2196,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)}: {redact_error_for_log(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)}: {redact_error_for_log(e)}") return False async def delete_async(self, key: str) -> bool: @@ -2204,8 +2211,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)}: {redact_error_for_log(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)}: {redact_error_for_log(e)}") return False diff --git a/src/cachekit/decorators/orchestrator.py b/src/cachekit/decorators/orchestrator.py index 66abbc2b..e663e0ec 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_error_for_log, 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) @@ -448,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 '{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/decorators/wrapper.py b/src/cachekit/decorators/wrapper.py index 08b2209b..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, @@ -36,7 +38,7 @@ from ..l1_cache import DEFAULT_L1_TTL_SECONDS, get_l1_cache from ..object_cache import ObjectCache from ..reliability import CircuitBreakerConfig -from ..serializers.base import SerializationError, bounded_error +from ..serializers.base import SerializationError from ..serializers.encryption_wrapper import DecryptionAuthenticationError, KeyringConfigurationError # Config import removed - using direct DecoratorConfig integration @@ -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 {cache_key}: {bounded_error(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... @@ -1444,7 +1458,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", @@ -1457,7 +1471,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, @@ -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 {cache_key}: {bounded_error(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", 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,11 +1822,17 @@ 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 - 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 the operation handler: corrupt entries evict (#159), # stale hits skip L1, fresh backfill bounded by fresh_for (LAB-557). @@ -1828,7 +1850,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) @@ -1874,7 +1896,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, @@ -1905,12 +1927,16 @@ 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: {redact_error_for_log(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 @@ -1956,7 +1982,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, @@ -1985,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. @@ -2003,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", 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 @@ -2030,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", 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) @@ -2045,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. @@ -2061,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", 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 @@ -2089,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", 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/hash_utils.py b/src/cachekit/hash_utils.py index 235a5be1..be3dc274 100644 --- a/src/cachekit/hash_utils.py +++ b/src/cachekit/hash_utils.py @@ -1,13 +1,109 @@ -"""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 +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. + + 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). + + 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 redact_error_for_log(error: object) -> str: + """Render an exception for a log/error message without leaking cache keys (CWE-532). + + 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). + """ + from cachekit.backends.errors import BackendError + + if isinstance(error, BackendError): + error_type = getattr(error.error_type, "value", error.error_type) + return f"{type(error).__name__}({error_type})" + 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/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 5cb2ffba..0e6eec36 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_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 # SHORTEN the L1 lifetime relative to this default, never extend it. @@ -186,7 +188,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_key_for_log(key), + expiry, + ) return # Estimate size @@ -203,7 +209,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_key_for_log(key), size, self.max_memory_bytes, ) @@ -418,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 c5ccc8a2..ad4ea278 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_error_for_log, redact_key_for_log # Configure base logger logger = logging.getLogger(__name__) @@ -132,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.""" @@ -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,16 +412,10 @@ 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.""" - 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/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 404a5d41..924b5473 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 PAYLOAD_DECODE_ERRORS, SerializationError, SerializationFormat, SerializationMetadata, unpackb_bounded @@ -641,7 +642,9 @@ def deserialize(self, data: bytes | memoryview, metadata: Optional[Serialization # final error (a checksum mismatch also lands here — retrieve raises a plain # ValueError for both; distinguishing them is a Rust-extension follow-up). envelope_error = e - 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)}" + ) else: # The envelope verified (checksum matched), so its payload is exactly what was # stored; a payload that then fails to decode is corruption or a forged entry diff --git a/src/cachekit/serializers/base.py b/src/cachekit/serializers/base.py index 5c4feba4..27f2d974 100644 --- a/src/cachekit/serializers/base.py +++ b/src/cachekit/serializers/base.py @@ -372,13 +372,15 @@ def bounded_error(exc: BaseException) -> str: """``str(exc)`` clipped to :data:`ERROR_ECHO_MAX` and reduced to one terminal-safe line, for logging or re-wrapping a failure whose text is influenced by untrusted cache bytes. - Applied once at each trust-boundary wrap site (the read-path log/re-raise points in - ``cache_handler``/``decorators.wrapper``) rather than per field: the bound then holds for + Applied once at each trust-boundary re-raise site (the read-path ``SerializationError`` + wraps in ``cache_handler``) rather than per field: the bound then holds for every attacker-inflatable field — marker, column name, dtype — including ones a future field - would add. Over-length text is truncated with the true length appended so the log still says - "this was huge", then every line/terminal-control char is escaped (:data:`_LOG_UNSAFE_ESCAPES`) - so one poisoned read is always exactly one log line with no injected ANSI or newlines. Clipping - before escaping keeps output O(1) (escape expansion applies to at most ``ERROR_ECHO_MAX`` chars). + would add. Over-length text is truncated with the true length appended so the message still + says "this was huge", then every line/terminal-control char is escaped + (:data:`_LOG_UNSAFE_ESCAPES`) so one poisoned read is always exactly one line with no injected + ANSI or newlines. Clipping before escaping keeps output O(1) (escape expansion applies to at + most ``ERROR_ECHO_MAX`` chars). Log sinks do not use this: they render exceptions via + ``cachekit.hash_utils.redact_error_for_log``, which echoes no exception text at all. """ text = str(exc) if len(text) > ERROR_ECHO_MAX: 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/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/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_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 new file mode 100644 index 00000000..95507e55 --- /dev/null +++ b/tests/unit/test_error_path_key_redaction.py @@ -0,0 +1,629 @@ +"""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 ``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 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, + 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" + +# 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.""" + + 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 _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 backend; ``delete_error`` makes delete raise.""" + + 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 + + +class _LockingDictBackend(_DictBackend): + """Adds ``acquire_lock`` so the async wrapper takes the stampede-lock branch.""" + + @asynccontextmanager + async def acquire_lock(self, key: str, **_: Any): + yield True + + +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 _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 = _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 = _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}" + + +class TestStandardCacheHandlerRedaction: + """set/delete/TTL-refresh failures log the digest, never the raw key.""" + + @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)) + + 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", ERRORS, ids=ERROR_IDS) + 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) + + @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 + # 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: + """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.""" + handler = StandardCacheHandler(backend=_FailingTTLBackend(error)) + + 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", ERRORS, ids=ERROR_IDS) + 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", ERRORS, ids=ERROR_IDS) + 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, "") == "" + + +class TestRedactErrorForLog: + """Pin the two-branch contract of ``redact_error_for_log`` (CWE-532). + + 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_renders_type_and_classification(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, + ) + 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 TENANT_KEY not in rendered + assert rendered == "BackendError(unknown)" + + 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 + + +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) + + +class TestSerializationSinksRedaction: + """cache_handler.py serialization sinks: exception text renders as a type name only.""" + + 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) + + 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"irrelevant", TENANT_KEY) # the patched decoder raises before reading them + + _assert_redacted(caplog, TENANT_KEY) + _assert_error_text_redacted(caplog, error) + + +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)) + + @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: + 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 + 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 misses, function recomputes + + self._assert_l1_sink(caplog, cache_key, 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 + 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} + + self._assert_l1_sink(caplog, cache_key, 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}") + calls: list[str] = [] + + 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 (a miss: the store is empty), 2nd = post-lock double-check + raise error + + 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) + + @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") + def get_user(user_id: int) -> dict[str, int]: + return {"id": user_id} + + get_user(1) + 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) + + 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") + async def get_user(user_id: int) -> dict[str, int]: + return {"id": user_id} + + await get_user(1) + 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_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 new file mode 100644 index 00000000..01068f77 --- /dev/null +++ b/tests/unit/test_log_redaction_architecture.py @@ -0,0 +1,261 @@ +"""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. + +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(...)``), 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"]``) + 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" + +LOG_METHODS = frozenset({"debug", "info", "warning", "warn", "error", "critical", "exception", "log"}) +# 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"}) +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: + 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, 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(...) / getLogger(__name__).info(...), incl. aliased factories + name = _call_name(node) + return name in LOGGER_FACTORIES or (direct or {}).get(name) == "getLogger" + return False + + +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): # 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: + 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 _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(_unredacted(node.func.value, ident, redactors)) + if _call_name(node) not in redactors: + for child in _call_args(node): + 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 _unredacted(node.body, ident, redactors) + _unredacted(node.orelse, ident, redactors) + for child in ast.iter_child_nodes(node): + found.extend(_unredacted(child, ident, redactors)) + return found + + +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) + + +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)) + direct, aliases = _direct_log_names(tree) + for node in ast.walk(tree): + 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)] + 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, direct): + 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)) + out.extend(_violations_in(tree, str(path.relative_to(root.parents[1])))) + return out + + +def test_no_raw_key_or_exception_text_reaches_a_logger_call() -> None: + violations = _violations(SRC) + 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= + ("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 + ("_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 + ("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 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 + ("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: + flagged = bool(_violations_in(ast.parse(src), "")) + assert flagged is expected, f"{src!r}: expected flagged={expected}, got {flagged}" diff --git a/tests/unit/test_orchestrator_error_handling.py b/tests/unit/test_orchestrator_error_handling.py index bbd0ed14..a430603b 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,157 @@ 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_structured_log_cache_operation_without_key(self, caplog: pytest.LogCaptureFixture) -> None: + """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") + + 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. + + 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 0aabe192..5d46ee2e 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 @@ -165,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") diff --git a/tests/unit/test_wrapper_lock_bare_key.py b/tests/unit/test_wrapper_lock_bare_key.py index 68cf1349..86edb6a3 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"