Fix logging integrations for DroppedSpan spans (#602)

* Fix logging integrations for DroppedSpan spans

* Add id=None to DroppedSpan for consistency

* Add id to __slots__

Author: basepi

elasticapm/handlers/structlog.py

@@ -56,6 +56,6 @@ def structlog_processor(logger, method_name, event_dict):
     if transaction and transaction.trace_parent:
         event_dict["trace.id"] = transaction.trace_parent.trace_id
     span = execution_context.get_span()
-    if span:
+    if span and span.id:
         event_dict["span.id"] = span.id
     return event_dict

elasticapm/traces.py

@@ -446,11 +446,12 @@ def __str__(self):
 
 
 class DroppedSpan(BaseSpan):
-    __slots__ = ("leaf", "parent")
+    __slots__ = ("leaf", "parent", "id")
 
     def __init__(self, parent, leaf=False):
         self.parent = parent
         self.leaf = leaf
+        self.id = None
         super(DroppedSpan, self).__init__()
 
     def end(self, skip_frames=0, duration=None):

tests/handlers/logging/logging_tests.py

@@ -252,9 +252,8 @@ def test_arbitrary_object(logger):
     assert event["log"]["param_message"] == "['a', 'list', 'of', 'strings']"
 
 
-def test_logging_filter_no_span():
-    requests_store = Tracer(lambda: [], lambda: [], lambda *args: None, Config(), None)
-    transaction = requests_store.begin_transaction("test")
+def test_logging_filter_no_span(elasticapm_client):
+    transaction = elasticapm_client.begin_transaction("test")
     f = LoggingFilter()
     record = logging.LogRecord(__name__, logging.DEBUG, __file__, 252, "dummy_msg", [], None)
     f.filter(record)
@@ -264,19 +263,18 @@ def test_logging_filter_no_span():
     assert record.elasticapm_labels
 
 
-def test_structlog_processor_no_span():
-    requests_store = Tracer(lambda: [], lambda: [], lambda *args: None, Config(), None)
-    transaction = requests_store.begin_transaction("test")
+def test_structlog_processor_no_span(elasticapm_client):
+    transaction = elasticapm_client.begin_transaction("test")
     event_dict = {}
     new_dict = structlog_processor(None, None, event_dict)
     assert new_dict["transaction.id"] == transaction.id
     assert new_dict["trace.id"] == transaction.trace_parent.trace_id
     assert "span.id" not in new_dict
 
 
-def test_logging_filter_span():
-    requests_store = Tracer(lambda: [], lambda: [], lambda *args: None, Config(), None)
-    transaction = requests_store.begin_transaction("test")
+@pytest.mark.parametrize("elasticapm_client", [{"transaction_max_spans": 5}], indirect=True)
+def test_logging_filter_span(elasticapm_client):
+    transaction = elasticapm_client.begin_transaction("test")
     with capture_span("test") as span:
         f = LoggingFilter()
         record = logging.LogRecord(__name__, logging.DEBUG, __file__, 252, "dummy_msg", [], None)
@@ -286,26 +284,52 @@ def test_logging_filter_span():
         assert record.elasticapm_span_id == span.id
         assert record.elasticapm_labels
 
+    # Capture too many spans so we start dropping
+    for i in range(10):
+        with capture_span("drop"):
+            pass
 
-def test_structlog_processor_span():
-    requests_store = Tracer(lambda: [], lambda: [], lambda *args: None, Config(), None)
-    transaction = requests_store.begin_transaction("test")
+    # Test logging with DroppedSpan
+    with capture_span("drop") as span:
+        record = logging.LogRecord(__name__, logging.DEBUG, __file__, 252, "dummy_msg2", [], None)
+        f.filter(record)
+        assert record.elasticapm_transaction_id == transaction.id
+        assert record.elasticapm_trace_id == transaction.trace_parent.trace_id
+        assert record.elasticapm_span_id is None
+        assert record.elasticapm_labels
+
+
+@pytest.mark.parametrize("elasticapm_client", [{"transaction_max_spans": 5}], indirect=True)
+def test_structlog_processor_span(elasticapm_client):
+    transaction = elasticapm_client.begin_transaction("test")
     with capture_span("test") as span:
         event_dict = {}
         new_dict = structlog_processor(None, None, event_dict)
         assert new_dict["transaction.id"] == transaction.id
         assert new_dict["trace.id"] == transaction.trace_parent.trace_id
         assert new_dict["span.id"] == span.id
 
+    # Capture too many spans so we start dropping
+    for i in range(10):
+        with capture_span("drop"):
+            pass
+
+    # Test logging with DroppedSpan
+    with capture_span("drop") as span:
+        event_dict = {}
+        new_dict = structlog_processor(None, None, event_dict)
+        assert new_dict["transaction.id"] == transaction.id
+        assert new_dict["trace.id"] == transaction.trace_parent.trace_id
+        assert "span.id" not in new_dict
+
 
 @pytest.mark.skipif(not compat.PY3, reason="Log record factories are only 3.2+")
 def test_automatic_log_record_factory_install(elasticapm_client):
     """
     Use the elasticapm_client fixture to load the client, which in turn installs
     the log_record_factory. Check to make sure it happened.
     """
-    requests_store = Tracer(lambda: [], lambda: [], lambda *args: None, Config(), None)
-    transaction = requests_store.begin_transaction("test")
+    transaction = elasticapm_client.begin_transaction("test")
     with capture_span("test") as span:
         record_factory = logging.getLogRecordFactory()
         record = record_factory(__name__, logging.DEBUG, __file__, 252, "dummy_msg", [], None)