Repository: scoutapp/scout_apm_python
Pull request #199 (2019-07-01 09:12:53)

Implement request queue timing in Falcon
Implement #120 for this integration. This required making `track_request_queue_time` a generic function usable by all the integrations.


Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index d1f5e9d..2c0d612 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -7,6 +7,7 @@
 - Track user IP on Flask
 - Make user IP tracking on Bottle and Pyramid use the same algorithm as other
   integrations, checking for the `client-ip` header
+- Add support to Falcon integration for tracking request queue timing
 
 ### Fixed
 
diff --git a/src/scout_apm/core/queue_time.py b/src/scout_apm/core/queue_time.py
new file mode 100644
index 0000000..0f64974
--- /dev/null
+++ b/src/scout_apm/core/queue_time.py
@@ -0,0 +1,36 @@
+# coding=utf-8
+from __future__ import absolute_import, division, print_function, unicode_literals
+
+from scout_apm.compat import datetime_to_timestamp
+from scout_apm.core.util import convert_ambiguous_timestamp_to_ns
+
+
+def track_request_queue_time(header_value, tracked_request):
+    if header_value.startswith("t="):
+        header_value = header_value[2:]
+
+    try:
+        first_char = header_value[0]
+    except IndexError:
+        return
+
+    if not first_char.isdigit():  # filter out negatives, nan, inf, etc.
+        return
+
+    try:
+        ambiguous_start_timestamp = float(header_value)
+    except ValueError:
+        return
+
+    start_timestamp_ns = convert_ambiguous_timestamp_to_ns(ambiguous_start_timestamp)
+    if start_timestamp_ns == 0.0:
+        return
+
+    tr_start_timestamp_ns = datetime_to_timestamp(tracked_request.start_time) * 1e9
+
+    # Ignore if in the future
+    if start_timestamp_ns > tr_start_timestamp_ns:
+        return
+
+    queue_time_ns = int(tr_start_timestamp_ns - start_timestamp_ns)
+    tracked_request.tag("scout.queue_time_ns", queue_time_ns)
diff --git a/src/scout_apm/django/middleware.py b/src/scout_apm/django/middleware.py
index 991c356..51e25f5 100644
--- a/src/scout_apm/django/middleware.py
+++ b/src/scout_apm/django/middleware.py
@@ -3,48 +3,13 @@ from __future__ import absolute_import, division, print_function, unicode_litera
 
 import logging
 
-from scout_apm.compat import datetime_to_timestamp
 from scout_apm.core.ignore import ignore_path
+from scout_apm.core.queue_time import track_request_queue_time
 from scout_apm.core.tracked_request import TrackedRequest
-from scout_apm.core.util import convert_ambiguous_timestamp_to_ns
 
 logger = logging.getLogger(__name__)
 
 
-def track_request_queue_time(request, tracked_request):
-    header_value = request.META.get("HTTP_X_QUEUE_START") or request.META.get(
-        "HTTP_X_REQUEST_START", ""
-    )
-    if header_value.startswith("t="):
-        header_value = header_value[2:]
-
-    try:
-        first_char = header_value[0]
-    except IndexError:
-        return
-
-    if not first_char.isdigit():  # filter out negatives, nan, inf, etc.
-        return
-
-    try:
-        ambiguous_start_timestamp = float(header_value)
-    except ValueError:
-        return
-
-    start_timestamp_ns = convert_ambiguous_timestamp_to_ns(ambiguous_start_timestamp)
-    if start_timestamp_ns == 0.0:
-        return
-
-    tr_start_timestamp_ns = datetime_to_timestamp(tracked_request.start_time) * 1e9
-
-    # Ignore if in the future
-    if start_timestamp_ns > tr_start_timestamp_ns:
-        return
-
-    queue_time_ns = int(tr_start_timestamp_ns - start_timestamp_ns)
-    tracked_request.tag("scout.queue_time_ns", queue_time_ns)
-
-
 def get_operation_name(request):
     view_name = request.resolver_match._func_path
     return "Controller/" + view_name
@@ -89,7 +54,10 @@ class MiddlewareTimingMiddleware(object):
         tracked_request = TrackedRequest.instance()
 
         tracked_request.start_span(operation="Middleware")
-        track_request_queue_time(request, tracked_request)
+        queue_time = request.META.get("HTTP_X_QUEUE_START") or request.META.get(
+            "HTTP_X_REQUEST_START", ""
+        )
+        track_request_queue_time(queue_time, tracked_request)
 
         try:
             return self.get_response(request)
