log error when trying to end a span that hasn't started (#229)

Usually, this shouldn't happen and is an indication of a bug. But we
should still ensure that we don't crash and instead log a message.

fixes #227
closes #229

Co-authored-by: goodspeed <[email protected]>

Author: beniwohli

elasticapm/traces.py

@@ -268,7 +268,10 @@ def __enter__(self):
     def __exit__(self, exc_type, exc_val, exc_tb):
         transaction = get_transaction()
         if transaction and transaction.is_sampled:
-            transaction.end_span(self.skip_frames)
+            try:
+                transaction.end_span(self.skip_frames)
+            except IndexError:
+                error_logger.info('ended non-existing span %s of type %s', self.name, self.type)
 
 
 def tag(**tags):

tests/instrumentation/base_tests.py

@@ -1,4 +1,5 @@
 # -*- coding: utf-8 -*-
+import logging
 import types
 
 import mock
@@ -110,3 +111,16 @@ def test_skip_ignored_frames(elasticapm_client):
     transaction = elasticapm_client.end_transaction('test', 'test')
     for frame in transaction.spans[0].frames:
         assert not frame['module'].startswith('elasticapm')
+
+
+def test_end_nonexisting_span(caplog, elasticapm_client):
+    with caplog.at_level(logging.INFO):
+        t = elasticapm_client.begin_transaction('test')
+        # we're purposefully creating a case where we don't begin a span
+        # and then try to end the non-existing span
+        t.is_sampled = False
+        with elasticapm.capture_span('test_name', 'test_type'):
+            t.is_sampled = True
+    elasticapm_client.end_transaction('test', '')
+    record = caplog.records[0]
+    assert record.args == ('test_name', 'test_type')