fix(swr): log failed and skipped background refreshes at WARNING (LAB-7456)

SECURITY.md

@@ -205,7 +205,7 @@ See [SSRF Protection](docs/features/ssrf-protection.md) for full details, includ
 
 ### Cache Key Redaction in Logs (CWE-532)
 
-Cache keys can embed caller-supplied tenant/user identifiers, so **the SDK's own loggers** (`cachekit.*`) never emit them verbatim ([CWE-532][cwe-532]). Every cachekit log path — decorator error handling (structured and backwards-compat), cache-operation logs, and SWR/TTL-refresh debug logs — replaces the key with a fixed-length blake2b digest (`<redacted:…>`), 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. Both structured cache-operation sinks (`FeatureOrchestrator.log_cache_operation`, `StructuredLogger.cache_operation`) also sanitise an exception passed as `error=` themselves — pass the exception object, never `str(e)`, which is emitted as-is. `BackendError` redacts the key in its formatted text (`str(e)` carries `key=<redacted:…>`), while the `.key` attribute keeps the raw caller-supplied key for programmatic use — never log `e.key` (see below for the same caution applied to `e`'s traceback). Its free-form `message` is caller-supplied and third-party exception text (a redis `ResponseError` naming the key, a pymemcache illegal-input error echoing it) has unknown provenance — so **no cachekit log line renders `str(e)`**. Every logging call that mentions an exception goes through `redact_error_for_log`, which emits only the exception type plus, for `BackendError`, its `BackendErrorType` classification; the full exception stays on the object (`original_exception`, `.message`) for programmatic access. Operators lose the provider's message text in the log line and keep it on the exception. An architecture test (`tests/unit/test_log_redaction_architecture.py`) walks every logging call in the package — `logger.*()`, `get_logger().*()`, `getattr(logger, level)()` — and fails CI if a key-shaped value reaches one unredacted in the message, `%s` arguments, or `extra=`; if an exception — any name bound by `except ... as`, a conventional name (`e`, `exc`, `err`, `error`, `*_err`), or an attribute of one — reaches one outside `redact_error_for_log`; or if a call emits a traceback (`logger.exception`, `exc_info=`). The guarantee does not depend on the next contributor remembering it. It is flow-insensitive: build log lines inline, not via a pre-formatted variable, and bind exceptions with `except ... as` or a conventional name (an `Exception`-typed parameter called `failure` is invisible to it), or the guard cannot see them.
+Cache keys can embed caller-supplied tenant/user identifiers, so **the SDK's own loggers** (`cachekit.*`) never emit them verbatim ([CWE-532][cwe-532]). Every cachekit log path — decorator error handling (structured and backwards-compat), cache-operation logs, and SWR/TTL-refresh logs — replaces the key with a fixed-length blake2b digest (`<redacted:…>`), keeping log lines correlatable without leaking the key. The SWR refresh WARNINGs name the decorated function by the same digest of its `module.qualname`, because a dynamically created function's `__qualname__` can carry caller data, and SWR background threads have static names, so a `%(threadName)s` log format leaks no function name either. 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. Both structured cache-operation sinks (`FeatureOrchestrator.log_cache_operation`, `StructuredLogger.cache_operation`) also sanitise an exception passed as `error=` themselves — pass the exception object, never `str(e)`, which is emitted as-is. `BackendError` redacts the key in its formatted text (`str(e)` carries `key=<redacted:…>`), while the `.key` attribute keeps the raw caller-supplied key for programmatic use — never log `e.key` (see below for the same caution applied to `e`'s traceback). 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 — application-rendered tracebacks are not covered.** `BackendError.original_exception` (and the `from exc` chain that sets `__cause__`) deliberately keeps the original provider exception for programmatic access, and that exception's own text can embed the raw key — a pymemcache `MemcacheIllegalInputError` echoing an oversized key, a redis `ResponseError` naming it, or an httpx error string carrying the CachekitIO request path. cachekit itself never renders that text: no `cachekit.*` log line calls `logger.exception()` or passes `exc_info=`, so the SDK never prints a traceback, which is the same architecture test enforcing the guarantee above. That guarantee scopes to cachekit's own logging *calls*, not to the `JsonFormatter` cachekit ships (`cachekit.logging.JsonFormatter`): that formatter renders whatever `record.exc_info` a caller supplies via `traceback.format_exception`, so wiring it into your application's logging and emitting a `BackendError` with `exc_info` set renders the chained cause and its raw key exactly like the application paths below. The remaining path is your own logging code: if application code catches a `BackendError` and calls `logger.exception(e)`, sets `exc_info=True`, calls `traceback.format_exc()`, or hands the exception to an APM/error-tracking SDK, the rendered traceback includes the chained cause and its raw key. Log `redact_error_for_log(e)` (`from cachekit.hash_utils import redact_error_for_log`) or `type(e).__name__` instead of the traceback for a cachekit exception. If you must hand the exception itself to an error/APM tracker, pass it a freshly constructed exception carrying only `redact_error_for_log(e)`, handed over explicitly (`capture_exception(RuntimeError(redact_error_for_log(e)))`) rather than raised inside the `except` block: raising it there sets its `__context__` to `e` and re-links the whole chain, and `raise … from None` does not undo that — it only sets `__suppress_context__`, which hides the chain from `traceback` but not from an SDK that walks exception attributes. Failing that, clear **all three** references to the provider exception on `e` first — `__cause__`, `__context__`, and `BackendError.original_exception` — **and `e.__traceback__` and `e.key` with them**. The backends raise the classified `BackendError` from inside the `except` block that caught the provider exception, so Python sets `__context__` as well as `__cause__`; clearing `__cause__` alone hides the provider text from `traceback` but leaves it reachable to an SDK that walks exception attributes, and `original_exception` is a third reference. `__traceback__` leaks by a different route than the other three: they carry the provider exception's *text*, whereas the traceback carries the backend *frame* that raised — and that frame's locals still hold the raw key (`MemcachedBackend.get` raises `classify_memcached_error(exc, operation="get", key=key) from exc`), so a tracker that captures frame locals reads the key off the frame even with all three references cleared. `e.key` is the raw caller-supplied key itself (only `str(e)` is redacted), so a tracker that serialises exception attributes reads it directly. On Python 3.11+, clearing `e.__traceback__` also clears what `sys.exc_info()` reports for that exception. On Python 3.10 it does not: `sys.exc_info()` keeps its own reference to the original traceback until the `except` block exits, so a no-argument `capture_exception()` inside the block still reads the backend frame — always pass the exception to the tracker explicitly.
 

docs/configuration.md

@@ -188,7 +188,7 @@ Rules and behavior:
 - Requires a positive `ttl`; `ttl + stale_ttl` is capped at 2,592,000 s (30 days). Violations raise `ConfigurationError` at decoration time.
 - **CachekitIO only, known at decoration time** — `@cache.io` or an explicit `backend=CachekitIOBackend()`. Other backends have no read-side freshness signal and raise `ConfigurationError` if `stale_ttl` is set; so does a CachekitIO backend resolved lazily from `CACHEKIT_API_KEY` under another preset (the remaining-freshness bound below still applies to its reads).
 - Concurrent stale hits trigger at most one revalidation: per-process dedup plus (async functions) a non-blocking distributed lease on the backend's lock. Contested = serve stale, don't wait.
-- A failed background recompute is silent: the entry keeps serving stale until its hard eviction bound, after which the next call takes the ordinary synchronous miss path.
+- A failed background recompute never reaches the caller: the entry keeps serving stale until its hard eviction bound, after which the next call takes the ordinary synchronous miss path. It logs a WARNING `SWR revalidation failed`, as does a revalidation skipped because the call's arguments cannot be deep-copied (`SWR revalidation skipped`) or one that could not be scheduled. It names the function by the same digest as the L1-only refresh WARNING. Each fires at most once a minute per function and carries the count since the last one; the occurrences in between log at DEBUG.
 - The background recompute runs with a **snapshot of the caller's `contextvars`** (contextvar-based tenant extraction works), but outside the request otherwise — don't rely on other request-scoped resources (open sessions, connections) inside functions that enable SWR.
 - Stale values are never written to the L1 in-memory cache, and stale reads still count as cache **hits** for metered-misses billing.
 - On the CachekitIO backend, every read (SWR-configured or not) also carries the server's remaining freshness (`X-CacheKit-Fresh-For`, [protocol spec](https://github.com/cachekit-io/protocol/blob/main/spec/saas-api.md#remaining-freshness)): an L2 hit backfilled into L1 lives at most `min(ttl, remaining)` locally (with `ttl=None`, L1's own 300-second default lifetime, capped by `remaining`), so a value read near the end of its server-side freshness window is never served fresh from L1 past the server's bound. Pre-signal servers omit the header and behavior is unchanged.
