feat: actually record xmlrpc cache metrics (#20347)

Signed-off-by: Mike Fiedler <miketheman@gmail.com>

Author: miketheman

tests/unit/legacy/api/xmlrpc/test_cache.py

@@ -18,6 +18,7 @@
     cached_return_view,
     services,
 )
+from warehouse.legacy.api.xmlrpc.cache.fncache import StubMetricReporter
 from warehouse.legacy.api.xmlrpc.cache.interfaces import CacheError, IXMLRPCCache
 
 
@@ -160,12 +161,29 @@ def test_create_redis_service(self, pyramid_request, mocker):
 
         assert isinstance(service, RedisXMLRPCCache)
         assert service._purger is delay
-        assert delay.call_args_list == [
-            mocker.call("wu"),
-            mocker.call("tang"),
-            mocker.call("4"),
-            mocker.call("evah"),
-        ]
+        # Without this the cache falls back to StubMetricReporter and reports nothing.
+        assert service.redis_lru.metric_reporter is pyramid_request.metrics
+
+    def test_create_redis_service_without_a_request(self, mocker):
+        """The factory tolerates being handed something that is not a request.
+
+        `execute_purge` calls it with the Configurator, which has no `metrics`. That
+        path only enqueues purges, so a stubbed reporter there costs nothing, but an
+        AttributeError would break every `after_commit`.
+        """
+        delay = mocker.stub(name="delay")
+        config = types.SimpleNamespace(
+            registry=types.SimpleNamespace(
+                settings={"warehouse.xmlrpc.cache.url": "redis://"}
+            ),
+            task=mocker.Mock(return_value=mocker.Mock(delay=delay)),
+        )
+
+        service = RedisXMLRPCCache.create_service(None, config)
+        service.purge_tags(["wu", "tang"])
+
+        assert isinstance(service.redis_lru.metric_reporter, StubMetricReporter)
+        assert delay.call_args_list == [mocker.call("wu"), mocker.call("tang")]
 
 
 class TestRedisLru:
@@ -193,8 +211,28 @@ def test_redis_custom_metrics(self, metrics, mockredis, mocker):
             func_test, [0, 1], {"kwarg0": 2, "kwarg1": 3}, None, None, None
         )
         assert metrics.increment.call_args_list == [
-            mocker.call("lru.cache.miss"),
-            mocker.call("lru.cache.hit"),
+            mocker.call("warehouse.lru.cache.miss"),
+            mocker.call("warehouse.lru.cache.hit"),
+        ]
+
+    def test_falsy_cached_value_is_a_single_hit(self, metrics, mockredis, mocker):
+        """An empty result is a real hit: counted once, and the view is not re-run.
+
+        `fetch` compares the cached value against None instead of testing its
+        truthiness. Testing truthiness reports the same request as both a hit and a
+        miss, which would make the hit rate unreadable, and re-runs the query every
+        time. `package_roles` returns `[]` for any unknown name.
+        """
+        empty_func = mocker.Mock(return_value=[], __name__="empty_func")
+        redis_lru = RedisLru(mockredis, metric_reporter=metrics)
+
+        assert redis_lru.fetch(empty_func, [], {}, "[]", None, None) == []
+        assert redis_lru.fetch(empty_func, [], {}, "[]", None, None) == []
+
+        empty_func.assert_called_once_with()
+        assert metrics.increment.call_args_list == [
+            mocker.call("warehouse.lru.cache.miss"),
+            mocker.call("warehouse.lru.cache.hit"),
         ]
 
     def test_redis_purge(self, metrics, mockredis, mocker):
@@ -216,11 +254,11 @@ def test_redis_purge(self, metrics, mockredis, mocker):
             func_test, [0, 1], {"kwarg0": 2, "kwarg1": 3}, None, "test", None
         )
         assert metrics.increment.call_args_list == [
-            mocker.call("lru.cache.miss"),
-            mocker.call("lru.cache.hit"),
-            mocker.call("lru.cache.purge"),
-            mocker.call("lru.cache.miss"),
-            mocker.call("lru.cache.hit"),
+            mocker.call("warehouse.lru.cache.miss"),
+            mocker.call("warehouse.lru.cache.hit"),
+            mocker.call("warehouse.lru.cache.purge"),
+            mocker.call("warehouse.lru.cache.miss"),
+            mocker.call("warehouse.lru.cache.hit"),
         ]
 
     def test_redis_down(self, metrics, mocker):
