fix: avoid context deadlock with logs injection enabled (#1338)

* don't try to get current span on patched internal logger

* run black

* add span directly to log record

* add test

* run black

* contextually group test a bit better

* don't add issue number

Co-Authored-By: Tahir H. Butt <[email protected]>

* rename logger_arg to logger_override 1/2

Co-Authored-By: Tahir H. Butt <[email protected]>

* rename logger_arg to logger_override 2/2

Co-Authored-By: Tahir H. Butt <[email protected]>

* fix arg name

Co-authored-by: Tahir H. Butt <[email protected]>

Author: zhammer

ddtrace/constants.py

@@ -17,3 +17,5 @@
 
 MANUAL_DROP_KEY = 'manual.drop'
 MANUAL_KEEP_KEY = 'manual.keep'
+
+LOG_SPAN_KEY = '__datadog_log_span'

ddtrace/context.py

@@ -1,7 +1,7 @@
 import logging
 import threading
 
-from .constants import HOSTNAME_KEY, SAMPLING_PRIORITY_KEY, ORIGIN_KEY
+from .constants import HOSTNAME_KEY, SAMPLING_PRIORITY_KEY, ORIGIN_KEY, LOG_SPAN_KEY
 from .internal.logger import get_logger
 from .internal import hostname
 from .settings import config
@@ -139,12 +139,13 @@ def close_span(self, span):
             # some children. On the other hand, asynchronous web frameworks still expect
             # to close the root span after all the children.
             if span.tracer and span.tracer.log.isEnabledFor(logging.DEBUG) and span._parent is None:
+                extra = {LOG_SPAN_KEY: span}
                 unfinished_spans = [x for x in self._trace if not x.finished]
                 if unfinished_spans:
                     log.debug('Root span "%s" closed, but the trace has %d unfinished spans:',
-                              span.name, len(unfinished_spans))
+                              span.name, len(unfinished_spans), extra=extra)
                     for wrong_span in unfinished_spans:
-                        log.debug('\n%s', wrong_span.pprint())
+                        log.debug('\n%s', wrong_span.pprint(), extra=extra)
 
     def _is_sampled(self):
         return any(span.sampled for span in self._trace)

ddtrace/contrib/logging/patch.py

@@ -35,7 +35,14 @@ def _w_makeRecord(func, instance, args, kwargs):
     setattr(record, RECORD_ATTR_ENV, ddtrace.config.env or "")
     setattr(record, RECORD_ATTR_SERVICE, ddtrace.config.service or "")
 
-    span = _get_current_span(tracer=ddtrace.config.logging.tracer)
+    # logs from internal logger may explicitly pass the current span to
+    # avoid deadlocks in getting the current span while already in locked code.
+    span_from_log = getattr(record, ddtrace.constants.LOG_SPAN_KEY, None)
+    if isinstance(span_from_log, ddtrace.Span):
+        span = span_from_log
+    else:
+        span = _get_current_span(tracer=ddtrace.config.logging.tracer)
+
     if span:
         setattr(record, RECORD_ATTR_TRACE_ID, span.trace_id)
         setattr(record, RECORD_ATTR_SPAN_ID, span.span_id)

tests/contrib/logging/test_logging.py

@@ -24,18 +24,23 @@ def current_span(tracer=None):
     return tracer.current_span()
 
 
-def capture_function_log(func, fmt=DEFAULT_FORMAT):
+def capture_function_log(func, fmt=DEFAULT_FORMAT, logger_override=None):
+    if logger_override is not None:
+        logger_to_capture = logger_override
+    else:
+        logger_to_capture = logger
+
     # add stream handler to capture output
     out = StringIO()
     sh = logging.StreamHandler(out)
 
     try:
         formatter = logging.Formatter(fmt)
         sh.setFormatter(formatter)
-        logger.addHandler(sh)
+        logger_to_capture.addHandler(sh)
         result = func()
     finally:
-        logger.removeHandler(sh)
+        logger_to_capture.removeHandler(sh)
 
     return out.getvalue().strip(), result
 
@@ -158,3 +163,26 @@ def create_span():
 
         with self.override_global_config(dict(version="global.version", env="global.env")):
             self._test_logging(create_span=create_span, version="global.version", env="global.env")
+
+    def test_unfinished_child(self):
+        """
+        Check that closing a span with unfinished children correctly logs out
+        unfinished spans.
+        """
+        # unfinished child spans only logged if tracer log level is debug
+        self.tracer.log.setLevel(logging.DEBUG)
+
+        # the actual logger used for these message is ddtrace.context logger,
+        # so debug logging has to be enabled here as well.
+        context_logger = logging.getLogger("ddtrace.context")
+        context_logger.setLevel(logging.DEBUG)
+
+        # finish parent span without finishing child span
+        parent = self.tracer.trace("parent")
+        child = self.tracer.trace("child")
+        out, span = capture_function_log(parent.finish, logger_override=context_logger)
+
+        assert 'Root span "parent" closed, but the trace has 1 unfinished spans' in out
+        assert "parent_id {}".format(parent.span_id) in out
+        assert "trace_id {}".format(child.trace_id) in out
+        assert "id {}".format(child.span_id) in out