implement "outcome" property for transactions and spans

This implements elastic/apm#299.

Additionally, the "status_code" attribute has been added to HTTP spans.

Author: beniwohli

elasticapm/instrumentation/packages/asyncio/aiohttp_client.py

@@ -69,7 +69,12 @@ async def call(self, module, method, wrapped, instance, args, kwargs):
             headers = kwargs.get("headers") or {}
             self._set_disttracing_headers(headers, trace_parent, transaction)
             kwargs["headers"] = headers
-            return await wrapped(*args, **kwargs)
+            response = await wrapped(*args, **kwargs)
+            if response:
+                if span.context:
+                    span.context["http"]["status_code"] = response.status
+                span.set_success() if response.status < 400 else span.set_failure()
+            return response
 
     def mutate_unsampled_call_args(self, module, method, wrapped, instance, args, kwargs, transaction):
         # since we don't have a span, we set the span id to the transaction id

elasticapm/instrumentation/packages/requests.py

@@ -55,5 +55,11 @@ def call(self, module, method, wrapped, instance, args, kwargs):
             span_subtype="http",
             extra={"http": {"url": url}, "destination": destination},
             leaf=True,
-        ):
-            return wrapped(*args, **kwargs)
+        ) as span:
+            response = wrapped(*args, **kwargs)
+            # requests.Response objects are falsy if status code > 400, so we have to check for None instead
+            if response is not None:
+                if span.context:
+                    span.context["http"]["status_code"] = response.status_code
+                span.set_success() if response.status_code < 400 else span.set_failure()
+            return response

elasticapm/instrumentation/packages/urllib.py

@@ -96,7 +96,12 @@ def call(self, module, method, wrapped, instance, args, kwargs):
                 span_id=parent_id, trace_options=TracingOptions(recorded=True)
             )
             self._set_disttracing_headers(request_object, trace_parent, transaction)
-            return wrapped(*args, **kwargs)
+            response = wrapped(*args, **kwargs)
+            if response:
+                if span.context:
+                    span.context["http"]["status_code"] = response.status
+                span.set_success() if response.status < 400 else span.set_failure()
+            return response
 
     def mutate_unsampled_call_args(self, module, method, wrapped, instance, args, kwargs, transaction):
         request_object = args[1] if len(args) > 1 else kwargs["req"]

elasticapm/instrumentation/packages/urllib3.py

@@ -95,7 +95,12 @@ def call(self, module, method, wrapped, instance, args, kwargs):
                     span_id=parent_id, trace_options=TracingOptions(recorded=True)
                 )
                 self._set_disttracing_headers(headers, trace_parent, transaction)
-            return wrapped(*args, **kwargs)
+            response = wrapped(*args, **kwargs)
+            if response:
+                if span.context:
+                    span.context["http"]["status_code"] = response.status
+                span.set_success() if response.status < 400 else span.set_failure()
+            return response
 
     def mutate_unsampled_call_args(self, module, method, wrapped, instance, args, kwargs, transaction):
         # since we don't have a span, we set the span id to the transaction id

elasticapm/traces.py

@@ -88,6 +88,7 @@ class BaseSpan(object):
     def __init__(self, labels=None):
         self._child_durations = ChildDuration(self)
         self.labels = {}
+        self.outcome = "unknown"
         if labels:
             self.label(**labels)
 
@@ -132,6 +133,12 @@ def tag(self, **tags):
         for key in tags.keys():
             self.labels[LABEL_RE.sub("_", compat.text_type(key))] = encoding.keyword_field(compat.text_type(tags[key]))
 
+    def set_success(self):
+        self.outcome = "success"
+
+    def set_failure(self):
+        self.outcome = "failure"
+
 
 class Transaction(BaseSpan):
     def __init__(self, tracer, transaction_type="custom", trace_parent=None, is_sampled=True, start=None):
@@ -176,6 +183,10 @@ def end(self, skip_frames=0, duration=None):
                 reset_on_collect=True,
                 **{"transaction.name": self.name, "transaction.type": self.transaction_type}
             ).update(self.duration)
