fix(structlog): ensures processor injection is not duplicated [backport 2.7]

ddtrace/contrib/structlog/patch.py

@@ -3,6 +3,8 @@
 import ddtrace
 from ddtrace import config
 
+from ...internal.utils import get_argument_value
+from ...internal.utils import set_argument_value
 from ..logging.constants import RECORD_ATTR_ENV
 from ..logging.constants import RECORD_ATTR_SERVICE
 from ..logging.constants import RECORD_ATTR_SPAN_ID
@@ -50,6 +52,7 @@ def _tracer_injection(_, __, event_dict):
 def _w_get_logger(func, instance, args, kwargs):
     """
     Append the tracer injection processor to the ``default_processors`` list used by the logger
+    Ensures that the tracer injection processor is the first processor in the chain and only injected once
     The ``default_processors`` list has built in defaults which protects against a user configured ``None`` value.
     The argument to configure ``default_processors`` accepts an iterable type:
         - List: default use case which has been accounted for
@@ -59,10 +62,47 @@ def _w_get_logger(func, instance, args, kwargs):
     """
 
     dd_processor = [_tracer_injection]
-    structlog._config._CONFIG.default_processors = dd_processor + list(structlog._config._CONFIG.default_processors)
+    if (
+        _tracer_injection not in list(structlog._config._CONFIG.default_processors)
+        and structlog._config._CONFIG.default_processors
+    ):
+        structlog._config._CONFIG.default_processors = dd_processor + list(structlog._config._CONFIG.default_processors)
+
+    return func(*args, **kwargs)
+
+
+def _w_configure(func, instance, args, kwargs):
+    """
+    Injects the tracer injection processor to the ``processors`` list parameter when configuring a logger
+    Ensures that the tracer injection processor is the first processor in the chain and only injected once
+    In addition, the tracer injection processor is only injected if there is a renderer processor in the chain
+    """
+
+    dd_processor = [_tracer_injection]
+    arg_processors = get_argument_value(args, kwargs, 0, "processors", True)
+    if arg_processors and len(arg_processors) != 0:
+        set_argument_value(args, kwargs, 0, "processors", dd_processor + list(arg_processors))
+
     return func(*args, **kwargs)
 
 
