Skip to content

Deadlock between log batcher lock and logging handler lock when GC runs a finalizer that logs #7775

Description

@NicoHinderling

Environment: sentry-sdk 2.66.1 and 2.71.0, Python 3.14, enable_logs=True with the default LoggingIntegration.

Batcher._flush holds self._lock while _add_to_envelope serializes the buffered items. If a cyclic GC runs during that serialization, and it collects an object whose __del__ calls logging, the flush thread goes through Handler.handle and blocks acquiring the SentryLogsHandler handler lock. add()'s thread-local _active guard (#5684) doesn't help here, because the handler lock is taken before add() is ever reached. If another thread is logging at the same moment, it already holds that handler lock inside emit and waits for Batcher._lock in add(). The result is a lock-order inversion: every later log call in the process blocks, forever. We hit this in production: Celery tasks froze until they were hard-killed.

Minimal repro (deadlocks in ~5s, 7/7 runs across both versions):

import gc, logging, sys, threading, time, traceback
import sentry_sdk
from sentry_sdk.transport import Transport

class DropTransport(Transport):
    def capture_envelope(self, envelope):
        pass

sentry_sdk.init(dsn="https://k@o0.ingest.sentry.io/0", transport=DropTransport, enable_logs=True)
logger = logging.getLogger("repro")
logger.setLevel(logging.INFO)

class Leaky:
    def __init__(self):
        self.cycle = self
    def __del__(self):
        logger.warning("finalizer logging")

progress = [0]
def log_forever():
    while True:
        logger.info("hello")
        progress[0] += 1

def make_garbage():
    while True:
        Leaky()
        time.sleep(0.0005)

gc.set_threshold(200, 2, 2)
for fn in (log_forever, log_forever, log_forever, make_garbage):
    threading.Thread(target=fn, daemon=True).start()

last = -1
while True:
    time.sleep(5)
    if progress[0] == last:
        print("DEADLOCK")
        for tid, frame in sys._current_frames().items():
            traceback.print_stack(frame)
        break
    last = progress[0]

The stacks show _flush_loop → _flush → _add_to_envelope → _to_transport_format → __del__ → logger.warning → Handler.handle blocked on the handler lock, and a logging thread at Handler.handle → emit → Batcher.add blocked on _lock.

Suggested fix: in Batcher._flush, swap the buffer out under the lock, then serialize outside it:

with self._lock:
    if not self._buffer:
        return None
    items, self._buffer = self._buffer, []
# build the envelope from `items` here, outside the lock

With that patch applied, the repro above ran 0 deadlocks in 3×60s. Happy to open a PR.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions