mirror of
https://github.com/ipnet-mesh/meshcore-hub.git
synced 2026-07-26 19:42:47 +02:00
log: cache invalidation observability for production diagnosis
After PR #311's invalidation wiring and HTTP policy fix, a user reported the routes list still showed stale data for ~30s after a PUT. The HAR they sent actually showed the fix working (x-cache: MISS after PUT, fresh data returned) but had been captured with DevTools' 'Disable cache' enabled — so it didn't represent normal browsing. We had four competing hypotheses and no way to pick between them. Add structured INFO logging at the two points that matter: * meshcore_hub.api.cache_invalidation._drop now emits 'Cache invalidate start: prefix=... backend=...' and 'Cache invalidate ok: prefix=...'. The backend= field distinguishes RedisCacheBackend from NullCache in one glance, catching 'REDIS_ENABLED is actually false' cases. * meshcore_hub.common.redis.RedisCacheBackend.delete now emits 'Redis cache delete: prefix=... full_prefix=... keys_deleted=N scan_iterations=N'. keys_deleted=0 after a mutation that should have invalidated entries is the smoking gun for a cache-key mismatch between the store path (key_builder) and the delete path (prefix glob). * NullCache.delete emits a DEBUG line for the same reason. The error paths are also enriched with full_prefix for greppability. No behavioral changes — invalidation still swallows errors so cache outages never break a write. After deploy, a single route-edit repro will produce log output whose shape (start/ok/warning/missing, keys_deleted count) unambiguously identifies which of the four hypotheses is correct, so we can write a targeted fix instead of guessing.
This commit is contained in:
Louis King
@@ -47,14 +47,35 @@ def _cache(request: Request) -> Optional[CacheBackend]:
|
||||
|
||||
|
||||
def _drop(request: Request, prefix: str) -> None:
|
||||
"""Best-effort ``delete(prefix)``; never raises."""
|
||||
"""Best-effort ``delete(prefix)``; never raises.
|
||||
|
||||
Emits structured log lines so production traces can confirm a mutation
|
||||
handler actually fired invalidation and see how many Redis keys were
|
||||
deleted. The ``backend=`` field distinguishes ``RedisCacheBackend``
|
||||
(real Redis) from ``NullCache`` (Redis disabled) in one glance — useful
|
||||
when ``REDIS_ENABLED`` is misconfigured.
|
||||
"""
|
||||
cache = _cache(request)
|
||||
if cache is None:
|
||||
logger.debug(
|
||||
"Cache invalidate skipped (no backend on app.state): prefix=%s",
|
||||
prefix,
|
||||
)
|
||||
return
|
||||
logger.info(
|
||||
"Cache invalidate start: prefix=%s backend=%s",
|
||||
prefix,
|
||||
type(cache).__name__,
|
||||
)
|
||||
try:
|
||||
cache.delete(prefix)
|
||||
logger.info("Cache invalidate ok: prefix=%s", prefix)
|
||||
except Exception as e:
|
||||
logger.warning("Cache invalidation error for prefix %s: %s", prefix, e)
|
||||
logger.warning(
|
||||
"Cache invalidate error: prefix=%s error=%s",
|
||||
prefix,
|
||||
e,
|
||||
)
|
||||
|
||||
|
||||
def invalidate_channels(request: Request) -> None:
|
||||
|
||||
@@ -32,7 +32,9 @@ class NullCache(CacheBackend):
|
||||
pass
|
||||
|
||||
def delete(self, prefix: str) -> None:
|
||||
pass
|
||||
# Logged so production traces can distinguish "Redis disabled" from
|
||||
# "Redis enabled but matched no keys" when diagnosing invalidation.
|
||||
logger.debug("NullCache delete: prefix=%s", prefix)
|
||||
|
||||
def ping(self) -> bool:
|
||||
return False
|
||||
@@ -84,19 +86,40 @@ class RedisCacheBackend(CacheBackend):
|
||||
logger.warning("Redis SET error for %s: %s", key, e)
|
||||
|
||||
def delete(self, prefix: str) -> None:
|
||||
# Diagnostic logging: emit one INFO line per call with the prefix,
|
||||
# full prefix (incl. key_prefix), total keys deleted, and SCAN
|
||||
# iterations. ``keys_deleted=0`` after a mutation that should have
|
||||
# invalidated entries is the smoking gun for a cache-key mismatch
|
||||
# between the store path (key_builder) and the delete path (prefix).
|
||||
full_prefix = self._full_key(prefix)
|
||||
total_deleted = 0
|
||||
iterations = 0
|
||||
try:
|
||||
full_prefix = self._full_key(prefix)
|
||||
cursor = 0
|
||||
while True:
|
||||
cursor, keys = self._client.scan(
|
||||
cursor, match=f"{full_prefix}*", count=100
|
||||
)
|
||||
iterations += 1
|
||||
if keys:
|
||||
self._client.delete(*keys)
|
||||
total_deleted += len(keys)
|
||||
if cursor == 0:
|
||||
break
|
||||
logger.info(
|
||||
"Redis cache delete: prefix=%s full_prefix=%s keys_deleted=%d scan_iterations=%d",
|
||||
prefix,
|
||||
full_prefix,
|
||||
total_deleted,
|
||||
iterations,
|
||||
)
|
||||
except Exception as e:
|
||||
logger.warning("Redis DELETE error for prefix %s: %s", prefix, e)
|
||||
logger.warning(
|
||||
"Redis DELETE error: prefix=%s full_prefix=%s error=%s",
|
||||
prefix,
|
||||
full_prefix,
|
||||
e,
|
||||
)
|
||||
|
||||
def ping(self) -> bool:
|
||||
try:
|
||||
|
||||
@@ -1778,3 +1778,177 @@ class TestMutationVisibilityThroughHttpCache:
|
||||
resp = client_no_auth.get("/api/v1/dashboard/activity")
|
||||
assert resp.status_code == 200
|
||||
assert resp.headers["cache-control"] == "private, no-cache"
|
||||
|
||||
|
||||
class TestInvalidationLogging:
|
||||
"""Diagnostic logging for cache invalidation.
|
||||
|
||||
These tests pin down the log lines that operators grep for when
|
||||
diagnosing whether mutation handlers actually fire invalidation and
|
||||
whether Redis SCAN matches stored keys. The shape of the log output
|
||||
is part of the contract — changing it breaks log dashboards and the
|
||||
diagnostic runbook.
|
||||
"""
|
||||
|
||||
def test_drop_logs_start_and_ok_on_success(self, caplog):
|
||||
from meshcore_hub.api.cache_invalidation import invalidate_routes
|
||||
|
||||
cache = MagicMock()
|
||||
cache.__class__.__name__ = "RedisCacheBackend"
|
||||
request = _make_request_with_cache(cache)
|
||||
|
||||
with caplog.at_level("INFO", logger="meshcore_hub.api.cache_invalidation"):
|
||||
invalidate_routes(request)
|
||||
|
||||
messages = [r.message for r in caplog.records]
|
||||
assert any(
|
||||
"Cache invalidate start" in m
|
||||
and "prefix=/api/v1/routes" in m
|
||||
and "backend=RedisCacheBackend" in m
|
||||
for m in messages
|
||||
), f"start line missing or malformed: {messages}"
|
||||
assert any(
|
||||
"Cache invalidate ok" in m and "prefix=/api/v1/routes" in m
|
||||
for m in messages
|
||||
), f"ok line missing or malformed: {messages}"
|
||||
|
||||
def test_drop_logs_warning_on_backend_error(self, caplog):
|
||||
from meshcore_hub.api.cache_invalidation import invalidate_channels
|
||||
|
||||
cache = MagicMock()
|
||||
cache.delete.side_effect = Exception("redis down")
|
||||
request = _make_request_with_cache(cache)
|
||||
|
||||
with caplog.at_level("WARNING", logger="meshcore_hub.api.cache_invalidation"):
|
||||
invalidate_channels(request)
|
||||
|
||||
# Must not raise; warning must carry prefix + error text.
|
||||
assert any(
|
||||
"Cache invalidate error" in r.message
|
||||
and "prefix=/api/v1/channels" in r.message
|
||||
and "redis down" in r.message
|
||||
for r in caplog.records
|
||||
), [r.message for r in caplog.records]
|
||||
|
||||
def test_drop_logs_skipped_when_no_backend(self, caplog):
|
||||
from meshcore_hub.api.cache_invalidation import invalidate_nodes
|
||||
|
||||
# No redis_cache attribute on app.state.
|
||||
request = _make_request_with_cache(cache=None)
|
||||
|
||||
with caplog.at_level("DEBUG", logger="meshcore_hub.api.cache_invalidation"):
|
||||
invalidate_nodes(request)
|
||||
|
||||
assert any(
|
||||
"Cache invalidate skipped" in r.message and "prefix=nodes" in r.message
|
||||
for r in caplog.records
|
||||
), [r.message for r in caplog.records]
|
||||
|
||||
def test_drop_logs_backend_name_distinguishes_nullcache(self, caplog):
|
||||
"""If NullCache is wired in, the start log must say so.
|
||||
|
||||
Catches the 'REDIS_ENABLED is actually false in production' case
|
||||
in one log line.
|
||||
"""
|
||||
from meshcore_hub.api.cache_invalidation import invalidate_routes
|
||||
|
||||
null_cache = NullCache()
|
||||
request = _make_request_with_cache(null_cache)
|
||||
|
||||
with caplog.at_level("INFO", logger="meshcore_hub.api.cache_invalidation"):
|
||||
invalidate_routes(request)
|
||||
|
||||
messages = [r.message for r in caplog.records]
|
||||
assert any(
|
||||
"backend=NullCache" in m and "prefix=/api/v1/routes" in m for m in messages
|
||||
), f"expected backend=NullCache in start log, got: {messages}"
|
||||
|
||||
def test_redis_delete_logs_keys_deleted_count(self, caplog):
|
||||
with patch("redis.Redis") as mock_redis_cls:
|
||||
mock_client = MagicMock()
|
||||
mock_redis_cls.return_value = mock_client
|
||||
mock_client.scan.return_value = (0, [b"hub:nodes:1", b"hub:nodes:2"])
|
||||
|
||||
backend = RedisCacheBackend(key_prefix="hub")
|
||||
with caplog.at_level("INFO", logger="meshcore_hub.common.redis"):
|
||||
backend.delete("nodes")
|
||||
|
||||
# One INFO line with prefix, full_prefix, and keys_deleted=2.
|
||||
info_records = [r for r in caplog.records if r.levelname == "INFO"]
|
||||
assert len(info_records) == 1, [r.message for r in caplog.records]
|
||||
msg = info_records[0].message
|
||||
assert "Redis cache delete" in msg
|
||||
assert "prefix=nodes" in msg
|
||||
assert "full_prefix=hub:nodes" in msg
|
||||
assert "keys_deleted=2" in msg
|
||||
assert "scan_iterations=1" in msg
|
||||
|
||||
def test_redis_delete_logs_zero_keys_on_empty_scan(self, caplog):
|
||||
"""The smoking-gun signal for the production bug.
|
||||
|
||||
If invalidation fires but SCAN matches nothing, ``keys_deleted=0``
|
||||
appears in the log. That points directly at a cache-key mismatch
|
||||
between the store path (key_builder) and the delete path (prefix).
|
||||
"""
|
||||
with patch("redis.Redis") as mock_redis_cls:
|
||||
mock_client = MagicMock()
|
||||
mock_redis_cls.return_value = mock_client
|
||||
mock_client.scan.return_value = (0, [])
|
||||
|
||||
backend = RedisCacheBackend(key_prefix="hub")
|
||||
with caplog.at_level("INFO", logger="meshcore_hub.common.redis"):
|
||||
backend.delete("/api/v1/routes")
|
||||
|
||||
info_records = [r for r in caplog.records if r.levelname == "INFO"]
|
||||
assert len(info_records) == 1
|
||||
msg = info_records[0].message
|
||||
assert "keys_deleted=0" in msg
|
||||
assert "prefix=/api/v1/routes" in msg
|
||||
assert "full_prefix=hub:/api/v1/routes" in msg
|
||||
|
||||
def test_redis_delete_warning_includes_full_prefix(self, caplog):
|
||||
with patch("redis.Redis") as mock_redis_cls:
|
||||
mock_client = MagicMock()
|
||||
mock_redis_cls.return_value = mock_client
|
||||
mock_client.scan.side_effect = Exception("scan timeout")
|
||||
|
||||
backend = RedisCacheBackend(key_prefix="hub")
|
||||
with caplog.at_level("WARNING", logger="meshcore_hub.common.redis"):
|
||||
backend.delete("nodes")
|
||||
|
||||
warning_records = [r for r in caplog.records if r.levelname == "WARNING"]
|
||||
assert len(warning_records) == 1
|
||||
msg = warning_records[0].message
|
||||
assert "Redis DELETE error" in msg
|
||||
assert "prefix=nodes" in msg
|
||||
assert "full_prefix=hub:nodes" in msg
|
||||
assert "scan timeout" in msg
|
||||
|
||||
def test_redis_delete_multi_page_scan_logs_total_keys(self, caplog):
|
||||
"""Multi-page SCAN must accumulate keys_deleted across iterations."""
|
||||
with patch("redis.Redis") as mock_redis_cls:
|
||||
mock_client = MagicMock()
|
||||
mock_redis_cls.return_value = mock_client
|
||||
mock_client.scan.side_effect = [
|
||||
(42, [b"hub:nodes:1", b"hub:nodes:2"]),
|
||||
(0, [b"hub:nodes:3"]),
|
||||
]
|
||||
|
||||
backend = RedisCacheBackend(key_prefix="hub")
|
||||
with caplog.at_level("INFO", logger="meshcore_hub.common.redis"):
|
||||
backend.delete("nodes")
|
||||
|
||||
info_records = [r for r in caplog.records if r.levelname == "INFO"]
|
||||
assert len(info_records) == 1
|
||||
msg = info_records[0].message
|
||||
assert "keys_deleted=3" in msg
|
||||
assert "scan_iterations=2" in msg
|
||||
|
||||
def test_nullcache_delete_emits_debug_log(self, caplog):
|
||||
cache = NullCache()
|
||||
with caplog.at_level("DEBUG", logger="meshcore_hub.common.redis"):
|
||||
cache.delete("nodes")
|
||||
assert any(
|
||||
"NullCache delete" in r.message and "prefix=nodes" in r.message
|
||||
for r in caplog.records
|
||||
), [r.message for r in caplog.records]
|
||||
|
||||
Reference in New Issue
Block a user