@@ -161,7 +129,10 @@ class OldStyleMiddlewareTimingMiddleware(object):
         tracked_request = TrackedRequest.instance()
         span = tracked_request.start_span(operation="Middleware")
         request.scout_middleware_span = span
-        track_request_queue_time(request, tracked_request)
+        queue_time = request.META.get("HTTP_X_QUEUE_START") or request.META.get(
+            "HTTP_X_REQUEST_START", ""
+        )
+        track_request_queue_time(queue_time, tracked_request)
 
     def process_response(self, request, response):
         tr = TrackedRequest.instance()
diff --git a/src/scout_apm/falcon.py b/src/scout_apm/falcon.py
index 4043dc4..10b6dde 100644
--- a/src/scout_apm/falcon.py
+++ b/src/scout_apm/falcon.py
@@ -7,6 +7,7 @@ import falcon
 
 from scout_apm.api import install
 from scout_apm.core.ignore import ignore_path
+from scout_apm.core.queue_time import track_request_queue_time
 from scout_apm.core.tracked_request import TrackedRequest
 
 logger = logging.getLogger(__name__)
@@ -48,6 +49,11 @@ class ScoutMiddleware(object):
         )
         tracked_request.tag("user_ip", user_ip)
 
+        queue_time = req.get_header("x-queue-start", default="") or req.get_header(
+            "x-request-start", default=""
+        )
+        track_request_queue_time(queue_time, tracked_request)
+
     def process_resource(self, req, resp, resource, params):
         tracked_request = getattr(req.context, "scout_tracked_request", None)
         if tracked_request is None:
diff --git a/tox.ini b/tox.ini
index bf35950..8b9f8ca 100644
--- a/tox.ini
+++ b/tox.ini
@@ -16,7 +16,7 @@ basepython =
     py35: {env:TOXPYTHON:python3.5}
     py36: {env:TOXPYTHON:python3.6}
     py37: {env:TOXPYTHON:python3.7}
-    {clean,check,report,coveralls,codecov}: {env:TOXPYTHON:python3.7}
+    {clean,check,report}: {env:TOXPYTHON:python3.7}
 setenv =
     PYTHONPATH={toxinidir}/tests
     PYTHONUNBUFFERED=yes