+        if self.outcome == "unknown" and self.context:
+            status_code = self.context.get("response", {}).get("status_code", None)
+            if isinstance(status_code, int):
+                self.outcome = "success" if status_code < 500 else "failure"
         if self._breakdown:
             for (span_type, span_subtype), timer in compat.iteritems(self._span_timers):
                 labels = {
@@ -274,17 +285,22 @@ def begin_span(
             start=start,
         )
 
-    def end_span(self, skip_frames=0, duration=None):
+    def end_span(self, skip_frames=0, duration=None, outcome=None):
         """
         End the currently active span
         :param skip_frames: numbers of frames to skip in the stack trace
         :param duration: override duration, mostly useful for testing
+        :param outcome: outcome of the span, either success, failure or unknown
         :return: the ended span
         """
         span = execution_context.get_span()
         if span is None:
             raise LookupError()
 
+        # only overwrite span outcome if it is still unknown
+        if span.outcome == "unknown":
+            span.outcome = outcome
+
         span.end(skip_frames=skip_frames, duration=duration)
         return span
 
@@ -309,6 +325,7 @@ def to_dict(self):
             "duration": self.duration * 1000,  # milliseconds
             "result": encoding.keyword_field(str(self.result)),
             "timestamp": int(self.timestamp * 1000000),  # microseconds
+            "outcome": self.outcome,
             "sampled": self.is_sampled,
             "span_count": {"started": self._span_counter - self.dropped_spans, "dropped": self.dropped_spans},
         }
@@ -346,6 +363,7 @@ class Span(BaseSpan):
         "frames",
         "labels",
         "sync",
+        "outcome",
         "_child_durations",
     )
 
@@ -423,6 +441,7 @@ def to_dict(self):
             "action": encoding.keyword_field(self.action),
             "timestamp": int(self.timestamp * 1000000),  # microseconds
             "duration": self.duration * 1000,  # milliseconds
+            "outcome": self.outcome,
         }
         if self.sync is not None:
             result["sync"] = self.sync
@@ -512,6 +531,14 @@ def action(self):
     def context(self):
         return None
 
+    @property
+    def outcome(self):
+        return "unknown"
+
+    @outcome.setter
+    def outcome(self, value):
+        return
+
 
 class Tracer(object):
     def __init__(self, frames_collector_func, frames_processing_func, queue_func, config, agent):
@@ -663,7 +690,8 @@ def __exit__(self, exc_type, exc_val, exc_tb):
 
         if transaction and transaction.is_sampled:
             try:
-                span = transaction.end_span(self.skip_frames, duration=self.duration)
+                outcome = "failure" if exc_val else "success"
+                span = transaction.end_span(self.skip_frames, duration=self.duration, outcome=outcome)
                 if exc_val and not isinstance(span, DroppedSpan):
                     try:
                         exc_val._elastic_apm_span_id = span.id

tests/contrib/django/django_tests.py

@@ -757,6 +757,28 @@ def test_transaction_metrics(django_elasticapm_client, client):
         assert transaction["duration"] > 0
         assert transaction["result"] == "HTTP 2xx"
         assert transaction["name"] == "GET tests.contrib.django.testapp.views.no_error"
+        assert transaction["outcome"] == "success"
+
+
+def test_transaction_metrics_error(django_elasticapm_client, client):
+    with override_settings(
+        **middleware_setting(django.VERSION, ["elasticapm.contrib.django.middleware.TracingMiddleware"])
+    ):
+        assert len(django_elasticapm_client.events[TRANSACTION]) == 0
+        try:
+            client.get(reverse("elasticapm-http-error", args=(500,)))
+        except Exception:
+            pass
+        assert len(django_elasticapm_client.events[TRANSACTION]) == 1
+
+        transactions = django_elasticapm_client.events[TRANSACTION]
+
+        assert len(transactions) == 1
+        transaction = transactions[0]
+        assert transaction["duration"] > 0
+        assert transaction["result"] == "HTTP 5xx"
+        assert transaction["name"] == "GET tests.contrib.django.testapp.views.http_error"
+        assert transaction["outcome"] == "failure"
 
 
 def test_transaction_metrics_debug(django_elasticapm_client, client):

tests/contrib/django/testapp/urls.py

@@ -49,6 +49,7 @@ def handler500(request):
     url(r"^render-user-template$", views.render_user_view, name="render-user-template"),
     url(r"^no-error$", views.no_error, name="elasticapm-no-error"),
     url(r"^no-error-slash/$", views.no_error, name="elasticapm-no-error-slash"),
