Repository: prometheus/client_python
Pull request #1076 (2024-12-01 19:21:25)

Fix incorrect use of reentrant locks
The first commit fixes a correctness bug introduced in
0014e9776350a252930671ed170edee464f9b428 resulting in eg. lost updates during some scenarios.

The code being locked is not reentrant safe. It's preferable to deadlock in these situations instead of silently loosing updates for example or allowing data corruption (mmap_dict).

Consider this example

```python
from prometheus_client import Counter

my_counter = Counter('my_counter', 'my_counter description', labelnames=["bug"])


class Tracked(float):
    def __radd__(self, other):
        # Executes within the locked section of ValueClass.inc() if used as
        # amount arg to Counter.inc().
        my_counter.labels(bug="isit").inc(1)
        my_counter.labels(bug="race").inc(10)
        return self + other

    def __str__(self):
        return f"Tracked({float(self)})"


def main():
    my_counter.labels(bug="race").inc(Tracked(100))

    for sample in my_counter.collect()[0].samples:
        print(sample)


if __name__ == '__main__':
    main()
```

Executing this with reentrant locks in place results in (both multiprocess and single process mode):
```
$ python3 example.py 
Sample(name='my_counter_total', labels={'bug': 'race'}, value=100.0, timestamp=None, exemplar=None, native_histogram=None)
Sample(name='my_counter_created', labels={'bug': 'race'}, value=1733062486.7625494, timestamp=None, exemplar=None, native_histogram=None)
Sample(name='my_counter_total', labels={'bug': 'isit'}, value=1.0, timestamp=None, exemplar=None, native_histogram=None)
Sample(name='my_counter_created', labels={'bug': 'isit'}, value=1733062486.7625587, timestamp=None, exemplar=None, native_histogram=None)
```

We would expect the value of the bug=race counter to be 110 however.

With this fix, this code will:

- With the changes from the first commit only: deadlock, signalling to the user that they have a bug.
- With both commits: raise a RuntimeError.

It's also likely to happen if someone tries to write metrics during signal handling. Again, it's preferable to deadlock instead of being incorrect IMHO.

I'm open to dropping the second commit (it does add some complexity and maybe not everyone will like the overhead of an extra lock), but it may be a useful quality of life improvement (crashing is usually better than a deadlock).

Let me know what you think!

csmarchbanks: Giving this some more thought, generally I agree that a deadlock or error would be better than incorrect data. Does this only happen for methods like `__radd__`? If so, I almost wonder if we should have all of the functions cast to a float before taking any locks as it is confusing for what should be a float value (according to typing) to break locking.

@btimby, I would also like your thoughts as you are the one who needs the RLock behavior. Would having normal locks in values.py still be sufficient for your use case?
btimby: Certainly, a deadlock is preferable to corrupt data. It may be the case that the change I proposed was too heavy-handed. In other words, my particular deadlock did not involve the changing of data, but the changing of the metrics registry. In fact, my problem occurred at startup. Manipulation of metric values may require a different locking strategy than registry access.

https://github.com/prometheus/client_python/pull/1014

I am actually using `django-prometheus` which uses `client_python`, and my usage is basically straight out of their documentation.
csmarchbanks: > In other words, my particular deadlock did not involve the changing of data, but the changing of the metrics registry. In fact, my problem occurred at startup. Manipulation of metric values may require a different locking strategy than registry access.

Great, that is what I was thinking, keep the reentrant lock where possible in the registry and use regular locks elsewhere. Do you have a link to a reproducible example? Otherwise I can try to set something up soon.
btimby: I am sorry, I did not record anything at the time. This was just a small issue that I ran into when setting up a new project. I debugged the code and proposed a fix and moved on. This is what I described in the initial issue:

> While using django-prometheus I found a situation where adding a metric to the registry caused a read from cache. I had cache metrics enabled, which attempted to add cache metrics to the registry. This resulting in a deadlock as the second registry call attempted to obtain the lock already held lower on the call stack.

I did a bit of digging just now to refresh my memory, and here is what I think triggered my initial problem. Keep in mind that I am using `django-prometheus` but I don't think there is anything particularly wrong with that project, it just provided the means for me to create this deadlock scenario.

Basically, I was adding a custom `Collector` in a module and the `collect()` method (called when adding to registry) accessed the django cache. I was also using a cache backend with it's own metrics, so by accessing the django cache, additional metrics (for cache access) were added to the registry, resulting in a deadlock.

So I think you could recreate my issue simply by creating a `Collector` that defines another `Collector` in it's `collect()` method.

Here is the code I believe caused the issue:

