Repository: scoutapp/scout_apm_python

Issue:
Rewrite exec calls
Currently the elasticsearch and pymongo instruments rely on `exec()` to create functions. This is orders of magnitude slower than using inner functions, more fragile, and prevents inspection by our code quality tools. We should rewrite to use inner functions for their generation.

Discussion:

Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 54c7186..81ea265 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -20,6 +20,8 @@
   ([PR #348](https://github.com/scoutapp/scout_apm_python/pull/348)).
 - Increase core agent socket timeout to reduce reconnections
   ([PR #247](https://github.com/scoutapp/scout_apm_python/pull/247)).
+- Fix the `RemovedInDjango20Warning` for `django.core.urlresolvers` on Django
+  1.11 ([PR #359](https://github.com/scoutapp/scout_apm_python/pull/359)).
 
 ## [2.7.0] 2019-11-03
 
diff --git a/src/scout_apm/async_/starlette.py b/src/scout_apm/async_/starlette.py
index 7670f64..0376651 100644
--- a/src/scout_apm/async_/starlette.py
+++ b/src/scout_apm/async_/starlette.py
@@ -1,6 +1,8 @@
 # coding=utf-8
 from __future__ import absolute_import, division, print_function, unicode_literals
 
+import wrapt
+from starlette.background import BackgroundTask
 from starlette.requests import Request
 
 import scout_apm.core
@@ -18,6 +20,8 @@ class ScoutMiddleware:
         self.app = app
         installed = scout_apm.core.install()
         self._do_nothing = not installed
+        if installed:
+            install_background_instrumentation()
 
     async def __call__(self, scope, receive, send):
         if self._do_nothing or scope["type"] != "http":
@@ -51,16 +55,57 @@ class ScoutMiddleware:
             amazon_queue_time = request.headers.get("x-amzn-trace-id", default="")
             track_amazon_request_queue_time(amazon_queue_time, tracked_request)
 
-        try:
-            await self.app(scope, receive, send)
-        except Exception as exc:
-            tracked_request.tag("error", "true")
-            raise exc
-        finally:
+        def rename_controller_span_from_endpoint():
             if "endpoint" in scope:
+                # Rename top span
                 endpoint = scope["endpoint"]
                 controller_span.operation = "Controller/{}.{}".format(
                     endpoint.__module__, endpoint.__qualname__
                 )
                 tracked_request.is_real_request = True
+
+        async def wrapped_send(data):
+            # Finish HTTP span when body finishes sending, not later (e.g.
+            # after background tasks)
+            if data.get("type", None) == "http.response.body" and not data.get(
+                "more_body", False
+            ):
+                rename_controller_span_from_endpoint()
+                tracked_request.stop_span()
+            return await send(data)
+
+        try:
+            await self.app(scope, receive, wrapped_send)
+        except Exception as exc:
+            tracked_request.tag("error", "true")
+            raise exc
+        finally:
+            if tracked_request.end_time is None:
+                rename_controller_span_from_endpoint()
+                tracked_request.stop_span()
+
+
+background_instrumentation_installed = False
+
+
+def install_background_instrumentation():
+    global background_instrumentation_installed
+    if background_instrumentation_installed:
+        return
+    background_instrumentation_installed = True
+
+    @wrapt.decorator
+    async def wrapped_background_call(wrapped, instance, args, kwargs):
+        tracked_request = TrackedRequest.instance()
+        tracked_request.is_real_request = True
+        tracked_request.start_span(
+            operation="Job/{}.{}".format(
+                instance.func.__module__, instance.func.__qualname__
+            )
+        )
+        try:
+            return await wrapped(*args, **kwargs)
+        finally:
             tracked_request.stop_span()
+
+    BackgroundTask.__call__ = wrapped_background_call(BackgroundTask.__call__)
diff --git a/src/scout_apm/core/tracked_request.py b/src/scout_apm/core/tracked_request.py
index 9b8bc1d..df3ed52 100644
--- a/src/scout_apm/core/tracked_request.py
+++ b/src/scout_apm/core/tracked_request.py
@@ -67,21 +67,30 @@ class TrackedRequest(object):
             )
         self.tags[key] = value
 
-    def start_span(self, *args, **kwargs):
-        maybe_parent = self.current_span()
-
-        if maybe_parent is not None:
-            parent_id = maybe_parent.span_id
-            if maybe_parent.ignore_children:
-                kwargs["ignore"] = True
-                kwargs["ignore_children"] = True
+    def start_span(
+        self,
+        operation,
+        ignore=False,
+        ignore_children=False,
+        should_capture_backtrace=True,
+    ):
+        parent = self.current_span()
+        if parent is not None:
+            parent_id = parent.span_id
+            if parent.ignore_children:
+                ignore = True
+                ignore_children = True
         else:
             parent_id = None
 
-        kwargs["parent"] = parent_id
-        kwargs["request_id"] = self.request_id
-
-        new_span = Span(**kwargs)
+        new_span = Span(
+            request_id=self.request_id,
+            operation=operation,
+            ignore=ignore,
+            ignore_children=ignore_children,
+            parent=parent_id,
+            should_capture_backtrace=should_capture_backtrace,
+        )
         self.active_spans.append(new_span)
         return new_span
 
@@ -100,7 +109,7 @@ class TrackedRequest(object):
             self.finish()
 
     def current_span(self):
-        if len(self.active_spans) > 0:
+        if self.active_spans:
             return self.active_spans[-1]
         else:
             return None
diff --git a/src/scout_apm/django/middleware.py b/src/scout_apm/django/middleware.py
index d5e205e..e10ef30 100644
--- a/src/scout_apm/django/middleware.py
+++ b/src/scout_apm/django/middleware.py
@@ -16,7 +16,7 @@ from scout_apm.core.web_requests import (
     track_request_queue_time,
 )
 
-if django.VERSION >= (2, 0):
+if django.VERSION >= (1, 11):
     from django.urls import get_urlconf
 else:
     from django.core.urlresolvers import get_urlconf
diff --git a/src/scout_apm/instruments/elasticsearch.py b/src/scout_apm/instruments/elasticsearch.py
index b255134..4450e04 100644
--- a/src/scout_apm/instruments/elasticsearch.py
+++ b/src/scout_apm/instruments/elasticsearch.py
@@ -70,11 +70,11 @@ class Instrument(object):
             logger.info("Elasticsearch instruments are not installed. Skipping.")
             return False
 
-        self.__class__.installed = False
-
         self.uninstrument_client()
         self.uninstrument_transport()
 
+        self.__class__.installed = False
+
     def instrument_client(self):
         for name in self.__class__.CLIENT_METHODS:
             method = getattr(Elasticsearch, name, None)
diff --git a/src/scout_apm/instruments/pymongo.py b/src/scout_apm/instruments/pymongo.py
index 0119895..2e53c5d 100644
--- a/src/scout_apm/instruments/pymongo.py
+++ b/src/scout_apm/instruments/pymongo.py
@@ -3,10 +3,14 @@ from __future__ import absolute_import, division, print_function, unicode_litera
 
 import logging
 
-# Used in the exec() call below.
-import wrapt  # noqa: F401
+import wrapt
 
-from scout_apm.core.tracked_request import TrackedRequest  # noqa: F401
+from scout_apm.core.tracked_request import TrackedRequest
+
+try:
+    from pymongo.collection import Collection
+except ImportError:
+    Collection = None
 
 logger = logging.getLogger(__name__)
 
@@ -49,9 +53,7 @@ class Instrument(object):
     ]
 
     def installable(self):
-        try:
-            from pymongo.collection import Collection  # noqa: F401
-        except ImportError:
+        if Collection is None:
             logger.info("Unable to import for PyMongo instruments")
             return False
         if self.installed:
@@ -66,44 +68,10 @@ class Instrument(object):
 
         self.__class__.installed = True
 
-        try:
-            from pymongo.collection import Collection  # noqa: F401
-        # There is no way the import can fail if self.installable() succeeded.
-        except ImportError:  # pragma: no cover
-            logger.info(
-                "Unable to import for PyMongo instruments. Instrument install failed."
-            )
-            return False
-
-        for method_str in self.__class__.PYMONGO_METHODS:
-            try:
-                code_str = """
-@wrapt.decorator
-def wrapped_{method_str}(wrapped, instance, args, kwargs):
-    tracked_request = TrackedRequest.instance()
-    name = '/'.join(['MongoDB', instance.name, '{camel_name}'])
-    span = tracked_request.start_span(operation=name, ignore_children=True)
-    span.tag('name', instance.name)
-
-    try:
-        return wrapped(*args, **kwargs)
-    finally:
-        tracked_request.stop_span()
-
-Collection.{method_str} = wrapped_{method_str}(Collection.{method_str})
-""".format(
-                    method_str=method_str,
-                    camel_name="".join(c.title() for c in method_str.split("_")),
-                )
-
-                exec(code_str)
-                logger.info("Instrumented PyMongo Collection.%s", method_str)
-
-            except Exception as e:
-                logger.warning(
-                    "Unable to instrument for PyMongo Collection.%s: %r", method_str, e
-                )
-                return False
+        for name in self.__class__.PYMONGO_METHODS:
+            method = getattr(Collection, name, None)
+            if method is not None:
+                setattr(Collection, name, wrap_collection_method(method))
         return True
 
     def uninstall(self):
@@ -111,9 +79,23 @@ Collection.{method_str} = wrapped_{method_str}(Collection.{method_str})
             logger.info("PyMongo instruments are not installed. Skipping.")
             return False
 
+        for name in self.__class__.PYMONGO_METHODS:
+            method = getattr(Collection, name, None)
+            if method is not None:
+                setattr(Collection, name, method.__wrapped__)
+
         self.__class__.installed = False
 
-        from pymongo.collection import Collection
 
-        for method_str in self.__class__.PYMONGO_METHODS:
-            setattr(Collection, method_str, getattr(Collection, method_str).__wrapped__)
+@wrapt.decorator
+def wrap_collection_method(wrapped, instance, args, kwargs):
+    tracked_request = TrackedRequest.instance()
+    camel_name = "".join(c.title() for c in wrapped.__name__.split("_"))
+    operation = "MongoDB/{}.{}".format(instance.name, camel_name)
+    span = tracked_request.start_span(operation=operation, ignore_children=True)
+    span.tag("name", instance.name)
+
+    try:
+        return wrapped(*args, **kwargs)
+    finally:
+        tracked_request.stop_span()


Test patch:
diff --git a/tests/integration/instruments/test_elasticsearch.py b/tests/integration/instruments/test_elasticsearch.py
index b22bfac..c2b9616 100644
--- a/tests/integration/instruments/test_elasticsearch.py
+++ b/tests/integration/instruments/test_elasticsearch.py
@@ -170,7 +170,10 @@ def test_instrument_client_install_missing_attribute():
         "scout_apm.instruments.elasticsearch.Elasticsearch"
     ) as mock_elasticsearch:
         del mock_elasticsearch.bulk
-    instrument.instrument_client()  # no crash
+    try:
+        instrument.instrument_client()  # no crash
+    finally:
+        instrument.uninstrument_client()
 
 
 @mock.patch(
diff --git a/tests/integration/instruments/test_pymongo.py b/tests/integration/instruments/test_pymongo.py
index 8204b8c..207dc90 100644
--- a/tests/integration/instruments/test_pymongo.py
+++ b/tests/integration/instruments/test_pymongo.py
@@ -9,11 +9,9 @@ import pytest
 
 from scout_apm.instruments.pymongo import Instrument
 from tests.compat import mock
-from tests.tools import pretend_package_unavailable
 
 # e.g. export MONGODB_URL="mongodb://localhost:27017/"
 MONGODB_URL = os.environ.get("MONGODB_URL")
-
 skip_if_mongodb_not_running = pytest.mark.skipif(
     MONGODB_URL is None, reason="MongoDB isn't available"
 )
@@ -57,22 +55,22 @@ def test_installable():
 
 
 def test_installable_no_pymongo_module():
-    with pretend_package_unavailable("pymongo"):
+    with mock.patch("scout_apm.instruments.pymongo.Collection", new=None):
         assert not instrument.installable()
 
 
 def test_install_no_pymongo_module():
-    with pretend_package_unavailable("pymongo"):
+    with mock.patch("scout_apm.instruments.pymongo.Collection", new=None):
         assert not instrument.install()
 
 
-@mock.patch("scout_apm.instruments.pymongo.wrapt.decorator", side_effect=RuntimeError)
-def test_install_failure(mock_decorator):
+def test_install_missing_attribute():
+    with mock.patch("scout_apm.instruments.pymongo.Collection") as mock_collection:
+        del mock_collection.aggregate
     try:
-        assert not instrument.install()  # doesn't crash
+        instrument.install()  # no crash
     finally:
-        # Currently installed = True even if installing failed.
-        Instrument.installed = False
+        instrument.uninstall()
 
 
 def test_install_is_idempotent():
diff --git a/tests/integration/test_starlette_py36plus.py b/tests/integration/test_starlette_py36plus.py
index 4f4ba77..f2fca51 100644
--- a/tests/integration/test_starlette_py36plus.py
+++ b/tests/integration/test_starlette_py36plus.py
@@ -8,6 +8,7 @@ from urllib.parse import urlencode
 import pytest
 from asgiref.testing import ApplicationCommunicator
 from starlette.applications import Starlette
+from starlette.background import BackgroundTasks
 from starlette.endpoints import HTTPEndpoint
 from starlette.responses import PlainTextResponse
 
@@ -36,6 +37,11 @@ def app_with_scout(*, scout_config=None):
 
     app = Starlette()
 
+    @app.exception_handler(500)
+    async def error(request, exc):
+        # Always raise exceptions
+        raise exc
+
     @app.route("/")
     async def home(request):
         return PlainTextResponse("Welcome home.")
@@ -49,10 +55,19 @@ def app_with_scout(*, scout_config=None):
     async def crash(request):
         raise ValueError("BØØM!")  # non-ASCII
 
-    @app.exception_handler(500)
-    async def error(request, exc):
-        # Always raise exceptions
-        raise exc
+    @app.route("/background-jobs/")
+    async def background_jobs(request):
+        def sync_noop():
+            pass
+
+        async def async_noop():
+            pass
+
+        tasks = BackgroundTasks()
+        tasks.add_task(sync_noop)
+        tasks.add_task(async_noop)
+
+        return PlainTextResponse("Triggering background jobs", background=tasks)
 
     # As per http://docs.scoutapm.com/#starlette
     Config.set(**scout_config)
@@ -283,3 +298,34 @@ async def test_unknown_asgi_scope(tracked_requests):
 
     assert response_start == {"type": "lifespan.startup.complete"}
     assert tracked_requests == []
+
+
+@async_test
+async def test_background_jobs(tracked_requests):
+    with app_with_scout() as app:
+        communicator = ApplicationCommunicator(app, get_scope(path="/background-jobs/"))
+        await communicator.send_input({"type": "http.request"})
+        response_start = await communicator.receive_output()
+        response_body = await communicator.receive_output()
+        await communicator.wait()
+
+    assert response_start["type"] == "http.response.start"
+    assert response_start["status"] == 200
+    assert response_body["body"] == b"Triggering background jobs"
+    assert len(tracked_requests) == 3
+
+    sync_tracked_request = tracked_requests[1]
+    assert len(sync_tracked_request.complete_spans) == 1
+    sync_span = sync_tracked_request.complete_spans[0]
+    assert sync_span.operation == (
+        "Job/tests.integration.test_starlette_py36plus."
+        + "app_with_scout.<locals>.background_jobs.<locals>.sync_noop"
+    )
+
+    async_tracked_request = tracked_requests[2]
+    assert len(async_tracked_request.complete_spans) == 1
+    async_span = async_tracked_request.complete_spans[0]
+    assert async_span.operation == (
+        "Job/tests.integration.test_starlette_py36plus."
+        + "app_with_scout.<locals>.background_jobs.<locals>.async_noop"
+    )
diff --git a/tests/unit/core/test_commands.py b/tests/unit/core/test_commands.py
index 66dea34..f924058 100644
--- a/tests/unit/core/test_commands.py
+++ b/tests/unit/core/test_commands.py
@@ -257,7 +257,7 @@ def test_batch_command_from_tracked_request_with_tag():
 @skip_if_objtrace_not_extension
 def test_batch_command_from_tracked_request_with_span():
     tracked_request = TrackedRequest()
-    tracked_request.start_span()
+    tracked_request.start_span("myoperation")
     tracked_request.stop_span()
     make_tracked_request_instance_deterministic(tracked_request)
 
@@ -270,7 +270,7 @@ def test_batch_command_from_tracked_request_with_span():
     }
     assert message_commands[1] == {
         "StartSpan": {
-            "operation": None,
+            "operation": "myoperation",
             "parent_id": None,
             "request_id": REQUEST_ID,
             "span_id": SPAN_ID,
@@ -321,7 +321,7 @@ def test_batch_command_from_tracked_request_with_span():
 @skip_if_objtrace_not_extension
 def test_batch_command_from_tracked_request_with_span_no_objtrace():
     tracked_request = TrackedRequest()
-    tracked_request.start_span()
+    tracked_request.start_span(operation="myoperation")
     tracked_request.stop_span()
     make_tracked_request_instance_deterministic(tracked_request)
 
@@ -334,7 +334,7 @@ def test_batch_command_from_tracked_request_with_span_no_objtrace():
     }
     assert message_commands[1] == {
         "StartSpan": {
-            "operation": None,
+            "operation": "myoperation",
             "parent_id": None,
             "request_id": REQUEST_ID,
             "span_id": SPAN_ID,
diff --git a/tests/unit/core/test_tracked_request.py b/tests/unit/core/test_tracked_request.py
index c1b5b97..5d471dc 100644
--- a/tests/unit/core/test_tracked_request.py
+++ b/tests/unit/core/test_tracked_request.py
@@ -2,6 +2,7 @@
 from __future__ import absolute_import, division, print_function, unicode_literals
 
 import datetime as dt
+import sys
 
 from scout_apm.core import objtrace
 from scout_apm.core.tracked_request import TrackedRequest
@@ -39,15 +40,19 @@ def test_tag_request_overwrite(tracked_request):
 
 
 def test_span_repr(tracked_request):
-    span = tracked_request.start_span()
-    try:
-        assert repr(span).startswith("<Span(")
-    finally:
-        tracked_request.stop_span()
+    span = tracked_request.start_span(operation="myoperation")
+    repr_ = repr(span)
+    tracked_request.stop_span()
+
+    assert repr_.startswith("<Span(")
+    if sys.version_info[0] == 2:
+        assert "operation=u'myoperation'" in repr_
+    else:
+        assert "operation='myoperation'" in repr_
 
 
 def test_tag_span(tracked_request):
-    span = tracked_request.start_span()
+    span = tracked_request.start_span(operation="myoperation")
     span.tag("foo", "bar")
     tracked_request.stop_span()
 
@@ -55,7 +60,7 @@ def test_tag_span(tracked_request):
 
 
 def test_tag_span_overwrite(tracked_request):
-    span = tracked_request.start_span()
+    span = tracked_request.start_span(operation="myoperation")
     span.tag("foo", "bar")
     span.tag("foo", "baz")
     tracked_request.stop_span()
@@ -64,8 +69,8 @@ def test_tag_span_overwrite(tracked_request):
 
 
 def test_start_span_wires_parents(tracked_request):
-    span1 = tracked_request.start_span()
-    span2 = tracked_request.start_span()
+    span1 = tracked_request.start_span(operation="myoperation")
+    span2 = tracked_request.start_span(operation="myoperation2")
     assert span1.parent is None
     assert span2.parent == span1.span_id
 
@@ -73,7 +78,7 @@ def test_start_span_wires_parents(tracked_request):
 @skip_if_objtrace_not_extension
 def test_tags_allocations_for_spans(tracked_request):
     objtrace.enable()
-    span = tracked_request.start_span()
+    span = tracked_request.start_span(operation="myoperation")
     tracked_request.stop_span()
     assert span.tags["allocations"] > 0
 
@@ -81,17 +86,17 @@ def test_tags_allocations_for_spans(tracked_request):
 @skip_if_objtrace_is_extension
 def test_tags_allocations_for_spans_no_objtrace_extension(tracked_request):
     objtrace.enable()
-    span = tracked_request.start_span()
+    span = tracked_request.start_span(operation="myoperation")
     tracked_request.stop_span()
     assert "allocations" not in span.tags
 
 
 def test_start_span_does_not_ignore_children(tracked_request):
     tracked_request.start_span(operation="parent")
-    child1 = tracked_request.start_span()
+    child1 = tracked_request.start_span(operation="myoperation")
     assert not child1.ignore
     assert not child1.ignore_children
-    child2 = tracked_request.start_span()
+    child2 = tracked_request.start_span(operation="myoperation")
     assert not child2.ignore
     assert not child2.ignore_children
     tracked_request.stop_span()
@@ -103,10 +108,10 @@ def test_start_span_does_not_ignore_children(tracked_request):
 
 def test_start_span_ignores_children(tracked_request):
     tracked_request.start_span(operation="parent", ignore_children=True)
-    child1 = tracked_request.start_span()
+    child1 = tracked_request.start_span(operation="child1")
     assert child1.ignore
     assert child1.ignore_children
-    child2 = tracked_request.start_span()
+    child2 = tracked_request.start_span(operation="child2")
     assert child2.ignore
     assert child2.ignore_children
     tracked_request.stop_span()
@@ -125,7 +130,7 @@ def test_span_captures_backtrace(tracked_request):
 
 
 def test_should_capture_backtrace_default_true(tracked_request):
-    span = tracked_request.start_span("Something")
+    span = tracked_request.start_span(operation="Something")
     # Trigger 'slow' condition
     span.start_time -= dt.timedelta(seconds=2)