Repository navigation
fix(swr): log failed and skipped background refreshes at WARNING (LAB-7456) - #446
Conversation
…-7456) A background refresh that raised, or never ran because the call's arguments cannot be deep-copied or its thread or task could not start, logged one DEBUG line. The caller keeps getting the cached value until it expires and must never see the failure, so at default log levels nothing showed that the refresh was broken. For arguments that cannot be copied, refresh-ahead can never run for that call at all. These now log a WARNING naming the function, the redacted key digest and the exception type: at most one per function per minute for each kind (failed, skipped, could not start), carrying the count since the last one, with DEBUG in between. This covers L1-only refresh-ahead (async and sync) and backed stale_ttl revalidation. The throttle is the one "Key tracking failed" already used, extracted into a fork-safe _WarnThrottle that both now share. A refresh_ttl_on_get TTL extension failure still logs at DEBUG: it is optional, and the entry still expires on its own TTL.
|
Warning Review limit reachedYou've used all free OSS reviews for now. Wait for the free limit to reset to keep reviewing this public repository. Next included review available in 35 minutes. View limit detailsLimit details: You’ve used the included review currently available. Review configuration: ⚙️ Run configurationConfiguration used: Repository: cachekit-io/cachekit-py/.coderabbit.yaml Review profile: ASSERTIVE Plan: Advanced Run ID: 📒 Files selected for processing (8)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
Code Review Completed! 🔥The code review was successfully completed based on your current configurations. Kody Guide: Usage and ConfigurationInteracting with Kody
Providing Context (Files & MCPs)Add these hints in your PR description (or a comment) to unlock deeper checks:
Current Kody ConfigurationReview OptionsThe following review options are enabled or disabled:
|
Codecov Report❌ Patch coverage is
📢 Thoughts on this report? Let us know! |
A function created at runtime can carry caller data in __qualname__ or __name__. The refresh WARNING printed the qualname verbatim. The L1-only sync refresh thread was also named after __name__, and that WARNING is emitted from that thread, so a log format with %(threadName)s leaked the name too. The WARNING now names the function by the <redacted:...> digest of its module.qualname: the same correlation id the key uses, and computable with redact_cache_key() to match a line to a function. The L1-only refresh thread gets a static name, like the backed revalidation thread.
Code Review Completed! 🔥The code review was successfully completed based on your current configurations. Kody Guide: Usage and ConfigurationInteracting with Kody
Providing Context (Files & MCPs)Add these hints in your PR description (or a comment) to unlock deeper checks:
Current Kody ConfigurationReview OptionsThe following review options are enabled or disabled:
|
Closes LAB-7456
Problem
When a background refresh raised, or never ran, cachekit logged one DEBUG line. The caller keeps the cached value until it expires and must never see a revalidation failure, so at default log levels nothing showed that refresh-ahead was broken. When a call's arguments cannot be deep-copied (a lock, an open connection), the refresh is skipped on every hit: refresh-ahead can never run for that call, and nothing said so.
Change
Every failed or skipped background value refresh now logs a WARNING that carries the function's digest, the redacted key digest and the exception type (never its message). It fires at most once per function per minute for each kind of problem, and carries the count since the last one; occurrences in between stay at DEBUG. A sample line:
backend=None)L1-only SWR refresh failed(async and sync)L1-only SWR refresh skippedL1-only SWR refresh could not be started(sync thread; this path logged nothing before)stale_ttlrevalidationSWR revalidation failed(async and sync)SWR revalidation skippedSWR revalidation could not be scheduledEach kind has its own window, so frequent failures cannot hide a permanent skip on the same function.
The function appears as the
<redacted:…>digest of itsmodule.qualname, not in plain text, because a function created at runtime can carry caller data in__qualname__.redact_cache_key("app.sources.fetch")gives the digest to match a line to a function. For the same reason the L1-only sync refresh thread now has a static name (cachekit-swr-refresh, like the backedcachekit-swr-revalidate). Before, it was named after__name__, and that WARNING is emitted from that thread.The throttle is the one the
Key tracking failedWARNING already used, extracted into a fork-safe_WarnThrottlethat both now share. A forked child's first claim replaces a lock a dead parent thread may hold, and drops the parent's window and count (owner-PID check, as elsewhere in the wrapper).Unchanged: a
refresh_ttl_on_getTTL-extension failure still logs at DEBUG. That extension is optional, and the entry still expires on its own TTL. Refreshes skipped at slot capacity also stay quiet, because they are transient and a later hit retries them.Tests
__qualname__and__name__carry caller data keeps them out of both the message and the record'sthreadName, and the message carriesredact_cache_key("<module>.<qualname>").1 since the last warning) and four DEBUG lines; once the window elapses, the next WARNING says5 since the last warning.tests/unit(3823 passed),tests/critical, doctests,--markdown-docs,tests/docs, ruff and basedpyright all pass locally.tests/unit/test_log_redaction_architecture.pypasses.Docs
docs/configuration.md(L1-only mode andstale_ttlsections) anddocs/features/l1-invalidation.md(refresh failure and its troubleshooting entry) now describe the WARNING, how to match its function digest, and the deep-copy skip.SECURITY.mdrecords that refresh WARNINGs name the function by digest and that SWR threads have static names. Thestale_ttlsection no longer says a failed recompute is "silent".