+    url(r"^http-error/(?P<status>[0-9]{3})$", views.http_error, name="elasticapm-http-error"),
     url(r"^logging$", views.logging_view, name="elasticapm-logging"),
     url(r"^ignored-exception/$", views.ignored_exception, name="elasticapm-ignored-exception"),
     url(r"^fake-login$", views.fake_login, name="elasticapm-fake-login"),

tests/contrib/django/testapp/views.py

@@ -55,6 +55,13 @@ def no_error(request, id=None):
     return resp
 
 
+def http_error(request, status=None):
+    if status:
+        status = int(status)
+    resp = HttpResponse(status=status)
+    return resp
+
+
 def fake_login(request):
     return HttpResponse("")
 

tests/instrumentation/asyncio/aiohttp_client_tests.py

@@ -62,11 +62,44 @@ async def test_http_get(instrument, event_loop, elasticapm_client, waiting_https
     assert span["subtype"] == "http"
     assert span["sync"] is False
     assert span["context"]["http"]["url"] == waiting_httpserver.url
+    assert span["context"]["http"]["status_code"] == 200
     assert spans[0]["context"]["destination"]["service"] == {
         "name": "http://127.0.0.1:%d" % waiting_httpserver.server_address[1],
         "resource": "127.0.0.1:%d" % waiting_httpserver.server_address[1],
         "type": "external",
     }
+    assert spans[0]["outcome"] == "success"
+
+
+@pytest.mark.parametrize("status_code", [400, 500])
+async def test_http_get_error(instrument, event_loop, elasticapm_client, waiting_httpserver, status_code):
+    assert event_loop.is_running()
+    elasticapm_client.begin_transaction("test")
+    waiting_httpserver.serve_content("", code=status_code)
+    url = waiting_httpserver.url
+
+    async with aiohttp.ClientSession() as session:
+        async with session.get(waiting_httpserver.url) as resp:
+            status = resp.status
+            text = await resp.text()
+
+    elasticapm_client.end_transaction()
+    transaction = elasticapm_client.events[constants.TRANSACTION][0]
+    spans = elasticapm_client.spans_for_transaction(transaction)
+    assert len(spans) == 1
+    span = spans[0]
+    assert span["name"] == "GET %s:%s" % waiting_httpserver.server_address
+    assert span["type"] == "external"
+    assert span["subtype"] == "http"
+    assert span["sync"] is False
+    assert span["context"]["http"]["url"] == waiting_httpserver.url
+    assert span["context"]["http"]["status_code"] == status_code
+    assert spans[0]["context"]["destination"]["service"] == {
+        "name": "http://127.0.0.1:%d" % waiting_httpserver.server_address[1],
+        "resource": "127.0.0.1:%d" % waiting_httpserver.server_address[1],
+        "type": "external",
+    }
+    assert spans[0]["outcome"] == "failure"
 
 
 @pytest.mark.parametrize(

tests/instrumentation/base_tests.py

@@ -38,7 +38,7 @@
 
 import elasticapm
 from elasticapm.conf import constants
-from elasticapm.conf.constants import SPAN
+from elasticapm.conf.constants import SPAN, TRANSACTION
 from elasticapm.instrumentation.packages.base import AbstractInstrumentedModule
 from elasticapm.utils import compat, wrapt
 
@@ -193,3 +193,19 @@ def test_end_nonexisting_span(caplog, elasticapm_client):
     elasticapm_client.end_transaction("test", "")
     record = caplog.records[0]
     assert record.args == ("test_name", "test_type")
+
+
+def test_outcome_by_span_exception(elasticapm_client):
+    elasticapm_client.begin_transaction("test")
+    try:
+        with elasticapm.capture_span("fail", "test_type"):
+            assert False
+    except AssertionError:
+        pass
+    with elasticapm.capture_span("success", "test_type"):
+        pass
+    elasticapm_client.end_transaction("test")
+    transactions = elasticapm_client.events[TRANSACTION]
+    spans = elasticapm_client.spans_for_transaction(transactions[0])
+    assert spans[0]["name"] == "fail" and spans[0]["outcome"] == "failure"
+    assert spans[1]["name"] == "success" and spans[1]["outcome"] == "success"