diff --git a/src/meshcore_hub/api/cache_invalidation.py b/src/meshcore_hub/api/cache_invalidation.py index ac8e320..d198587 100644 --- a/src/meshcore_hub/api/cache_invalidation.py +++ b/src/meshcore_hub/api/cache_invalidation.py @@ -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: diff --git a/src/meshcore_hub/common/redis.py b/src/meshcore_hub/common/redis.py index 8f4dbc5..8024442 100644 --- a/src/meshcore_hub/common/redis.py +++ b/src/meshcore_hub/common/redis.py @@ -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: diff --git a/tests/test_api/test_cache.py b/tests/test_api/test_cache.py index 7253a23..99a94d9 100644 --- a/tests/test_api/test_cache.py +++ b/tests/test_api/test_cache.py @@ -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]