```python
from typing import Generator

from django.db.models import OuterRef, Subquery
from django.utils import timezone
from django.core.cache import cache

from prometheus_client.core import GaugeMetricFamily, Metric
from prometheus_client.registry import Collector

from schedule.models import MatchTimeSlot
from facility.models import Facility


METRIC_IN_USE = GaugeMetricFamily(
    'two47dink_schedule_courts_in_use',
    'Number of courts reserved for matches',
    labels=['facility']
)


class MatchCollector(Collector):
    """
    Collect court metrics for each facility
    """
    def collect(self) -> Generator[Metric, None, None]:
        now = timezone.now().replace(
            minute=0, second=0, microsecond=0,
        )

        key = f'{__name__}.metrics-results'
        cached_results = cache.get(key)

        if not cached_results:
            match_count = MatchTimeSlot.objects \
                .filter(facility_id=OuterRef('id'), time=now) \
                .values('spanning')
            facilities = Facility.objects.all().annotate(
                match_count=Subquery(match_count),
            )

            cached_results = {
                facility.name: {'match_count': facility.match_count}
                for facility in facilities
            }
            cache.set(key, cached_results, 60)

        for facility_name, results in cached_results.items():
            METRIC_IN_USE.add_metric(
                labels=[facility_name], value=results.get('match_count') or 0.0
            )

        yield METRIC_IN_USE

    def describe(self) -> Generator[Metric, None, None]:
        yield METRIC_IN_USE
```

I added the optional `describe()` method later (to address an unrelated problem), which likely also fixes this issue, as it will be called instead of `collect()` and does NOT access the django cache. I am using this cache backend from `django-prometheus`:

https://github.com/korfuri/django-prometheus/blob/master/django_prometheus/cache/backends/redis.py

And now that I look at that code, it is indeed modifying counters related to cache access, so it may be modifying data (and not just the registry). OTOH, django does a lot of lazy loading and imports, so it may be the case that the cache backend is not loaded (and thus metrics are not initialized) until the cache is accessed. I know my original description of the problem specifically states that the registry is accessed in a nested manner, and I know that I did run this code under a debugger so I would tend to trust past me on this assessment.

I hope this helps, I can try to provide more information if you need it.
suligap: @csmarchbanks

> Does this only happen for methods like `__radd__`?

Oh, I think/hope the `__radd__` example is something that doesn't happen often in the real world. But it illustrates nicely that the code being locked is not reentrant safe. I think that the `float()` treatment might be a good idea on its own but it still does not make this code reentrant safe.

I'd expect that in practice people may have been running into deadlocks here (metric updates) mostly in case when they're handling signals (signal handlers invoked during the execution of the critical section held by the lock) and during signal handling they're updating some metrics. This is what we've seen and that's how I stumbled upon the RLock PR. In that case I think the proper fix is keeping the application's signal handling code very simple and not allowing it to update prometheus metrics (at least not in the multiprocess mode).


> Great, that is what I was thinking, keep the reentrant lock where possible in the registry and use regular locks elsewhere.

Hmm, the code protected by CollectorRegistry._lock does not look reentrant safe to me either. Same with locking in metrics.py. There's nothing special about the access happening from within the same thread that is currently holding a lock that would make it safe to re-enter these contexts. I think if anything, allowing that will make it harder to spot/debug the resulting issues?


@btimby

> Basically, I was adding a custom Collector in a module and the collect()
> method (called when adding to registry) accessed the django cache. I was also
> using a cache backend with it's own metrics, so by accessing the django
> cache, additional metrics (for cache access) were added to the registry,
> resulting in a deadlock.

This makes sense indeed if your custom Collector's .collect() resulted in lazy loading the django-prometheus' custom cache module which imports the module that registers the cache metrics in the first place. Perhaps a solution in your case would be to make sure the cache module is already loaded properly somehow. Or like you say, use the .describe() method which does not access the cache.

Thank you both for looking at this!
csmarchbanks: Yep, I agree. What I was thinking is that the same thread should be able to instantiate the same metric lazily which is why a reentrant lock sounded like a good idea, but yeah it is not safe in that case either. If your issue can be solved by implementing `.describe()` we should just advise users towards that to avoid any deadlocks.

For this PR let's start simple and just move the RLocks back to Locks. I somewhat like the idea of raising an error instead, but I don't think value is the right place since it sounds like the use case is for a custom collector.


suligap: > For this PR let's start simple and just move the RLocks back to Locks.

Sure thing and done.

> I somewhat like the idea of raising an error instead, but I don't think value is the right place since it sounds like the use case is for a custom collector.

