chore(logging): remove log correlation attributes from ddtrace loggers [Take 2] [backport 3.16] (#15043)

Backport c1a6758 from #15036 to 3.16.

Reverts #15027
Fixes failing test and suitespec:
https://gitlab.ddbuild.io/DataDog/apm-reliability/dd-trace-py/-/pipelines/80160879

Co-authored-by: Munir Abdinur <[email protected]>

Author: dd-octo-sts[bot]

ddtrace/_logger.py

@@ -110,14 +110,6 @@ def _add_file_handler(
     return ddtrace_file_handler
 
 
-def set_log_formatting():
-    # type: () -> None
-    """Sets the log format for the ddtrace logger."""
-    ddtrace_logger = logging.getLogger("ddtrace")
-    for handler in ddtrace_logger.handlers:
-        handler.setFormatter(logging.Formatter(DD_LOG_FORMAT))
-
-
 def get_log_injection_state(raw_config: Optional[str]) -> bool:
     """Returns the current log injection state."""
     if raw_config:

ddtrace/contrib/internal/logging/patch.py

@@ -5,7 +5,6 @@
 
 import ddtrace
 from ddtrace import config
-from ddtrace._logger import set_log_formatting
 from ddtrace.contrib.internal.trace_utils import unwrap as _u
 from ddtrace.internal.constants import LOG_ATTR_ENV
 from ddtrace.internal.constants import LOG_ATTR_SERVICE
@@ -100,13 +99,6 @@ def patch():
     _w(logging.Logger, "makeRecord", _w_makeRecord)
     _w(logging.StrFormatStyle, "_format", _w_StrFormatStyle_format)
 
-    if config._logs_injection:
-        # Only set the formatter is DD_LOGS_INJECTION is set to True. We do not want to modify
-        # unstructured logs if a user has not enabled logs injection.
-        # Also, the Datadog log format must be set after the logging module has been patched,
-        # otherwise the formatter will raise an exception.
-        set_log_formatting()
-
 
 def unpatch():
     if getattr(logging, "_datadog_patch", False):

releasenotes/notes/remove-set-log-formatting-a8b9c7d2e1f3g4h5.yaml

@@ -0,0 +1,5 @@
+---
+fixes:
+  - |
+    logging: Fixed ddtrace internal logging when trace-log correlation is disabled. 
+    Prevents ``ValueError: Formatting field not found in record: 'dd.service'``.

tests/commands/ddtrace_run_logs_injection.py

@@ -1,17 +1,28 @@
+from io import StringIO
+import json
 import logging
 
 
+class JSONFormatter(logging.Formatter):
+    """Custom formatter that outputs log records as JSON."""
+
+    def format(self, record):
+        return json.dumps({k: str(v) for k, v in record.__dict__.items()})
+
+
 if __name__ == "__main__":
-    # Ensure if module is patched then default log formatter is set up for logs
-    ddtrace_logger = logging.getLogger("ddtrace")
-    if logging._datadog_patch:
-        assert (
-            "[dd.service=%(dd.service)s dd.env=%(dd.env)s dd.version=%(dd.version)s"
-            " dd.trace_id=%(dd.trace_id)s dd.span_id=%(dd.span_id)s]" in ddtrace_logger.handlers[0].formatter._fmt
-        )
-    else:
-        assert (
-            "[dd.service=%(dd.service)s dd.env=%(dd.env)s dd.version=%(dd.version)s"
-            " dd.trace_id=%(dd.trace_id)s dd.span_id=%(dd.span_id)s]" not in ddtrace_logger.handlers[0].formatter._fmt
-        )
+    log_capture_string = StringIO()
+    handler = logging.StreamHandler(log_capture_string)
+    handler.setLevel(logging.INFO)
+    handler.setFormatter(JSONFormatter())
+
+    logger = logging.getLogger("ddtrace")
+    logger.addHandler(handler)
+    logger.setLevel(logging.INFO)
+    logger.info("Test log message")
+
+    json_contents = json.loads(log_capture_string.getvalue().strip())
+    assert json_contents.get("dd.service") == "my-service"
+    assert json_contents.get("dd.env") == "my-env"
+    assert json_contents.get("dd.version") == "my-version"
     print("Test success")

tests/commands/test_runner.py

@@ -212,7 +212,7 @@ def test_global_trace_tags(self):
 
     def test_logs_injection(self):
         """Ensure logs injection works"""
-        with self.override_env(dict(DD_LOGS_INJECTION="true")):
+        with self.override_env(dict(DD_TAGS="service:my-service,env:my-env,version:my-version")):
             out = subprocess.check_output(["ddtrace-run", "python", "tests/commands/ddtrace_run_logs_injection.py"])
             assert out.startswith(b"Test success"), out.decode()
 

tests/integration/test_integration.py

@@ -807,8 +807,8 @@ def test_logging_during_tracer_init_succeeds_when_debug_logging_and_logs_injecti
     assert out == b"", "an empty program should generate no logs under ddtrace-run"
 
     assert (
-        b"[dd.service=ddtrace_subprocess_dir dd.env= dd.version= dd.trace_id=0 dd.span_id=0]" in err
-    ), "stderr should contain debug output when DD_TRACE_DEBUG is set"
+        b"[dd.service=ddtrace_subprocess_dir dd.env= dd.version= dd.trace_id=0 dd.span_id=0]" not in err
+    ), "stderr should not contain debug output when DD_TRACE_DEBUG is set"
 
     assert b"KeyError: 'dd.service'" not in err, "stderr should not contain any exception logs"
     assert (

tests/suitespec.yml

@@ -55,6 +55,7 @@ components:
     - ddtrace/internal/gitmetadata.py
     - ddtrace/internal/glob_matching.py
     - ddtrace/internal/logger.py
+    - ddtrace/_logger.py
     - ddtrace/internal/hostname.py
     - ddtrace/internal/http.py
     - ddtrace/internal/bytecode_injection/*