@@ -288,7 +288,15 @@ honored as follows:
   expiry rather than truly indefinitely, and can still be evicted earlier under
   byte pressure.
 - **Refresh failures are non-fatal**: the stale value keeps being served until hard
-  expiry, and the next qualifying hit retries the refresh.
+  expiry, and the next qualifying hit retries the refresh. The refresh runs on a deep copy
+  of the call's arguments; when they cannot be copied (a lock, an open connection), it is
+  skipped, so that call is only ever recomputed in the foreground after expiry.
+- **Failed and skipped refreshes log a WARNING** (`L1-only SWR refresh failed`, `… skipped`,
+  `… could not be started`) with the redacted function, the redacted key and the exception
+  type. The function appears as the `<redacted:…>` digest of its `module.qualname`;
+  `cachekit.hash_utils.redact_cache_key("app.sources.fetch")` gives the digest to match.
+  Each fires at most once a minute per function and carries the count since the last one;
+  the occurrences in between log at DEBUG.
 
 ```python notest
 import asyncio

docs/features/l1-invalidation.md

@@ -46,7 +46,7 @@ cached_at = 1850   # Freshness clock restarts
 expires_at = 5450  # Hard expiry restarts too (1850 + 3600)
 ```
 
-If the background refresh fails (your function raises), the entry is left as-is: the cached value keeps being served until its original hard expiry, and the next qualifying hit retries the refresh.
+If the background refresh fails (your function raises), the entry is left as-is: the cached value keeps being served until its original hard expiry, the next qualifying hit retries the refresh, and cachekit logs a WARNING `L1-only SWR refresh failed` (see [SWR refresh failing](#problem-swr-refresh-failing)).
 
 ---
 
@@ -385,9 +385,11 @@ For typical workloads (1000s of keys), overhead is <1MB.
 
 ### Problem: SWR refresh failing
 
-**Cause:** Your function raised during the background re-run (L1-only mode)
+**Cause:** Your function raised during the background re-run (L1-only mode), or the refresh never ran: the call's arguments cannot be deep-copied (a lock, an open connection), or its thread could not start.
 
-**Behavior:** The cached value continues to be served until its hard expiry, and the next qualifying hit retries the refresh. This is by design - a failed refresh never evicts a servable value.
+**Behavior:** The cached value continues to be served until its hard expiry, and the next qualifying hit retries the refresh. This is by design - a failed refresh never evicts a servable value. Arguments that cannot be copied fail the same way on every retry, so for that call refresh-ahead never runs and the value is recomputed in the foreground after expiry.
+
+**Diagnosis:** cachekit logs a WARNING `L1-only SWR refresh failed`, `L1-only SWR refresh skipped` or `L1-only SWR refresh could not be started`, with the function and the key as `<redacted:…>` digests and the exception type (never its message). The function's digest is that of its `module.qualname`: `cachekit.hash_utils.redact_cache_key("app.sources.fetch")` gives the value to match. Each fires at most once a minute per function and carries the count since the last one; the occurrences in between log at DEBUG.
 
 ### Problem: High memory usage despite max_size_mb limit