fix(cache): log a key digest, not the cache key, on backend failure

changelog.d/299.security.md

@@ -0,0 +1,11 @@
+**`@cache` backend-failure warnings no longer log the cache key.** The
+"Cache backend read failed" and "Cache backend write failed" warnings wrote
+the full key, which holds the raw query string (`?token=...`, `?code=...`,
+e-mail addresses), `vary` header values and any `build_cache_key` components,
+into application logs. They now log the method, the path (formatted with `%r`,
+so a control character in it is escaped) and `key_ref`, the first 12 hex
+digits of the key's SHA-256, the same digest format as the OAuth state logs;
+the full key is logged at `DEBUG` under the same `key_ref`.
+`CacheManager.get()`'s "Failed to decode cached value" warning likewise logs
+`key_ref` instead of the developer's key, which often embeds user IDs or
+e-mail addresses.

docs/HTTP_CACHING.md

@@ -134,6 +134,13 @@ served unstored. Either way a warning is logged on the `fastapi_cachex.cache`
 logger, and a backend outage cannot turn cached routes into 500s. The load
 goes to your handlers instead, so watch for those warnings.
 
+The warning names the request's method and path and a `key_ref`, a short
+SHA-256 digest of the cache key, but not the key itself: the key holds the
+raw query string, `vary` header values and any `build_cache_key` components,
+which may be tokens or personal data. The full key is logged at `DEBUG` with
+the same `key_ref`, so enabling `DEBUG` on `fastapi_cachex.cache` while
+troubleshooting ties a warning to its key.
+
 Pass `fail_open=False` to let the backend error propagate and fail the request
 instead:
 

fastapi_cachex/cache.py

@@ -43,6 +43,7 @@
 from .types import CacheEntry
 from .types import CacheKeyBuilder
 from .types import escape_key_component
+from .types import log_ref
 
 if TYPE_CHECKING:
     from fastapi.routing import APIRoute
@@ -109,6 +110,29 @@ def per_user_key(request: Request) -> str:
     return key
 
 
+def _log_backend_failure(
+    what: str, request: Request, cache_key: str, error: Exception
+) -> None:
+    """Log a failed backend call without writing the cache key at WARNING.
+
+    The key holds the raw query string, ``vary`` header values and any custom
+    key components, so the warning carries the method, the path and a digest
+    of the key; the full key goes to ``DEBUG`` under the same digest. The path
+    is formatted with ``%r`` because it is percent-decoded client input and
+    could otherwise put a CR/LF into the log.
+    """
+    key_ref = log_ref(cache_key)
+    logger.warning(
+        "Cache backend %s. method=%s path=%r key_ref=%s error=%r",
+        what,
+        request.method,
+        request.url.path,
+        key_ref,
+        error,
+    )
+    logger.debug("Cache backend %s; key_ref=%s key=%s", what, key_ref, cache_key)
+
+
 def _append_key_components(key: str, components: Sequence[str | int]) -> str:
     """Append each component to ``key``, escaped, after another separator."""
     parts = [key]
@@ -940,11 +964,7 @@ async def serve(*args: Any, **kwargs: Any) -> Response:
             except Exception as e:
                 if not fail_open:
                     raise
-                logger.warning(
-                    "Cache backend read failed; serving uncached. key=%s error=%r",
-                    cache_key,
-                    e,
-                )
+                _log_backend_failure("read failed; serving uncached", req, cache_key, e)
                 cached_data = None
 
             current_response: Response | None = None
@@ -1060,10 +1080,8 @@ async def serve(*args: Any, **kwargs: Any) -> Response:
                 except Exception as e:
                     if not fail_open:
                         raise
