Add option to log payloads on error response from the trace agent

Adding new environment variable `_DD_TRACE_WRITER_LOG_ERROR_PAYLOADS`
which when enabled will update the existing "failed to send traces to Datadog agent" log message
to include the payload.

Author: brettlangdon

ddtrace/internal/writer.py

@@ -1,4 +1,5 @@
 import abc
+import binascii
 from collections import defaultdict
 from json import loads
 import logging
@@ -22,6 +23,7 @@
 from ..constants import KEEP_SPANS_RATE_KEY
 from ..sampler import BasePrioritySampler
 from ..sampler import BaseSampler
+from ..utils.formats import asbool
 from ..utils.formats import get_env
 from ..utils.formats import parse_tags_str
 from ..utils.time import StopWatch
@@ -300,6 +302,7 @@ def __init__(
             stop=tenacity.stop_after_attempt(self.RETRY_ATTEMPTS),
             retry=tenacity.retry_if_exception_type((compat.httplib.HTTPException, OSError, IOError)),
         )
+        self._log_error_payloads = asbool(os.environ.get("_DD_TRACE_WRITER_LOG_ERROR_PAYLOADS", False))
 
     def _metrics_dist(self, name, count=1, tags=None):
         self._metrics[name]["count"] += count
@@ -407,12 +410,22 @@ def _send_payload(self, payload, count):
                 if payload is not None:
                     self._send_payload(payload, count)
         elif response.status >= 400:
-            log.error(
-                "failed to send traces to Datadog Agent at %s: HTTP error status %s, reason %s",
+            msg = "failed to send traces to Datadog Agent at %s: HTTP error status %s, reason %s"
+            log_args = (
                 self.agent_url,
                 response.status,
                 response.reason,
             )
+            # Append the payload if requested
+            if self._log_error_payloads:
+                msg += ", payload %s"
+                # If the payload is bytes then hex encode the value before logging
+                if isinstance(payload, six.binary_type):
+                    log_args += (binascii.hexlify(payload).decode(),)
+                else:
+                    log_args += (payload,)
+
+            log.error(msg, *log_args)
             self._metrics_dist("http.dropped.bytes", len(payload))
             self._metrics_dist("http.dropped.traces", count)
         elif self._priority_sampler or isinstance(self._sampler, BasePrioritySampler):

tests/integration/test_integration.py

@@ -393,6 +393,84 @@ def encode_traces(self, traces):
     log.error.assert_has_calls(calls)
 
 
+@pytest.mark.skipif(AGENT_VERSION == "testagent", reason="FIXME: Test agent response is different.")
+def test_bad_payload_log_payload(monkeypatch):
+    monkeypatch.setenv("_DD_TRACE_WRITER_LOG_ERROR_PAYLOADS", "true")
+    t = Tracer()
+
+    class BadEncoder:
+        def __len__(self):
+            return 0
+
+        def put(self, trace):
+            pass
+
+        def encode(self):
+            return b"bad_payload"
+
+        def encode_traces(self, traces):
+            return b"bad_payload"
+
+    t.writer._encoder = BadEncoder()
+    with mock.patch("ddtrace.internal.writer.log") as log:
+        t.trace("asdf").finish()
+        t.shutdown()
+    calls = [
+        mock.call(
+            "failed to send traces to Datadog Agent at %s: HTTP error status %s, reason %s, payload %s",
+            "http://localhost:8126",
+            400,
+            "Bad Request",
+            "6261645f7061796c6f6164",
+        )
+    ]
+    log.error.assert_has_calls(calls)
+
+
+@pytest.mark.skipif(AGENT_VERSION == "testagent", reason="FIXME: Test agent response is different.")
+def test_bad_payload_log_payload_non_bytes(monkeypatch):
+    monkeypatch.setenv("_DD_TRACE_WRITER_LOG_ERROR_PAYLOADS", "true")
+    t = Tracer()
+
+    class BadEncoder:
+        def __len__(self):
+            return 0
+
+        def put(self, trace):
+            pass
+
+        def encode(self):
+            # Python 2.7
+            # >>> isinstance("", bytes)
+            # True
+            # >>> isinstance(u"", bytes)
+            # False
+            # Python 3
+            # >>> isinstance("", bytes)
+            # False
+            # >>> isinstance(u"", bytes)
+            # False
+            return u"bad_payload"
+
+        def encode_traces(self, traces):
+            return u"bad_payload"
+
+    t.writer._encoder = BadEncoder()
+    with mock.patch("ddtrace.internal.writer.log") as log:
+        t.trace("asdf").finish()
+        t.shutdown()
+    calls = [
+        mock.call(
+            "failed to send traces to Datadog Agent at %s: HTTP error status %s, reason %s, payload %s",
+            "http://localhost:8126",
+            400,
+            "Bad Request",
+            "bad_payload",
+        )
+    ]
+    log.error.assert_has_calls(calls)
+
+
 def test_bad_encoder():
     t = Tracer()