Ensure logging is patched before calling basicConfig (#2905) (#2911)

* Ensure logging is patched before calling basicConfig
fixes #1960

To reproduce run `DD_LOGS_INJECTION=true DD_TRACE_DEBUG=true ddtrace-run python -c ''`.

The problem happens because we call basicConfig in `ddtrace/tracer.py` and then any
logging that occurs during tracer initialization before `sitecustomize.py` will
call `patch(logging=True)`

* Add release note

* remove flaky assertion

* update comment

Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>
(cherry picked from commit 38ddd31)

Co-authored-by: Brett Langdon <[email protected]>

Author: mergify[bot]

ddtrace/contrib/logging/patch.py

@@ -39,7 +39,9 @@ def _get_current_span(tracer=None):
     if not tracer:
         tracer = ddtrace.tracer
 
-    if not tracer.enabled:
+    # We might be calling this during library initialization, in which case `ddtrace.tracer` might
+    # be the `tracer` module and not the global tracer instance.
+    if not getattr(tracer, "enabled", False):
         return None
 
     return tracer.current_span()

ddtrace/tracer.py

@@ -49,6 +49,7 @@
 from .internal.writer import AgentWriter
 from .internal.writer import LogWriter
 from .internal.writer import TraceWriter
+from .monkey import patch
 from .provider import DefaultContextProvider
 from .sampler import BasePrioritySampler
 from .sampler import BaseSampler
@@ -72,6 +73,8 @@
 )
 if debug_mode and not hasHandlers(log) and call_basic_config:
     if config.logs_injection:
+        # We need to ensure logging is patched in case the tracer logs during initialization
+        patch(logging=True)
         logging.basicConfig(level=logging.DEBUG, format=DD_LOG_FORMAT)
     else:
         logging.basicConfig(level=logging.DEBUG)

releasenotes/notes/fix-tracer-logging-init-25e8de1dd9d09ac9.yaml

@@ -0,0 +1,4 @@
+---
+fixes:
+  - |
+    Fixes exceptions raised when logging during tracer initialization when ``DD_LOGS_INJECTION`` is enabled.

tests/integration/test_integration.py

@@ -601,3 +601,33 @@ def test_partial_flush_log(run_python_code_in_subprocess):
     log.debug.assert_has_calls(calls)
     s1.finish()
     t.shutdown()
+
+
+def test_ddtrace_run_startup_logging_injection(ddtrace_run_python_code_in_subprocess):
+    """
+    Regression test for enabling debug logging and logs injection
+
+    When both DD_TRACE_DEBUG and DD_LOGS_INJECTION are enabled
+    any logging during tracer initialization would raise an exception
+    because `dd.service` was not available in the log record yet.
+    """
+    env = os.environ.copy()
+    env["DD_TRACE_DEBUG"] = "true"
+    env["DD_LOGS_INJECTION"] = "true"
+
+    # DEV: We don't actually have to execute any code to validate this
+    out, err, status, pid = ddtrace_run_python_code_in_subprocess("", env=env)
+
+    # The program will always exit successfully
+    # Errors during logging do not crash the app
+    assert status == 0, (out, err)
+
+    # The program does nothing
+    assert out == b""
+
+    # stderr is expected to log something due to debug logging
+    assert b"[dd.service= dd.env= dd.version= dd.trace_id=0 dd.span_id=0]" in err
+
+    # Assert no logging exceptions in stderr
+    assert b"KeyError: 'dd.service'" not in err
+    assert b"ValueError: Formatting field not found in record: 'dd.service'" not in err