@@ -67,21 +67,6 @@ commands =
     flake8 src tests setup.py
     twine check {distdir}/*
 
-[testenv:coveralls]
-deps =
-    coveralls
-skip_install = true
-commands =
-    coveralls []
-
-[testenv:codecov]
-deps =
-    codecov
-skip_install = true
-commands =
-    coverage xml --ignore-errors
-    codecov []
-
 [testenv:report]
 deps = coverage
 skip_install = true


Test patch:
diff --git a/tests/conftest.py b/tests/conftest.py
index c1fdc4a..44dda66 100644
--- a/tests/conftest.py
+++ b/tests/conftest.py
@@ -106,6 +106,18 @@ def short_timeouts():
         scout_apm_core_socket.SECOND = 1
 
 
+@pytest.fixture
+def tracked_request():
+    """
+    Create a temporary tracked request for the duration of the test.
+    """
+    request = TrackedRequest.instance()
+    try:
+        yield request
+    finally:
+        request.finish()
+
+
 @pytest.fixture
 def tracked_requests():
     """
diff --git a/tests/integration/test_django.py b/tests/integration/test_django.py
index 2e95590..af0257f 100644
--- a/tests/integration/test_django.py
+++ b/tests/integration/test_django.py
@@ -3,7 +3,6 @@ from __future__ import absolute_import, division, print_function, unicode_litera
 
 import datetime as dt
 import sys
-import time
 from contextlib import contextmanager
 
 import django
@@ -358,42 +357,6 @@ def test_queue_time(header_name, tracked_requests):
     assert queue_time_ns >= 2000000000 and queue_time_ns < 4000000000
 
 
-@pytest.mark.parametrize(
-    "header_value",
-    [
-        str(""),
-        str("t=X"),  # first character not a digit
-        str("t=0.3f"),  # raises ValueError on float() conversion
-        str(datetime_to_timestamp(dt.datetime.utcnow()) + 1000.0),  # in future
-        str(datetime_to_timestamp(dt.datetime(2009, 1, 1))),  # before ambig cutoff
-    ],
-)
-def test_queue_time_invalid(header_value, tracked_requests):
-    with app_with_scout() as app:
-        response = TestApp(app).get("/", headers={"X-Queue-Start": header_value})
-
-    assert response.status_int == 200
-    assert len(tracked_requests) == 1
-    assert "scout.queue_time_ns" not in tracked_requests[0].tags
-
-
-def test_queue_time_future(tracked_requests):
-    # Not testing floats due to Python 2/3 rounding differences
-    queue_start = int(time.time() + 2)
-    with app_with_scout() as app:
-        response = TestApp(app).get(
-            "/", headers={"X-Queue-Start": str("t=") + str(queue_start)}
-        )
-
-    assert response.status_int == 200
-    assert len(tracked_requests) == 1
-    spans = tracked_requests[0].complete_spans
-    assert [s.operation for s in spans] == [
-        "Controller/tests.integration.django_app.home",
-        "Middleware",
-    ]
-
-
 @skip_unless_old_style_middleware
 @pytest.mark.parametrize("list_or_tuple", [list, tuple])
 @pytest.mark.parametrize("preinstalled", [True, False])
diff --git a/tests/integration/test_falcon.py b/tests/integration/test_falcon.py
index 1faf2e8..5d4af01 100644
--- a/tests/integration/test_falcon.py
+++ b/tests/integration/test_falcon.py
@@ -1,6 +1,7 @@
 # coding=utf-8
 from __future__ import absolute_import, division, print_function, unicode_literals
 
+import datetime as dt
 import logging
 import sys
 from contextlib import contextmanager
@@ -10,6 +11,7 @@ import pytest
 from webtest import TestApp
 
 from scout_apm.api import Config
+from scout_apm.compat import datetime_to_timestamp
 from scout_apm.falcon import ScoutMiddleware
 from tests.integration.util import parametrize_user_ip_headers
 
@@ -156,6 +158,22 @@ def test_home_ignored(tracked_requests):
     assert tracked_requests == []
 
 
+@pytest.mark.parametrize("header_name", ["X-Queue-Start", "X-Request-Start"])
+def test_queue_time(header_name, tracked_requests):
+    # Not testing floats due to Python 2/3 rounding differences
+    queue_start = int(datetime_to_timestamp(dt.datetime.utcnow()) - 2)
+    with app_with_scout() as app:
+        response = TestApp(app).get(
+            "/", headers={header_name: str("t=") + str(queue_start)}
+        )
+
+    assert response.status_int == 200
+    assert len(tracked_requests) == 1
+    queue_time_ns = tracked_requests[0].tags["scout.queue_time_ns"]
+    # Upper bound assumes we didn't take more than 2s to run this test...
+    assert queue_time_ns >= 2000000000 and queue_time_ns < 4000000000
+
+
 def test_middleware_returning_early_from_process_request(tracked_requests):
     class ShortcutMiddleware(object):
         def process_request(self, req, resp):
diff --git a/tests/unit/core/test_queue_time.py b/tests/unit/core/test_queue_time.py
new file mode 100644
index 0000000..39547e9
--- /dev/null
+++ b/tests/unit/core/test_queue_time.py
@@ -0,0 +1,39 @@
+# coding=utf-8
+from __future__ import absolute_import, division, print_function, unicode_literals
+
+import datetime as dt
+
+import pytest
+
+from scout_apm.compat import datetime_to_timestamp
+from scout_apm.core.queue_time import track_request_queue_time
+
+
+@pytest.mark.parametrize("with_t", [True, False])
+def test_track_request_queue_time_valid(with_t, tracked_request):
+    queue_start = int(datetime_to_timestamp(dt.datetime.utcnow()) - 2)
+    if with_t:
+        header_value = str("t=") + str(queue_start)
+    else:
+        header_value = str(queue_start)
+
+    track_request_queue_time(header_value, tracked_request)
+    queue_time_ns = tracked_request.tags["scout.queue_time_ns"]
+    # Upper bound assumes we didn't take more than 2s to run this test...
+    assert queue_time_ns >= 2000000000 and queue_time_ns < 4000000000
+
+
+@pytest.mark.parametrize(
+    "header_value",
+    [
+        str(""),
+        str("t=X"),  # first character not a digit
+        str("t=0.3f"),  # raises ValueError on float() conversion
+        str(datetime_to_timestamp(dt.datetime.utcnow()) + 3600.0),  # one hour in future
+        str(datetime_to_timestamp(dt.datetime(2009, 1, 1))),  # before ambig cutoff
+    ],
+)
+def test_track_request_queue_time_invalid(header_value, tracked_request):
+    track_request_queue_time(header_value, tracked_request)
+
+    assert "scout.queue_time_ns" not in tracked_request.tags