fix(internal) cdef Python exceptions being ignored (backport #3008)

ddtrace/internal/_encoding.pyx

@@ -78,7 +78,7 @@ cdef inline int pack_bytes(msgpack_packer *pk, char *bs, Py_ssize_t l):
     return ret
 
 
-cdef inline int pack_number(msgpack_packer *pk, object n):
+cdef inline int pack_number(msgpack_packer *pk, object n) except? -1:
     if n is None:
         return msgpack_pack_nil(pk)
 
@@ -101,7 +101,7 @@ cdef inline int pack_number(msgpack_packer *pk, object n):
     raise TypeError("Unhandled numeric type: %r" % type(n))
 
 
-cdef inline int pack_text(msgpack_packer *pk, object text):
+cdef inline int pack_text(msgpack_packer *pk, object text) except? -1:
     cdef Py_ssize_t L
     cdef int ret
 
@@ -422,7 +422,7 @@ cdef class MsgpackEncoderBase(BufferedEncoder):
     cdef void * get_dd_origin_ref(self, str dd_origin):
         raise NotImplementedError()
 
-    cdef inline int _pack_trace(self, list trace):
+    cdef inline int _pack_trace(self, list trace) except? -1:
         cdef int ret
         cdef Py_ssize_t L
         cdef void * dd_origin = NULL
@@ -482,7 +482,7 @@ cdef class MsgpackEncoderBase(BufferedEncoder):
     cpdef flush(self):
         raise NotImplementedError()
 
-    cdef int pack_span(self, object span, void *dd_origin):
+    cdef int pack_span(self, object span, void *dd_origin) except? -1:
         raise NotImplementedError()
 
 
@@ -496,7 +496,7 @@ cdef class MsgpackEncoderV03(MsgpackEncoderBase):
     cdef void * get_dd_origin_ref(self, str dd_origin):
         return string_to_buff(dd_origin)
 
-    cdef inline int _pack_meta(self, object meta, char *dd_origin):
+    cdef inline int _pack_meta(self, object meta, char *dd_origin) except? -1:
         cdef Py_ssize_t L
         cdef int ret
         cdef dict d
@@ -524,7 +524,7 @@ cdef class MsgpackEncoderV03(MsgpackEncoderBase):
 
         raise TypeError("Unhandled meta type: %r" % type(meta))
 
-    cdef inline int _pack_metrics(self, object metrics):
+    cdef inline int _pack_metrics(self, object metrics) except? -1:
         cdef Py_ssize_t L
         cdef int ret
         cdef dict d
@@ -546,7 +546,7 @@ cdef class MsgpackEncoderV03(MsgpackEncoderBase):
 
         raise TypeError("Unhandled metrics type: %r" % type(metrics))
 
-    cdef int pack_span(self, object span, void *dd_origin):
+    cdef int pack_span(self, object span, void *dd_origin) except? -1:
         cdef int ret
         cdef Py_ssize_t L
         cdef int has_span_type
@@ -662,7 +662,7 @@ cdef class MsgpackEncoderV05(MsgpackEncoderBase):
     cdef void * get_dd_origin_ref(self, str dd_origin):
         return <void *> PyLong_AsLong(self._st._index(dd_origin))
 
-    cdef int pack_span(self, object span, void *dd_origin):
+    cdef int pack_span(self, object span, void *dd_origin) except? -1:
         cdef int ret
 
         ret = msgpack_pack_array(&self.pk, 12)

releasenotes/notes/fix-encoding-exceptions-c12900b38741d2bf.yaml

@@ -0,0 +1,4 @@
+---
+fixes:
+  - |
+    Fix handling of Python exceptions during trace encoding. The tracer will no longer silently fail to encode invalid span data and instead log an exception.

tests/integration/test_encoding.py

@@ -5,7 +5,6 @@
 import pytest
 
 from ddtrace import Tracer
-from ddtrace.internal import agent
 
 
 AGENT_VERSION = os.environ.get("AGENT_VERSION")
@@ -64,68 +63,3 @@ def test_trace_with_metrics_accepted_by_agent(self, metrics):
             tracer.shutdown()
         log.warning.assert_not_called()
         log.error.assert_not_called()
-
-
-@pytest.mark.skipif(AGENT_VERSION == "testagent", reason="Test agent doesn't return 400 response for bad trace")
-class TestTraceRejectedByAgent:
-    def _assert_bad_trace_refused_by_agent(self, mock_log):
-        """Assert that agent refused a bad trace via log call."""
-        calls = [
-            mock.call(
-                "failed to send traces to Datadog Agent at %s: HTTP error status %s, reason %s",
-                "{}/{}/traces".format(agent.get_trace_url(), "v0.4"),
-                400,
-                "Bad Request",
-            )
-        ]
-        mock_log.error.assert_has_calls(calls)
-
-    def test_wrong_span_name_type_refused_by_agent(self):
-        """Span names should be a text type."""
-        tracer = Tracer()
-        with mock.patch("ddtrace.internal.writer.log") as log:
-            with tracer.trace(123):
-                pass
-            tracer.shutdown()
-
-        self._assert_bad_trace_refused_by_agent(log)
-
-    @pytest.mark.parametrize(
-        "meta",
-        [
-            ({"env": "my-env", "tag1": "some_str_1", "tag2": "some_str_2", "tag3": [1, 2, 3]}),
-            ({"env": "test-env", b"tag1": {"wrong_type": True}, b"tag2": "some_str_2", b"tag3": "some_str_3"}),
-            ({"env": "my-test-env", u"😐": "some_str_1", b"tag2": "some_str_2", "unicode": 12345}),
-        ],
-    )
-    def test_trace_with_wrong_meta_types_refused_by_agent(self, meta):
-        tracer = Tracer()
-        with mock.patch("ddtrace.internal.writer.log") as log:
-            with tracer.trace("root") as root:
-                root.meta = meta
-                for _ in range(499):
-                    with tracer.trace("child") as child:
-                        child.meta = meta
-            tracer.shutdown()
-
-        self._assert_bad_trace_refused_by_agent(log)
-
-    @pytest.mark.parametrize(
-        "metrics",
-        [
-            ({"num1": 12345, "num2": 53421, "num3": 1, "num4": "not-a-number"}),
-            ({b"num1": 123.45, b"num2": [1, 2, 3], b"num3": 11.0, b"num4": 1.20}),
-            ({u"😐": "123.45", b"num2": "1", "num3": {"is_number": False}, "num4": "12345"}),
-        ],
-    )
-    def test_trace_with_wrong_metrics_types_refused_by_agent(self, metrics):
-        tracer = Tracer()
-        with mock.patch("ddtrace.internal.writer.log") as log:
-            with tracer.trace("root") as root:
-                root.metrics = metrics
-                for _ in range(499):
-                    with tracer.trace("child") as child:
-                        child.metrics = metrics
-            tracer.shutdown()
-
-        self._assert_bad_trace_refused_by_agent(log)

tests/integration/test_integration_snapshots.py

@@ -1,5 +1,7 @@
+# -*- coding: utf-8 -*-
 import multiprocessing
 
+import mock
 import pytest
 
 from ddtrace import Tracer
@@ -221,3 +223,53 @@ def task2(tracer):
         p.start()
         p.join()
     tracer.shutdown()
+
+
+@snapshot()
+def test_wrong_span_name_type_not_sent():
+    """Span names should be a text type."""
+    tracer = Tracer()
+    with mock.patch("ddtrace.span.log") as log:
+        with tracer.trace(123):
+            pass
+        log.exception.assert_called_once_with("error closing trace")
+
+
+@pytest.mark.parametrize(
+    "meta",
+    [
+        ({"env": "my-env", "tag1": "some_str_1", "tag2": "some_str_2", "tag3": [1, 2, 3]}),
+        ({"env": "test-env", b"tag1": {"wrong_type": True}, b"tag2": "some_str_2", b"tag3": "some_str_3"}),
+        ({"env": "my-test-env", u"😐": "some_str_1", b"tag2": "some_str_2", "unicode": 12345}),
+    ],
+)
+@snapshot()
+def test_trace_with_wrong_meta_types_not_sent(meta):
+    tracer = Tracer()
+    with mock.patch("ddtrace.span.log") as log:
+        with tracer.trace("root") as root:
+            root.meta = meta
+            for _ in range(499):
+                with tracer.trace("child") as child:
+                    child.meta = meta
+        log.exception.assert_called_once_with("error closing trace")
+
+
+@pytest.mark.parametrize(
+    "metrics",
+    [
+        ({"num1": 12345, "num2": 53421, "num3": 1, "num4": "not-a-number"}),
+        ({b"num1": 123.45, b"num2": [1, 2, 3], b"num3": 11.0, b"num4": 1.20}),
+        ({u"😐": "123.45", b"num2": "1", "num3": {"is_number": False}, "num4": "12345"}),
+    ],
+)
+@snapshot()
+def test_trace_with_wrong_metrics_types_not_sent(metrics):
+    tracer = Tracer()
+    with mock.patch("ddtrace.span.log") as log:
+        with tracer.trace("root") as root:
+            root.metrics = metrics
+            for _ in range(499):
+                with tracer.trace("child") as child:
+                    child.metrics = metrics
+        log.exception.assert_called_once_with("error closing trace")

tests/snapshots/tests.integration.test_integration_snapshots.test_trace_with_wrong_meta_types_not_sent.json

@@ -0,0 +1 @@
+[]

tests/snapshots/tests.integration.test_integration_snapshots.test_trace_with_wrong_metrics_types_not_sent.json

@@ -0,0 +1 @@
+[]

tests/snapshots/tests.integration.test_integration_snapshots.test_wrong_span_name_type_not_sent.json

@@ -0,0 +1 @@
+[]

tests/tracer/test_encoders.py

@@ -565,3 +565,33 @@ def test_list_string_table():
     string_table_test(t)
 
     assert list(t) == ["", "foobar", "foobaz"]
+
+
+@pytest.mark.parametrize(
+    "data",
+    [
+        {"trace_id": "trace_id"},
+        {"span_id": "span_id"},
+        {"parent_id": "parent_id"},
+        {"service": True},
+        {"resource": 50},
+        {"name": [1, 2, 3]},
+        {"start_ns": "start_time"},
+        {"duration_ns": "duration_time"},
+        {"span_type": 100},
+        {"meta": {"num": 100}},
+        {"metrics": {"key": "value"}},
+    ],
+)
+def test_encoding_invalid_data(data):
+    encoder = MsgpackEncoderV03(1 << 20, 1 << 20)
+
+    span = Span(tracer=None, name="test")
+    for key, value in data.items():
+        setattr(span, key, value)
+
+    trace = [span]
+    with pytest.raises(TypeError):
+        encoder.put(trace)
+
+    assert encoder.encode() is None