@@ -242,13 +280,13 @@ def test_redis_down(self, metrics, mocker):
             redis_lru.purge("test")
 
         assert metrics.increment.call_args_list == [
-            mocker.call("lru.cache.error"),  # Failed get
-            mocker.call("lru.cache.miss"),
-            mocker.call("lru.cache.error"),  # Failed add
-            mocker.call("lru.cache.error"),  # Failed get
-            mocker.call("lru.cache.miss"),
-            mocker.call("lru.cache.error"),  # Failed add
-            mocker.call("lru.cache.error"),  # Failed purge
+            mocker.call("warehouse.lru.cache.error"),  # Failed get
+            mocker.call("warehouse.lru.cache.miss"),
+            mocker.call("warehouse.lru.cache.error"),  # Failed add
+            mocker.call("warehouse.lru.cache.error"),  # Failed get
+            mocker.call("warehouse.lru.cache.miss"),
+            mocker.call("warehouse.lru.cache.error"),  # Failed add
+            mocker.call("warehouse.lru.cache.error"),  # Failed purge
         ]
 
 

warehouse/legacy/api/xmlrpc/cache/fncache.py

@@ -43,16 +43,16 @@ def get(self, func_name, key, tag):
         try:
             value = self.conn.hget(self.format_key(func_name, tag), str(key))
         except redis.exceptions.RedisError, redis.exceptions.ConnectionError:
-            self.metric_reporter.increment(f"{self.name}.cache.error")
+            self.metric_reporter.increment(f"warehouse.{self.name}.cache.error")
             return None
         if value:
-            self.metric_reporter.increment(f"{self.name}.cache.hit")
+            self.metric_reporter.increment(f"warehouse.{self.name}.cache.hit")
             value = orjson.loads(value)
         return value
 
     def add(self, func_name, key, value, tag, expires):
         try:
-            self.metric_reporter.increment(f"{self.name}.cache.miss")
+            self.metric_reporter.increment(f"warehouse.{self.name}.cache.miss")
             pipeline = self.conn.pipeline()
             pipeline.hset(
                 self.format_key(func_name, tag), str(key), orjson.dumps(value)
@@ -62,7 +62,7 @@ def add(self, func_name, key, value, tag, expires):
             pipeline.execute()
             return value
         except redis.exceptions.RedisError, redis.exceptions.ConnectionError:
-            self.metric_reporter.increment(f"{self.name}.cache.error")
+            self.metric_reporter.increment(f"warehouse.{self.name}.cache.error")
             return value
 
     def purge(self, tag):
@@ -72,12 +72,19 @@ def purge(self, tag):
             for key in keys:
                 pipeline.delete(key)
             pipeline.execute()
-            self.metric_reporter.increment(f"{self.name}.cache.purge")
+            self.metric_reporter.increment(f"warehouse.{self.name}.cache.purge")
         except redis.exceptions.RedisError, redis.exceptions.ConnectionError:
-            self.metric_reporter.increment(f"{self.name}.cache.error")
+            self.metric_reporter.increment(f"warehouse.{self.name}.cache.error")
             raise CacheError
 
     def fetch(self, func, args, kwargs, key, tag, expires):
-        return self.get(func.__name__, str(key), str(tag)) or self.add(
+        # `get` returns None for both a miss and a Redis error, so compare against
+        # None rather than testing truthiness: an empty list or dict is a real hit.
+        # Treating it as a miss counts the request as both a hit and a miss and
+        # re-runs the query on every call.
+        value = self.get(func.__name__, str(key), str(tag))
+        if value is not None:
+            return value
+        return self.add(
             func.__name__, str(key), func(*args, **kwargs), str(tag), expires
         )

warehouse/legacy/api/xmlrpc/cache/services.py

@@ -48,6 +48,12 @@ def create_service(cls, context, request):
                     "warehouse.xmlrpc.cache.expires", 25 * 60 * 60
                 )
             ),
+            # `execute_purge` calls this factory with the Configurator rather than a
+            # request, and a Configurator has no `metrics`. That path only calls
+            # `purge_tags`, which enqueues celery tasks and never touches `RedisLru`,
+            # so falling back to `StubMetricReporter` there loses nothing: the real
+            # `purge` runs in the `purge_tag` task, which does have a request.
+            metric_reporter=getattr(request, "metrics", None),
         )
 
     def fetch(self, func, args, kwargs, key, tag, expires):