I think it can happen in all cases, and we have certainly been affected by these elusive deadlocks in production caused by our gunicorn wrapper instrumenting the gunicorn main process' logging with sentry and related prometheus metrics (recording http metrics for requests sent to sentry). So this is a single threaded context in which  the main process was sometimes in the middle of incrementing a prometheus counter as a result of sending an event to sentry as a result of gunicorn main process logging an error log about eg. terminating an unresponsive worker. In the middle of that when the global multiprocessing mode lock in values.py was held, a signal handler for SIGCHLD was invoked in that main process in response to some other worker terminating. During that signal handling the main process also logs an error message which caused the sentry event and a corresponding prometheus counter update -> deadlock. But the proper fix in this case is for us to be more careful/conservative with what we do during signal handling, or in this case what we instrumented gunicorn to do. We'd certainly find this issue quicker if there was an error instead. If people think it makes sense I can propose a separate PR with a change that adds this for all locks.

Patch:
diff --git a/prometheus_client/metrics.py b/prometheus_client/metrics.py
index 4617586..9b25127 100644
--- a/prometheus_client/metrics.py
+++ b/prometheus_client/metrics.py
@@ -1,5 +1,5 @@
 import os
-from threading import RLock
+from threading import Lock
 import time
 import types
 from typing import (
@@ -120,7 +120,7 @@ class MetricWrapperBase(Collector):
 
         if self._is_parent():
             # Prepare the fields needed for child metrics.
-            self._lock = RLock()
+            self._lock = Lock()
             self._metrics: Dict[Sequence[str], T] = {}
 
         if self._is_observable():
@@ -673,7 +673,7 @@ class Info(MetricWrapperBase):
 
     def _metric_init(self):
         self._labelname_set = set(self._labelnames)
-        self._lock = RLock()
+        self._lock = Lock()
         self._value = {}
 
     def info(self, val: Dict[str, str]) -> None:
@@ -735,7 +735,7 @@ class Enum(MetricWrapperBase):
 
     def _metric_init(self) -> None:
         self._value = 0
-        self._lock = RLock()
+        self._lock = Lock()
 
     def state(self, state: str) -> None:
         """Set enum metric state."""
diff --git a/prometheus_client/registry.py b/prometheus_client/registry.py
index 4326b39..694e4bd 100644
--- a/prometheus_client/registry.py
+++ b/prometheus_client/registry.py
@@ -1,6 +1,6 @@
 from abc import ABC, abstractmethod
 import copy
-from threading import RLock
+from threading import Lock
 from typing import Dict, Iterable, List, Optional
 
 from .metrics_core import Metric
@@ -30,7 +30,7 @@ class CollectorRegistry(Collector):
         self._collector_to_names: Dict[Collector, List[str]] = {}
         self._names_to_collectors: Dict[str, Collector] = {}
         self._auto_describe = auto_describe
-        self._lock = RLock()
+        self._lock = Lock()
         self._target_info: Optional[Dict[str, str]] = {}
         self.set_target_info(target_info)
 
diff --git a/prometheus_client/values.py b/prometheus_client/values.py
index 05331f8..6ff85e3 100644
--- a/prometheus_client/values.py
+++ b/prometheus_client/values.py
@@ -1,5 +1,5 @@
 import os
-from threading import RLock
+from threading import Lock
 import warnings
 
 from .mmap_dict import mmap_key, MmapedDict
@@ -13,7 +13,7 @@ class MutexValue:
     def __init__(self, typ, metric_name, name, labelnames, labelvalues, help_text, **kwargs):
         self._value = 0.0
         self._exemplar = None
-        self._lock = RLock()
+        self._lock = Lock()
 
     def inc(self, amount):
         with self._lock:
@@ -50,7 +50,7 @@ def MultiProcessValue(process_identifier=os.getpid):
     # Use a single global lock when in multi-processing mode
     # as we presume this means there is no threading going on.
     # This avoids the need to also have mutexes in __MmapDict.
-    lock = RLock()
+    lock = Lock()
 
     class MmapedValue:
         """A float protected by a mutex backed by a per-process mmaped file."""


Test patch:
diff --git a/tests/test_core.py b/tests/test_core.py
index 4e99ca3..f28c9ab 100644
--- a/tests/test_core.py
+++ b/tests/test_core.py
@@ -19,14 +19,6 @@ from prometheus_client.validation import (
 )
 
 
-def is_locked(lock):
-    "Tries to obtain a lock, returns True on success, False on failure."
-    locked = lock.acquire(blocking=False)
-    if locked:
-        lock.release()
-    return not locked
-
-
 def assert_not_observable(fn, *args, **kwargs):
     """
     Assert that a function call falls with a ValueError exception containing
@@ -1012,7 +1004,7 @@ class TestCollectorRegistry(unittest.TestCase):
         m = Metric('target', 'Target metadata', 'info')
         m.samples = [Sample('target_info', {'foo': 'bar'}, 1)]
         for _ in registry.restricted_registry(['target_info', 's_sum']).collect():
-            self.assertFalse(is_locked(registry._lock))
+            self.assertFalse(registry._lock.locked())
 
 
 if __name__ == '__main__':