+def _w_reset_defaults(func, instance, args, kwargs):
+    """
+    Reset the default_processors list to the original defaults
+    Ensures that the tracer injection processor is injected after to the default_processors list
+    """
+    func(*args, **kwargs)
+
+    dd_processor = [_tracer_injection]
+    if (
+        _tracer_injection not in list(structlog._config._CONFIG.default_processors)
+        and structlog._config._CONFIG.default_processors
+    ):
+        structlog._config._CONFIG.default_processors = dd_processor + list(structlog._config._CONFIG.default_processors)
+
+    return
+
+
 def patch():
     """
     Patch ``structlog`` module for injection of tracer information
@@ -79,6 +119,12 @@ def patch():
     if hasattr(structlog, "getLogger"):
         _w(structlog, "getLogger", _w_get_logger)
 
+    if hasattr(structlog, "configure"):
+        _w(structlog, "configure", _w_configure)
+
+    if hasattr(structlog, "reset_defaults"):
+        _w(structlog, "reset_defaults", _w_reset_defaults)
+
 
 def unpatch():
     if getattr(structlog, "_datadog_patch", False):
@@ -88,3 +134,7 @@ def unpatch():
             _u(structlog, "get_logger")
         if hasattr(structlog, "getLogger"):
             _u(structlog, "getLogger")
+        if hasattr(structlog, "configure"):
+            _u(structlog, "configure")
+        if hasattr(structlog, "reset_defaults"):
+            _u(structlog, "reset_defaults")

releasenotes/notes/structlog-configure-patch-479a0534962957e8.yaml

@@ -0,0 +1,5 @@
+---
+fixes:
+  - |
+    structlog: Fixes error where multiple loggers would duplicate processors. Also adds processors injection 
+    when resetting to defaults.

tests/contrib/structlog/test_structlog_logging.py

@@ -345,3 +345,108 @@ def test_no_configured_processor():
 
     cf.logger.calls.clear()
     unpatch()
+
+
+@pytest.mark.subprocess()
+def test_two_loggers_no_duplicates():
+    """
+    Check if patching two loggers does not duplicate processors
+    """
+    import structlog
+
+    from ddtrace.contrib.structlog import patch
+    from ddtrace.contrib.structlog import unpatch
+
+    patch()
+
+    logger1 = structlog.getLogger()
+    num_log1_processors = len(logger1.bind()._processors)
+
+    logger2 = structlog.getLogger()
+    num_log2_processors = len(logger2.bind()._processors)
+
+    assert (
+        num_log1_processors
+        == num_log2_processors
+        == len(logger1.bind()._processors)
+        == len(structlog._config._BUILTIN_DEFAULT_PROCESSORS) + 1
+    )
+
+    unpatch()
+
+
+@pytest.mark.subprocess()
+def test_configure_processor():
+    """
+    Check if calling configure() after get_logger() does not duplicate/remove injected processors
+    """
+    import structlog
+
+    from ddtrace.contrib.structlog import patch
+    from ddtrace.contrib.structlog import unpatch
+
+    patch()
+
+    structlog.configure()
+    logger1 = structlog.getLogger()
+    num_log1_processors = len(logger1.bind()._processors)
+
+    cf = structlog.testing.CapturingLoggerFactory()
+    structlog.configure(
+        logger_factory=cf,
+    )
+
+    assert (
+        num_log1_processors == len(logger1.bind()._processors) == len(structlog._config._BUILTIN_DEFAULT_PROCESSORS) + 1
+    )
+
+    cf.logger.calls.clear()
+    unpatch()
+
+
+@pytest.mark.subprocess()
+def test_consistent_empty_config():
+    """
+    Check if calling configure() with an empty processor list stays empty
+    """
+    import structlog
+
+    from ddtrace.contrib.structlog import patch
+    from ddtrace.contrib.structlog import unpatch
+
+    patch()
+
+    logger1 = structlog.getLogger()
+    structlog.configure(processors=[])
+    num_log1_processors = len(logger1.bind()._processors)
+
+    logger1 = structlog.getLogger()
+
+    assert num_log1_processors == len(logger1.bind()._processors) == 0
+
+    unpatch()
+
+
+@pytest.mark.subprocess()
+def test_reset_defaults():
+    """
+    Check if injected processor still exists after resetting to default
+    """
+    import structlog
+
+    from ddtrace.contrib.structlog import patch
+    from ddtrace.contrib.structlog import unpatch
+
+    patch()
+
+    structlog.configure()
+    logger1 = structlog.getLogger()
+    num_log1_processors = len(logger1.bind()._processors)
+
+    structlog.reset_defaults()
+
+    assert (
+        num_log1_processors == len(logger1.bind()._processors) == len(structlog._config._BUILTIN_DEFAULT_PROCESSORS) + 1
+    )
+
+    unpatch()

tests/contrib/structlog/test_structlog_patch.py

@@ -24,11 +24,17 @@ class TestStructlogPatch(PatchTestCase.Base):
     def assert_module_patched(self, structlog):
         self.assert_wrapped(structlog.get_logger)
         self.assert_wrapped(structlog.getLogger)
+        self.assert_wrapped(structlog.configure)
+        self.assert_wrapped(structlog.reset_defaults)
 
     def assert_not_module_patched(self, structlog):
         self.assert_not_wrapped(structlog.get_logger)
         self.assert_not_wrapped(structlog.getLogger)
+        self.assert_not_wrapped(structlog.configure)
+        self.assert_not_wrapped(structlog.reset_defaults)
 
     def assert_not_module_double_patched(self, structlog):
         self.assert_not_double_wrapped(structlog.get_logger)
         self.assert_not_double_wrapped(structlog.getLogger)
+        self.assert_not_double_wrapped(structlog.configure)
+        self.assert_not_double_wrapped(structlog.reset_defaults)