From 5fc3ce148aa66729fa1d31e332909b4029fbc2f6 Mon Sep 17 00:00:00 2001 From: allen0099 Date: Sun, 27 Sep 2026 14:01:10 +0000 Subject: [PATCH] fix(cache): log a key digest, not the cache key, on backend failure The read/write failure warnings wrote the full cache key, which holds the raw query string, vary header values and custom key components. They now log method, path (%r-escaped) and key_ref, a 12-hex SHA-256 digest shared with the OAuth state logs via types.log_ref; the full key goes to DEBUG under the same key_ref. CacheManager.get()'s decode warning gets the same treatment. --- changelog.d/299.security.md | 11 +++ docs/HTTP_CACHING.md | 7 ++ fastapi_cachex/cache.py | 36 +++++++--- fastapi_cachex/manager.py | 5 +- fastapi_cachex/state/manager.py | 3 +- fastapi_cachex/types.py | 13 ++++ i18n/zh-TW/docs/HTTP_CACHING.md | 2 + tests/test_cache_backend_failure.py | 103 ++++++++++++++++++++++++++++ tests/test_cache_manager.py | 23 +++++++ 9 files changed, 192 insertions(+), 11 deletions(-) create mode 100644 changelog.d/299.security.md diff --git a/changelog.d/299.security.md b/changelog.d/299.security.md new file mode 100644 index 0000000..dbcfa30 --- /dev/null +++ b/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. diff --git a/docs/HTTP_CACHING.md b/docs/HTTP_CACHING.md index 0d9884e..8c807d3 100644 --- a/docs/HTTP_CACHING.md +++ b/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: diff --git a/fastapi_cachex/cache.py b/fastapi_cachex/cache.py index dae6c90..ab1f37a 100644 --- a/fastapi_cachex/cache.py +++ b/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) diff --git a/fastapi_cachex/manager.py b/fastapi_cachex/manager.py index ab69f56..24feba3 100644 --- a/fastapi_cachex/manager.py +++ b/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: diff --git a/fastapi_cachex/state/manager.py b/fastapi_cachex/state/manager.py index cd0a380..ebc360c 100644 --- a/fastapi_cachex/state/manager.py +++ b/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: diff --git a/fastapi_cachex/types.py b/fastapi_cachex/types.py index 9165312..542ecfb 100644 --- a/fastapi_cachex/types.py +++ b/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 diff --git a/i18n/zh-TW/docs/HTTP_CACHING.md b/i18n/zh-TW/docs/HTTP_CACHING.md index aa32cac..b4fef18 100644 --- a/i18n/zh-TW/docs/HTTP_CACHING.md +++ b/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 diff --git a/tests/test_cache_backend_failure.py b/tests/test_cache_backend_failure.py index 36a2219..f4fc56b 100644 --- a/tests/test_cache_backend_failure.py +++ b/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 diff --git a/tests/test_cache_manager.py b/tests/test_cache_manager.py index 9887100..4dac446 100644 --- a/tests/test_cache_manager.py +++ b/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 ------------------------------------------------------------------------