-                    logger.warning(
-                        "Cache backend write failed; response not stored. key=%s error=%r",
-                        cache_key,
-                        e,
+                    _log_backend_failure(
+                        "write failed; response not stored", req, cache_key, e
                     )
                 else:
                     logger.debug("Updated cache entry; key=%s ttl=%s", cache_key, ttl)

fastapi_cachex/manager.py

@@ -12,6 +12,7 @@
 from .backends.base import validate_ttl
 from .proxy import BackendProxy
 from .types import CacheEntry
+from .types import log_ref
 
 logger = logging.getLogger(__name__)
 
@@ -77,7 +78,9 @@ async def get(self, key: str, default: Any = None) -> Any:
         try:
             return json.loads(cached.content)
         except _DECODE_ERRORS:
-            logger.warning("Failed to decode cached value; key=%s", key)
+            # Keys often embed user IDs or e-mails: only a digest at WARNING.
+            logger.warning("Failed to decode cached value; key_ref=%s", log_ref(key))
+            logger.debug("Failed to decode cached value; key=%s", key)
             return default
 
     async def set(self, key: str, value: Any, ttl: int | None = None) -> None:

fastapi_cachex/state/manager.py

@@ -14,6 +14,7 @@
 from fastapi_cachex.backends.base import validate_ttl
 from fastapi_cachex.proxy import BackendProxy
 from fastapi_cachex.types import CacheEntry
+from fastapi_cachex.types import log_ref
 
 from .exceptions import InvalidStateError
 from .exceptions import StateDataError
@@ -36,7 +37,7 @@ def _state_ref(state: str) -> str:
     The state comes straight from the callback query string, so logging it raw
     would leak live tokens and let a caller forge log lines with CR/LF.
     """
-    return hashlib.sha256(state.encode("utf-8", "surrogatepass")).hexdigest()[:12]
+    return log_ref(state)
 
 
 def _binding_hash(binding: str) -> str:

fastapi_cachex/types.py

@@ -1,5 +1,6 @@
 """Type definitions and type aliases for FastAPI-CacheX."""
 
+import hashlib
 import re
 from collections.abc import Callable
 from dataclasses import dataclass
@@ -35,6 +36,18 @@ def unescape_key_component(value: str) -> str:
     return _KEY_UNESCAPE_RE.sub(lambda match: _KEY_UNESCAPES[match.group()], value)
 
 
+def log_ref(value: str) -> str:
+    """Return a short digest that identifies ``value`` in logs without revealing it.
+
+    Cache keys carry the raw query string, ``vary`` header values and custom
+    key components, and OAuth states come from the callback query string;
+    logging them at ``WARNING`` would leak tokens, e-mail addresses or user
+    IDs into application logs. The same value always gives the same digest,
+    so a warning can still be matched to the full value logged at ``DEBUG``.
+    """
+    return hashlib.sha256(value.encode("utf-8", "surrogatepass")).hexdigest()[:12]
+
+
 # Status replayed for entries stored before ``CacheEntry`` carried a status code.
 DEFAULT_STATUS_CODE = 200
 

i18n/zh-TW/docs/HTTP_CACHING.md

@@ -86,6 +86,8 @@ handler 回傳一般資料而非 `Response` 時，得到的處理與沒有 `@cac
 
 `@cache` 採取 fail open。讀取時後端拋出錯誤（例如 Redis 或 Memcached 無法連線），該請求會被當成快取未命中，照常執行 handler。儲存回應時拋出錯誤（例如回應超過 Memcached 的項目大小上限，預設為 1 MB），回應會照常送出，只是不會被儲存。兩種情況都會在 `fastapi_cachex.cache` logger 記錄一則警告，因此後端中斷不會讓有快取的路由變成 500；負載會轉到你的 handler 上，請留意這些警告。
 
+警告會列出請求的 method、路徑與 `key_ref`（快取鍵的簡短 SHA-256 摘要），但不會列出快取鍵本身：快取鍵含有原始查詢字串、`vary` 標頭值以及任何 `build_cache_key` 元件，可能是 token 或個人資料。完整的快取鍵會以 `DEBUG` 等級連同相同的 `key_ref` 記錄，因此排查問題時在 `fastapi_cachex.cache` 開啟 `DEBUG`，即可將警告對應到其快取鍵。
+
 傳入 `fail_open=False` 則會讓後端錯誤直接往外拋出，使該請求失敗：
 
 ```python

tests/test_cache_backend_failure.py

@@ -4,12 +4,15 @@
 uncached instead of turning every cached route into a 500.
 """
 
+import hashlib
 import logging
 
 import pytest
 from fastapi import FastAPI
 from fastapi.responses import PlainTextResponse
 from fastapi.testclient import TestClient
+from starlette.types import Message
+from starlette.types import Scope
 
 from fastapi_cachex import BackendProxy
 from fastapi_cachex import cache
@@ -131,3 +134,103 @@ async def large() -> PlainTextResponse:
 
     assert response.status_code == 200
     assert response.text == body
+
+
+@pytest.mark.parametrize(
+    ("fail_get", "fail_set", "message"),
+    [(True, False, "read failed"), (False, True, "write failed")],
+    ids=["get", "set"],
+)
+def test_failure_warning_does_not_log_the_cache_key(
+    caplog: pytest.LogCaptureFixture, *, fail_get: bool, fail_set: bool, message: str
+) -> None:
+    """The key holds the query string and vary values: only a digest at WARNING (#299)."""
+    BackendProxy.set(FailingBackend(fail_get=fail_get, fail_set=fail_set))
+    app = FastAPI()
+
+    @app.get("/callback")
+    @cache(ttl=60, vary=["X-Tenant"])
+    async def callback() -> dict[str, str]:
+        return {"ok": "yes"}
+
+    with caplog.at_level(logging.DEBUG, logger="fastapi_cachex.cache"):
+        response = TestClient(app).get(
+            "/callback",
+            params={"token": "s3cr3t-token", "email": "alice@example.com"},
+            headers={"X-Tenant": "tenant-secret"},
+        )
+
+    assert response.status_code == 200
+    [warning] = [
+        r.getMessage()
+        for r in caplog.records
+        if r.levelno == logging.WARNING and message in r.getMessage()
+    ]
+    for secret in ("s3cr3t-token", "alice", "tenant-secret", "|||"):
+        assert secret not in warning
+    assert "method=GET" in warning
+    assert "path='/callback'" in warning
+    assert "error=ConnectionError('backend unreachable')" in warning
+
+    # The full key is at DEBUG only, tagged with the same digest.
+    [debug] = [
+        r.getMessage()
+        for r in caplog.records
+        if r.levelno == logging.DEBUG and message in r.getMessage()
+    ]
+    key = debug.split(" key=", 1)[1]
+    assert "token=s3cr3t-token" in key
+    assert "tenant-secret" in key
+    digest = hashlib.sha256(key.encode()).hexdigest()[:12]
+    assert f"key_ref={digest}" in warning
+    assert f"key_ref={digest}" in debug
+
+
+async def test_failure_warning_escapes_control_characters_in_the_path(
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    """Control characters in the decoded path are escaped, not written raw."""
+    BackendProxy.set(FailingBackend(fail_get=True, fail_set=False))
+    app = FastAPI()
+
+    @app.get("/{name}")
+    @cache(ttl=60)
+    async def item(name: str) -> dict[str, str]:
+        return {"name": name}
+
+    # ASGI servers percent-decode the path, so ``%0D%0A`` arrives as a real
+    # CR/LF; test clients normalise it away, so drive the app directly.
+    # ``request.url`` already drops CR/LF/tab (urllib), but an ANSI escape or
+    # a line separator gets through and must show up escaped.
+    scope: Scope = {
+        "type": "http",
+        "asgi": {"version": "3.0"},
+        "http_version": "1.1",
+        "method": "GET",
+        "scheme": "http",
+        "path": "/a\r\n\x1b[2K\u2028FAKE entry",
+        "raw_path": b"/a%0D%0A%1B%5B2K%E2%80%A8FAKE%20entry",
+        "root_path": "",
+        "query_string": b"",
+        "headers": [(b"host", b"testserver")],
+        "client": ("127.0.0.1", 1),
+        "server": ("testserver", 80),
+    }
+    sent: list[Message] = []
+
+    async def receive() -> Message:
+        return {"type": "http.request", "body": b"", "more_body": False}
+
+    async def send(message: Message) -> None:
+        sent.append(message)
+
+    with caplog.at_level(logging.WARNING, logger="fastapi_cachex.cache"):
+        await app(scope, receive, send)
+
+    assert sent[0]["status"] == 200
+    [warning] = [
+        r.getMessage() for r in caplog.records if "read failed" in r.getMessage()
+    ]
+    for raw in ("\n", "\r", "\x1b", "\u2028"):
+        assert raw not in warning
+    assert "\\x1b[2K\\u2028FAKE entry'" in warning

tests/test_cache_manager.py

@@ -1,6 +1,7 @@
 """Tests for CacheManager application-level caching."""
 
 import asyncio
+import logging
 import time
 from collections.abc import AsyncGenerator
 from functools import partial
@@ -17,6 +18,7 @@
 from fastapi_cachex.manager_proxy import CacheManagerProxy
 from fastapi_cachex.proxy import BackendProxy
 from fastapi_cachex.types import CacheEntry
+from fastapi_cachex.types import log_ref
 from tests.conftest import Clock
 from tests.live_servers import REDIS_HOST
 from tests.live_servers import REDIS_PORT
@@ -296,6 +298,27 @@ def factory() -> object:
     assert not await cache_manager.has("key")
 
 
+async def test_decode_failure_warning_logs_a_digest_not_the_key(
+    memory_backend: MemoryBackend, caplog: pytest.LogCaptureFixture
+) -> None:
+    """Keys often embed e-mails or user IDs: the full key is logged at DEBUG only."""
+    manager = CacheManager(backend=memory_backend)
+    key = "user:alice@example.com"
+    entry = CacheEntry(fingerprint="x", content=b"not valid json")
+    await memory_backend.set(f"{manager.key_prefix}{key}", entry, ttl=60)
+
+    with caplog.at_level(logging.DEBUG, logger="fastapi_cachex.manager"):
+        assert await manager.get(key) is None
+
+    [warning] = [r.getMessage() for r in caplog.records if r.levelno == logging.WARNING]
+    assert "alice" not in warning
+    assert f"key_ref={log_ref(key)}" in warning
+    assert any(
+        r.levelno == logging.DEBUG and f"key={key}" in r.getMessage()
+        for r in caplog.records
+    )
+
+
 # --- add ------------------------------------------------------------------------