Skip to content

Commit e7bd283

Browse files
fix(profiling): stop calling logger from lock profiler [backport 3.4] (#13152)
Backport 29ab7d8 from #13147 to 3.4. ```Python try: del self._self_acquired_at except AttributeError: LOG.debug("Failed to delete _self_acquired_at") ``` Above code resulted in an infinite recursion from a customer environment, by calling `LOG.debug()`. This PR removes `logger` from the lock profiler as logging any information from lock profiler to customer environment caused more harm than benefit. We don't always set the `_self_acquired_at` attribute when `acquire()` is called. It's set only when the `acquire()` is sampled. And in the `except` block above, the call to `LOG.debug()` leads to `acquire()/release()` calls. Then if a subsequent `acquire()` was not captured, then it will be calling `LOG.debug()` again from `release()`, leading to an infinite recursion. 1. File `/usr/local/lib/python3.11/logging/__init__.py`, [line 1477](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/logging/__init__.py#L1477), in `debug` ```Python self._log(DEBUG, msg, args, **kwargs) ``` 2. File `/usr/local/lib/python3.11/logging/__init__.py`, [line 1632](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/logging/__init__.py#L1632), in `_log` ```Python record = self.makeRecord(self.name, level, fn, lno, msg, args, exc_info, func, extra, sinfo) ``` 3. File `/code/.venv/lib/python3.11/site-packages/ddtrace/contrib/internal/logging/patch.py`, [line 70](https://github.com/DataDog/dd-trace-py/blob/eb81294f4c5ae0ac1b30ece3ef3a81ff00bfae90/ddtrace/contrib/internal/logging/patch.py#L70), in `_w_makeRecord` ```Python record = func(*args, **kwargs) ``` 4. File `/usr/local/lib/python3.11/logging/__init__.py`, [line 1601](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/logging/__init__.py#L1601), in `makeRecord` ```Python rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func, sinfo) ``` 5. File `/usr/local/lib/python3.11/logging/__init__.py`, [line 341](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/logging/__init__.py#L341), in `__init__` ```Python self.threadName = threading.current_thread().name ``` 6. File `/usr/local/lib/python3.11/threading.py`, [line 1463](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/threading.py#L1463), in `current_thread` ```Python return _DummyThread() ``` 7. File `/usr/local/lib/python3.11/threading.py`, [line 1433](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/threading.py#L1433), in `__init__` ```Python self._started.set() ``` 8. File `/usr/local/lib/python3.11/threading.py`, [line 597](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/threading.py#L597), in `set` ```Python with self._cond: ``` 9. File `/usr/local/lib/python3.11/threading.py`, [line 275](https://github.com/python/cpython/blob/ab4746261870bcdbb6e7c5a5b307465fbe517790/Lib/threading.py#L275), in `__exit__` ```Python return self._lock.__exit__(*args) ``` 10. File `/code/.venv/lib/python3.11/site-packages/ddtrace/profiling/collector/_lock.py`, [line 259](https://github.com/DataDog/dd-trace-py/blob/eb81294f4c5ae0ac1b30ece3ef3a81ff00bfae90/ddtrace/profiling/collector/_lock.py#L259), in `__exit__` ```Python self._release(self.__wrapped__.__exit__, *args, **kwargs) ``` 11. File `/code/.venv/lib/python3.11/site-packages/ddtrace/profiling/collector/_lock.py`, [line 198](https://github.com/DataDog/dd-trace-py/blob/eb81294f4c5ae0ac1b30ece3ef3a81ff00bfae90/ddtrace/profiling/collector/_lock.py#L198), in _release ``` LOG.debug("Failed to delete _self_acquired_at") ``` ## Checklist - [x] PR author has checked that all the criteria below are met - The PR description includes an overview of the change - The PR description articulates the motivation for the change - The change includes tests OR the PR description describes a testing strategy - The PR description notes risks associated with the change, if any - Newly-added code is easy to change - The change follows the [library release note guidelines](https://ddtrace.readthedocs.io/en/stable/releasenotes.html) - The change includes or references documentation updates if necessary - Backport labels are set (if [applicable](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting)) ## Reviewer Checklist - [x] Reviewer has checked that all the criteria below are met - Title is accurate - All changes are related to the pull request's stated goal - Avoids breaking [API](https://ddtrace.readthedocs.io/en/stable/versioning.html#interfaces) changes - Testing strategy adequately addresses listed risks - Newly-added code is easy to change - Release note makes sense to a user of the library - If necessary, author has acknowledged and discussed the performance implications of this PR as reported in the benchmarks PR comment - Backport labels are set in a manner that is consistent with the [release branch maintenance policy](https://ddtrace.readthedocs.io/en/latest/contributing.html#backporting) Co-authored-by: Taegyun Kim <[email protected]>
1 parent 5ed4bc5 commit e7bd283

File tree

2 files changed

+9
-7
lines changed

2 files changed

+9
-7
lines changed

ddtrace/profiling/collector/_lock.py

Lines changed: 3 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -11,7 +11,6 @@
1111
import wrapt
1212

1313
from ddtrace.internal.datadog.profiling import ddup
14-
from ddtrace.internal.logger import get_logger
1514
from ddtrace.profiling import _threading
1615
from ddtrace.profiling import collector
1716
from ddtrace.profiling import event
@@ -22,9 +21,6 @@
2221
from ddtrace.trace import Tracer
2322

2423

25-
LOG = get_logger(__name__)
26-
27-
2824
class LockEventBase(event.StackBasedEvent):
2925
"""Base Lock event."""
3026

@@ -170,8 +166,7 @@ def _acquire(self, inner_func, *args, **kwargs):
170166
event.set_trace_info(self._self_tracer.current_span(), self._self_endpoint_collection_enabled)
171167

172168
self._self_recorder.push_event(event)
173-
except Exception as e:
174-
LOG.debug("Failed to record a lock acquire event: %s", e)
169+
except Exception:
175170
pass # nosec
176171

177172
def acquire(self, *args, **kwargs):
@@ -195,7 +190,8 @@ def _release(self, inner_func, *args, **kwargs):
195190
# and unlocked lock, and the expected behavior is to propagate that.
196191
del self._self_acquired_at
197192
except AttributeError:
198-
LOG.debug("Failed to delete _self_acquired_at")
193+
# We just ignore the error, if the attribute is not found.
194+
pass
199195
try:
200196
return inner_func(*args, **kwargs)
201197
finally:
Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,6 @@
1+
---
2+
fixes:
3+
- |
4+
profiling: fixes an infinite recursion from calling logging module when
5+
lock profiler fails to delete ``_self_acquired_at`` attribute.
6+

0 commit comments

Comments
 (0)