From 62d55d43501e624b9b0cfa02e3a8dc34df895e7a Mon Sep 17 00:00:00 2001 From: Tim Schilling Date: Wed, 26 May 2021 19:27:42 -0500 Subject: [PATCH 1/4] Monitor errors via got_request_exception signal. The middleware process_exception would only allow us to track exceptions thrown in views, that weren't picked up by an earlier middleware that returned a result. This solution allows us to track exceptions that occur anywhere in the application. The downside to this is that it's possible if another receiver of got_request_exception throws a new exception, our handler may get the wrong exception with sys.exc_info(). We could limit the scope of that issue by injecting a middleware that's as far down the list as possible to wrap the view and catch exceptions there. Then rely on the signal handler for catching exceptions in the middleware. Create ErrorServiceThread to buffer error messages. Implement buffering logic, write integration tests for error_service. Exclude specific libraries' logs from caplog. Some of our checks are positional based, but have the chance of triggering a libraries own debug statements. For cases we know we can ignore, we can add them to the filter to make the tests more robust. Expose a configurable API and ErrorMonitor interface. Support Celery for the error monitoring solution. Custom params belong on the context. Celery's custom params go into a celery key of custom params. Custom controller overrides the request_component's controller. --- CHANGELOG.md | 3 + setup.py | 1 + src/scout_apm/api/__init__.py | 52 +++++ src/scout_apm/celery.py | 64 +++++- src/scout_apm/compat.py | 19 ++ src/scout_apm/core/__init__.py | 24 ++- src/scout_apm/core/backtrace.py | 35 +-- src/scout_apm/core/config.py | 4 + src/scout_apm/core/error.py | 76 +++++++ src/scout_apm/core/error_service.py | 152 +++++++++++++ src/scout_apm/core/web_requests.py | 71 +++++-- src/scout_apm/django/apps.py | 33 +++ src/scout_apm/django/middleware.py | 101 +-------- src/scout_apm/django/request.py | 149 +++++++++++++ src/scout_apm/instruments/urllib3.py | 5 + tests/compat.py | 18 +- tests/conftest.py | 64 ++++++ tests/integration/core/agent/test_socket.py | 2 +- tests/integration/core/test_error_service.py | 134 ++++++++++++ tests/integration/django_app.py | 17 ++ tests/integration/instruments/test_urllib3.py | 15 ++ tests/integration/test_api.py | 67 ++++++ tests/integration/test_celery.py | 95 ++++++++- tests/integration/test_django.py | 200 ++++++++++++++++++ tests/unit/core/test_backtrace.py | 24 +++ tests/unit/core/test_error.py | 196 +++++++++++++++++ tests/unit/core/test_web_requests.py | 21 ++ 27 files changed, 1507 insertions(+), 135 deletions(-) create mode 100644 src/scout_apm/core/error.py create mode 100644 src/scout_apm/core/error_service.py create mode 100644 src/scout_apm/django/request.py create mode 100644 tests/integration/core/test_error_service.py create mode 100644 tests/unit/core/test_error.py diff --git a/CHANGELOG.md b/CHANGELOG.md index e05f694f..e8da855c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,9 @@ ## Pending ### Added +- Support Error Monitoring. See + [integration docs](https://scoutapm.com/docs/python/error-monitoring). + ([PR #651](https://github.com/scoutapp/scout_apm_python/pull/651)) ### Fixed - Setup metadata keywords now contains an array of strings. diff --git a/setup.py b/setup.py index 3e3e28f3..23b57432 100644 --- a/setup.py +++ b/setup.py @@ -67,6 +67,7 @@ 'urllib3[secure] < 1.25 ; python_version < "3.5"', 'urllib3[secure] < 2 ; python_version >= "3.5"', "wrapt>=1.10,<2.0", + "requests", ], keywords=["apm", "performance monitoring", "development"], classifiers=[ diff --git a/src/scout_apm/api/__init__.py b/src/scout_apm/api/__init__.py index 2fc44b16..6be73aba 100644 --- a/src/scout_apm/api/__init__.py +++ b/src/scout_apm/api/__init__.py @@ -1,9 +1,12 @@ # coding=utf-8 from __future__ import absolute_import, division, print_function, unicode_literals +import sys + import scout_apm.core from scout_apm.compat import ContextDecorator, text from scout_apm.core.config import ScoutConfig +from scout_apm.core.error import ErrorMonitor from scout_apm.core.tracked_request import TrackedRequest # The async_ module can only be shipped on Python 3.6+ @@ -19,6 +22,7 @@ class AsyncDecoratorMixin(object): "BackgroundTransaction", "Config", "Context", + "Error", "WebTransaction", "install", "instrument", @@ -143,3 +147,51 @@ def rename_transaction(name): if name is not None: tracked_request = TrackedRequest.instance() tracked_request.tag("transaction.name", name) + + +class Error(object): + @classmethod + def capture( + cls, + exception, + request_path=None, + request_params=None, + session=None, + custom_controller=None, + custom_params=None, + ): + """ + Capture the exception manually. + + Utilizes sys.exc_info to gather the traceback. This has the side + effect that if another exception is raised before calling + ``Error.capture``, the traceback will match the most recently + raised exception. + + Includes any context added for the TrackedRequest. + + :exception: Any exception. + :request_path: Any String identifying the relative path of the request. + Example: "/hello-world/" + :request_params: Any json-serializable dict representing the + querystring parameters. + Example: {"page": 1} + :session: Any json-serializable dict representing the + request session. + Example: {"step": 0} + :custom_controller: Any String identifying the controller or job. + Example: "send_email" + :custom_params: Any json-serializable dict. + Example: {"to": "scout@test.com", "from": "no-reply@test.com"} + :returns: nothing. + """ + if isinstance(exception, Exception): + exc_info = (exception.__class__, exception, sys.exc_info()[2]) + ErrorMonitor.send( + exc_info, + request_path=request_path, + request_params=request_params, + session=session, + custom_controller=custom_controller, + custom_params=custom_params, + ) diff --git a/src/scout_apm/celery.py b/src/scout_apm/celery.py index 1512b293..362f54e3 100644 --- a/src/scout_apm/celery.py +++ b/src/scout_apm/celery.py @@ -2,14 +2,34 @@ from __future__ import absolute_import, division, print_function, unicode_literals import datetime as dt +import logging from celery.signals import before_task_publish, task_failure, task_postrun, task_prerun +try: + import django + + if django.VERSION < (3, 1): + from django.views.debug import get_safe_settings + else: + from django.views.debug import SafeExceptionReporterFilter + + def get_safe_settings(): + return SafeExceptionReporterFilter().get_safe_settings() + + +except ImportError: + # Django not installed + get_safe_settings = None + import scout_apm.core from scout_apm.compat import datetime_to_timestamp from scout_apm.core.config import scout_config +from scout_apm.core.error import ErrorMonitor from scout_apm.core.tracked_request import TrackedRequest +logger = logging.getLogger(__name__) + def before_task_publish_callback(headers=None, properties=None, **kwargs): if "scout_task_start" not in headers: @@ -52,10 +72,52 @@ def task_postrun_callback(task=None, **kwargs): tracked_request.stop_span() -def task_failure_callback(task_id=None, **kwargs): +def task_failure_callback( + sender, + task_id=None, + exception=None, + args=None, + kwargs=None, + traceback=None, + **remaining +): tracked_request = TrackedRequest.instance() tracked_request.tag("error", "true") + custom_controller = sender.name + custom_params = { + "celery": { + "task_id": task_id, + "args": args, + "kwargs": kwargs, + } + } + + # Look up the django settings if populated. + environment = None + if get_safe_settings: + try: + environment = get_safe_settings() + except django.core.exceptions.ImproperlyConfigured as exc: + # Django not setup correctly + logger.debug( + "Celery integration does not have django configured properly: %r", exc + ) + pass + except Exception as exc: + logger.debug( + "Celery task_failure callback exception: %r", exc, exc_info=exc + ) + pass + + exc_info = (exception.__class__, exception, traceback) + ErrorMonitor.send( + exc_info, + environment=environment, + custom_params=custom_params, + custom_controller=custom_controller, + ) + def install(app=None): if app is not None: diff --git a/src/scout_apm/compat.py b/src/scout_apm/compat.py index 6d96b827..cae96815 100644 --- a/src/scout_apm/compat.py +++ b/src/scout_apm/compat.py @@ -2,6 +2,7 @@ from __future__ import absolute_import, division, print_function, unicode_literals import datetime as dt +import gzip import inspect import sys from functools import wraps @@ -151,9 +152,27 @@ def urllib3_cert_pool_manager(**kwargs): return urllib3.PoolManager(cert_reqs=CERT_REQUIRED, ca_certs=certifi.where()) +if sys.version_info >= (3, 2): + + def gzip_compress(data): + return gzip.compress(data) + + +else: + import io + + def gzip_compress(data): + """Reimplementation gzip.compress for python 2.7""" + buf = io.BytesIO() + with gzip.GzipFile(fileobj=buf, mode="wb") as f: + f.write(data) + return buf.getvalue() + + __all__ = [ "ContextDecorator", "datetime_to_timestamp", + "gzip_compress", "kwargs_only", "parse_qsl", "queue", diff --git a/src/scout_apm/core/__init__.py b/src/scout_apm/core/__init__.py index df0eb33b..d391127d 100644 --- a/src/scout_apm/core/__init__.py +++ b/src/scout_apm/core/__init__.py @@ -12,6 +12,7 @@ from scout_apm.core.agent.manager import CoreAgentManager from scout_apm.core.agent.socket import CoreAgentSocketThread from scout_apm.core.config import scout_config +from scout_apm.core.error_service import ErrorServiceThread from scout_apm.core.metadata import report_app_metadata logger = logging.getLogger(__name__) @@ -61,7 +62,7 @@ def install(config=None): def shutdown(): timeout_seconds = scout_config.value("shutdown_timeout_seconds") - def callback(queue_size): + def apm_callback(queue_size): if scout_config.value("shutdown_message_enabled"): print( # noqa: T001 ( @@ -75,6 +76,25 @@ def callback(queue_size): file=sys.stderr, ) + def error_callback(queue_size): + if scout_config.value("shutdown_message_enabled"): + print( # noqa: T001 + ( + "Scout draining {queue_size} error{s} for up to" + + " {timeout_seconds} seconds" + ).format( + queue_size=queue_size, + s=("" if queue_size == 1 else "s"), + timeout_seconds=timeout_seconds, + ), + file=sys.stderr, + ) + CoreAgentSocketThread.wait_until_drained( - timeout_seconds=timeout_seconds, callback=callback + timeout_seconds=timeout_seconds, callback=apm_callback ) + + if scout_config.value("errors_enabled"): + ErrorServiceThread.wait_until_drained( + timeout_seconds=timeout_seconds, callback=error_callback + ) diff --git a/src/scout_apm/core/backtrace.py b/src/scout_apm/core/backtrace.py index 55510645..eb301003 100644 --- a/src/scout_apm/core/backtrace.py +++ b/src/scout_apm/core/backtrace.py @@ -23,36 +23,44 @@ def filter_frames(frames): if sys.version_info >= (3, 5): - def frame_walker(): + def frame_walker(start_frame=None): """Iterate over each frame of the stack. Taken from python3/traceback.ExtractSummary.extract to support iterating over the entire stack, but without creating a large data structure. """ - for frame, lineno in traceback.walk_stack(sys._getframe().f_back): + if start_frame is None: + start_frame = sys._getframe().f_back + for frame, lineno in traceback.walk_stack(start_frame): co = frame.f_code filename = co.co_filename name = co.co_name yield {"file": filename, "line": lineno, "function": name} - def capture(): - return list(itertools.islice(filter_frames(frame_walker()), LIMIT)) + def capture(start_frame=None, apply_filter=True): + walker = frame_walker(start_frame) + if apply_filter: + walker = filter_frames(walker) + return list(itertools.islice(walker, LIMIT)) else: - def frame_walker(): + def frame_walker(start_frame): """Iterate over each frame of the stack. Taken from python2.7/traceback.extract_stack to support iterating over the entire stack, but without creating a large data structure. """ - try: - raise ZeroDivisionError - except ZeroDivisionError: - # Get the current frame - f = sys.exc_info()[2].tb_frame.f_back + if start_frame is None: + try: + raise ZeroDivisionError + except ZeroDivisionError: + # Get the current frame + f = sys.exc_info()[2].tb_frame.f_back + else: + f = start_frame while f is not None: lineno = f.f_lineno @@ -62,5 +70,8 @@ def frame_walker(): yield {"file": filename, "line": lineno, "function": name} f = f.f_back - def capture(): - return list(itertools.islice(filter_frames(frame_walker()), LIMIT)) + def capture(start_frame=None, apply_filter=True): + walker = frame_walker(start_frame) + if apply_filter: + walker = filter_frames(walker) + return list(itertools.islice(walker, LIMIT)) diff --git a/src/scout_apm/core/config.py b/src/scout_apm/core/config.py index 076f0a12..020cbdf0 100644 --- a/src/scout_apm/core/config.py +++ b/src/scout_apm/core/config.py @@ -223,6 +223,10 @@ def __init__(self): "core_agent_version": "v1.3.0", # can be an exact tag name, or 'latest' "disabled_instruments": [], "download_url": "https://s3-us-west-1.amazonaws.com/scout-public-downloads/apm_core_agent/release", # noqa: B950 + "errors_batch_size": 5, + "errors_enabled": False, + "errors_ignored_exceptions": (), + "errors_host": "https://errors.scoutapm.com", "framework": "", "framework_version": "", "hostname": None, diff --git a/src/scout_apm/core/error.py b/src/scout_apm/core/error.py new file mode 100644 index 00000000..33495393 --- /dev/null +++ b/src/scout_apm/core/error.py @@ -0,0 +1,76 @@ +# coding=utf-8 +from __future__ import absolute_import, division, print_function, unicode_literals + +import sys + +from scout_apm.core.backtrace import capture +from scout_apm.core.config import scout_config +from scout_apm.core.error_service import ErrorServiceThread +from scout_apm.core.tracked_request import TrackedRequest +from scout_apm.core.web_requests import RequestComponents, filter_element + +text_type = str if sys.version_info[0] >= 3 else unicode # noqa: F821 + + +class ErrorMonitor(object): + @classmethod + def send( + cls, + exc_info, + request_components=None, + request_path=None, + request_params=None, + session=None, + environment=None, + custom_controller=None, + custom_params=None, + ): + if not scout_config.value("errors_enabled"): + return + + exc_class, exc_value, traceback = exc_info + + ignore_exceptions = scout_config.value("errors_ignored_exceptions") + if ignore_exceptions and isinstance(exc_value, tuple(ignore_exceptions)): + return + + tracked_request = TrackedRequest.instance() + + context = {} + context.update(tracked_request.tags) + + if custom_params: + context["custom_params"] = custom_params + + if custom_controller: + if request_components: + request_components.controller = custom_controller + else: + request_components = RequestComponents( + module=None, controller=custom_controller, action=None + ) + + error = { + "exception_class": exc_class.__name__, + "message": text_type(exc_value), + "request_id": tracked_request.request_id, + "request_uri": request_path, + "request_params": filter_element("", request_params) + if request_params + else None, + "request_session": filter_element("", session) if session else None, + "environment": filter_element("", environment) if environment else None, + "trace": capture(traceback.tb_frame, apply_filter=False), + "request_components": { + "module": request_components.module, + "controller": request_components.controller, + "action": request_components.action, + } + if request_components + else None, + "context": context, + "host": scout_config.value("hostname"), + "revision_sha": scout_config.value("revision_sha"), + } + + ErrorServiceThread.send(error=error) diff --git a/src/scout_apm/core/error_service.py b/src/scout_apm/core/error_service.py new file mode 100644 index 00000000..a469ea1a --- /dev/null +++ b/src/scout_apm/core/error_service.py @@ -0,0 +1,152 @@ +# coding=utf-8 +from __future__ import absolute_import, division, print_function, unicode_literals + +import json +import logging +import os +import threading +import time + +try: + from html import escape +except ImportError: + from cgi import escape + +try: + from urllib.parse import urljoin +except ImportError: + from urlparse import urljoin + +import requests + +from scout_apm.compat import gzip_compress, queue +from scout_apm.core.config import scout_config +from scout_apm.core.threading import SingletonThread + +# Time unit - monkey-patched in tests to make them run faster +SECOND = 1 + +logger = logging.getLogger(__name__) + + +class ErrorServiceThread(SingletonThread): + _instance_lock = threading.Lock() + _stop_event = threading.Event() + _queue = queue.Queue(maxsize=500) + + @classmethod + def _on_stop(cls): + super(ErrorServiceThread, cls)._on_stop() + # Unblock _queue.get() + try: + cls._queue.put(None, False) + except queue.Full as exc: + logger.debug("ErrorServiceThread full for stop: %r", exc, exc_info=exc) + pass + + @classmethod + def send(cls, error): + try: + cls._queue.put(error, False) + except queue.Full as exc: + logger.debug("ErrorServiceThread full for send: %r", exc, exc_info=exc) + + cls.ensure_started() + + @classmethod + def wait_until_drained(cls, timeout_seconds=2.0, callback=None): + interval_seconds = min(timeout_seconds, 0.05) + start = time.time() + while True: + queue_size = cls._queue.qsize() + queue_empty = queue_size == 0 + elapsed = time.time() - start + if queue_empty or elapsed >= timeout_seconds: + break + + if callback is not None: + callback(queue_size) + callback = None + + cls.ensure_started() + + time.sleep(interval_seconds) + return queue_empty + + def run(self): + batch_size = scout_config.value("errors_batch_size") or 1 + try: + while True: + errors = [] + try: + # Attempt to fetch the batch size off of the queue. + for _ in range(batch_size): + error = self._queue.get(block=True, timeout=1 * SECOND) + if error: + errors.append(error) + except queue.Empty: + pass + + if errors and self._send(errors): + for _ in range(len(errors)): + self._queue.task_done() + + # Check for stop event after each read. This allows opening, + # sending, and then immediately stopping. + if self._stop_event.is_set(): + logger.debug("ErrorServiceThread stopping.") + break + except Exception as exc: + logger.debug("ErrorServiceThread exception: %r", exc, exc_info=exc) + finally: + logger.debug("ErrorServiceThread stopped.") + + def _send(self, errors): + try: + data = json.dumps( + { + "notifier": "scout_apm_python", + "environment": scout_config.value("environment"), + "root": scout_config.value("application_root"), + "problems": errors, + } + ) + except (ValueError, TypeError) as exc: + logger.debug( + "Exception when serializing error message: %r", exc, exc_info=exc + ) + return False + + params = { + "key": scout_config.value("key"), + "name": escape(scout_config.value("name"), quote=False), + } + headers = { + "Agent-Hostname": scout_config.value("hostname"), + "Content-Encoding": "gzip", + "Content-Type": "application/json", + "X-Error-Count": "{}".format(len(errors)), + } + + try: + response = requests.post( + urljoin(scout_config.value("errors_host"), "apps/error.scout"), + params=params, + data=gzip_compress(data.encode("utf-8")), + headers=headers, + ) + response.raise_for_status() + except requests.HTTPError as exc: + logger.debug( + ( + "ErrorServiceThread exception on _send:" + + " %r on PID: %s on thread: %s" + ), + exc, + os.getpid(), + threading.current_thread(), + exc_info=exc, + ) + return False + + return True diff --git a/src/scout_apm/core/web_requests.py b/src/scout_apm/core/web_requests.py index 89f2d7c6..e4a6c312 100644 --- a/src/scout_apm/core/web_requests.py +++ b/src/scout_apm/core/web_requests.py @@ -43,34 +43,58 @@ def create_filtered_path(path, query_params): if scout_config.value("uri_reporting") == "path": return path - # We expect query_params to have keys and values both of strings, because - # that's how frameworks build it. However sometimes application code - # mutates this structure to use incorrect types before we read it, so we - # have to cautiously make everything a string again. Ignoring the - # possibilities of bytes or objects with bad __str__ methods because they - # seem very unlikely. - string_query_params = ( - (text_type(key), text_type(value)) for key, value in query_params - ) - # Python 2 unicode compatibility: force all keys and values to bytes filtered_params = sorted( - ( + [ ( - key.encode("utf-8"), - ( - b"[FILTERED]" - if key.lower() in FILTER_PARAMETERS - else value.encode("utf-8") - ), + text_type(key).encode("utf-8"), + # Apply text_type again to cover the None case. + text_type(filter_element(key, value)).encode("utf-8"), ) - for key, value in string_query_params - ) + for key, value in query_params + ] ) if not filtered_params: return path return path + "?" + urlencode(filtered_params) +def filter_element(key, value): + """ + Filter an individual key/value element of sensitive content. If the + value is a dictionary, recursively filter the keys in that dictionary. + + Can be used recursively on a dict with: + + filter_element('', {"foo": "bar"}) + """ + is_sensitive = text_type(key).lower() in FILTER_PARAMETERS + + if is_sensitive: + filtered = "[FILTERED]" + elif isinstance(value, dict): + # Python 2 unicode compatibility: force all keys and values to bytes + # + # We expect query_params to have keys and values both of strings, because + # that's how frameworks build it. However sometimes application code + # mutates this structure to use incorrect types, or we are filtering a + # different collection, so we have to cautiously make everything a string + # again. Ignoring the possibilities of bytes or objects with bad __str__ + # methods because they seem very unlikely. + filtered = {text_type(k): filter_element(k, v) for k, v in value.items()} + elif isinstance(value, list): + filtered = [filter_element("", v) for v in value] + elif isinstance(value, set): + filtered = {filter_element("", v) for v in value} + elif isinstance(value, tuple): + filtered = tuple([filter_element("", v) for v in value]) + elif value is None: + filtered = value + else: + filtered = text_type(value) + + return filtered + + def ignore_path(path): ignored_paths = scout_config.value("ignore") for ignored in ignored_paths: @@ -192,3 +216,12 @@ def werkzeug_track_request_data(werkzeug_request, tracked_request): "x-queue-start", default="" ) or werkzeug_request.headers.get("x-request-start", default="") track_request_queue_time(queue_time, tracked_request) + + +class RequestComponents(object): + __slots__ = ("module", "controller", "action") + + def __init__(self, module, controller, action): + self.module = module + self.controller = controller + self.action = action diff --git a/src/scout_apm/django/apps.py b/src/scout_apm/django/apps.py index c5f6c091..5568dbde 100644 --- a/src/scout_apm/django/apps.py +++ b/src/scout_apm/django/apps.py @@ -1,15 +1,30 @@ # coding=utf-8 from __future__ import absolute_import, division, print_function, unicode_literals +import sys + +import django from django.apps import AppConfig from django.conf import settings +from django.core.signals import got_request_exception from django.test.signals import setting_changed +if django.VERSION < (3, 1): + from django.views.debug import get_safe_settings +else: + from django.views.debug import SafeExceptionReporterFilter + + def get_safe_settings(): + return SafeExceptionReporterFilter().get_safe_settings() + + import scout_apm.core from scout_apm.core.config import scout_config +from scout_apm.core.error import ErrorMonitor from scout_apm.django.instruments.huey import ensure_huey_instrumented from scout_apm.django.instruments.sql import ensure_sql_instrumented from scout_apm.django.instruments.template import ensure_templates_instrumented +from scout_apm.django.request import get_request_components class ScoutApmDjangoConfig(AppConfig): @@ -26,6 +41,9 @@ def ready(self): if not installed: return + if scout_config.value("errors_enabled"): + got_request_exception.connect(self.on_got_request_exception) + self.install_middleware() # Setup Instruments @@ -37,6 +55,21 @@ def update_scout_config_from_django_settings(self, **kwargs): for name in dir(settings): self.on_setting_changed(name) + def on_got_request_exception(self, request, **kwargs): + """ + Process this exception with the error monitoring solution. + """ + ErrorMonitor.send( + sys.exc_info(), + request_components=get_request_components(request), + request_path=request.path, + request_params=request.GET.dict(), + session=dict(request.session.items()) + if hasattr(request, "session") + else None, + environment=get_safe_settings(), + ) + def on_setting_changed(self, setting, **kwargs): cast = None if setting == "BASE_DIR": diff --git a/src/scout_apm/django/middleware.py b/src/scout_apm/django/middleware.py index 9cb95a93..8cb12983 100644 --- a/src/scout_apm/django/middleware.py +++ b/src/scout_apm/django/middleware.py @@ -1,12 +1,9 @@ # coding=utf-8 from __future__ import absolute_import, division, print_function, unicode_literals -import sys - import django from django.conf import settings -from scout_apm.compat import string_types from scout_apm.core.config import scout_config from scout_apm.core.tracked_request import TrackedRequest from scout_apm.core.web_requests import ( @@ -14,6 +11,7 @@ ignore_path, track_request_queue_time, ) +from scout_apm.django.request import get_controller_name if django.VERSION >= (1, 11): from django.urls import get_urlconf @@ -21,95 +19,6 @@ from django.core.urlresolvers import get_urlconf -def get_operation_name(request): - view_func = request.resolver_match.func - view_name = request.resolver_match._func_path - - if hasattr(view_func, "model_admin"): - # Seems to comes from Django admin (attribute only set on Django 1.9+) - admin_class = view_func.model_admin.__class__ - view_name = ( - admin_class.__module__ - + "." - + admin_class.__name__ - + "." - + view_func.__name__ - ) - - django_rest_framework_name = _get_django_rest_framework_name( - request, view_func, view_name - ) - if django_rest_framework_name is not None: - return django_rest_framework_name - - # Seems to be a Tastypie Resource. Need to resort to some stack inspection - # to find a better name since its decorators don't wrap very well - if view_name == "tastypie.resources.wrapper": - tastypie_name = _get_tastypie_operation_name(request, view_func) - if tastypie_name is not None: - return tastypie_name - - return "Controller/" + view_name - - -def _get_django_rest_framework_name(request, view_func, view_name): - try: - from rest_framework.viewsets import ViewSetMixin - except ImportError: - return None - - kls = getattr(view_func, "cls", None) - if isinstance(kls, type) and not issubclass(kls, ViewSetMixin): - return None - - # Get 'actions' set in ViewSetMixin.as_view - actions = getattr(view_func, "actions", None) - if not actions or not isinstance(actions, dict): - return None - - method_lower = request.method.lower() - if method_lower not in actions: - return None - - return "Controller/{}.{}".format(view_name, actions[method_lower]) - - -def _get_tastypie_operation_name(request, view_func): - try: - from tastypie.resources import Resource - except ImportError: - return None - - if sys.version_info[0] == 2: # pragma: no cover - try: - wrapper = view_func.__closure__[0].cell_contents - except (AttributeError, IndexError): - return None - else: - try: - wrapper = view_func.__wrapped__ - except AttributeError: - return None - - if not hasattr(wrapper, "__closure__") or len(wrapper.__closure__) != 2: - return None - - instance = wrapper.__closure__[0].cell_contents - if not isinstance(instance, Resource): # pragma: no cover - return None - - method_name = wrapper.__closure__[1].cell_contents - if not isinstance(method_name, string_types): # pragma: no cover - return None - - if method_name.startswith("dispatch_"): # pragma: no cover - method_name = request.method.lower() + method_name.split("dispatch", 1)[1] - - return "Controller/{}.{}.{}".format( - instance.__module__, instance.__class__.__name__, method_name - ) - - def track_request_view_data(request, tracked_request): path = request.path tracked_request.tag( @@ -221,7 +130,7 @@ def process_view(self, request, view_func, view_args, view_kwargs): span = tracked_request.current_span() if span is not None: - span.operation = get_operation_name(request) + span.operation = get_controller_name(request) def process_exception(self, request, exception): """ @@ -260,9 +169,9 @@ def process_response(self, request, response): # i.e. that custom instrumentation within the application is not # causing errors tracked_request = getattr(request, "_scout_tracked_request", None) - if 500 <= response.status_code <= 599: - tracked_request.tag("error", "true") if tracked_request is not None: + if 500 <= response.status_code <= 599: + tracked_request.tag("error", "true") tracked_request.stop_span() return response @@ -278,7 +187,7 @@ def process_view(self, request, view_func, view_func_args, view_func_kwargs): tracked_request.is_real_request = True span = tracked_request.start_span( - operation=get_operation_name(request), should_capture_backtrace=False + operation=get_controller_name(request), should_capture_backtrace=False ) # Save the span into the request, so we can check # if we're matched up when stopping diff --git a/src/scout_apm/django/request.py b/src/scout_apm/django/request.py new file mode 100644 index 00000000..319d0a47 --- /dev/null +++ b/src/scout_apm/django/request.py @@ -0,0 +1,149 @@ +# coding=utf-8 +from __future__ import absolute_import, division, print_function, unicode_literals + +import sys + +from scout_apm.compat import string_types +from scout_apm.core.web_requests import RequestComponents + + +def get_controller_name(request): + view_func = request.resolver_match.func + view_name = request.resolver_match._func_path + + django_admin_components = _get_django_admin_components(view_func) + if django_admin_components: + view_name = "{}.{}.{}".format( + django_admin_components.module, + django_admin_components.controller, + django_admin_components.action, + ) + + django_rest_framework_components = _get_django_rest_framework_components( + request, view_func + ) + if django_rest_framework_components is not None: + view_name = "{}.{}.{}".format( + django_rest_framework_components.module, + django_rest_framework_components.controller, + django_rest_framework_components.action, + ) + + # Seems to be a Tastypie Resource. Need to resort to some stack inspection + # to find a better name since its decorators don't wrap very well + if view_name == "tastypie.resources.wrapper": + tastypie_components = _get_tastypie_components(request, view_func) + if tastypie_components is not None: + view_name = "{}.{}.{}".format( + tastypie_components.module, + tastypie_components.controller, + tastypie_components.action, + ) + + return "Controller/{}".format(view_name) + + +def get_request_components(request): + if not request.resolver_match: + return None + view_func = request.resolver_match.func + view_name = request.resolver_match._func_path + request_components = RequestComponents( + module=view_func.__module__, + controller=view_func.__name__, + action=request.method, + ) + + django_admin_components = _get_django_admin_components(view_func) + if django_admin_components: + request_components = django_admin_components + + django_rest_framework_components = _get_django_rest_framework_components( + request, view_func + ) + if django_rest_framework_components is not None: + request_components = django_rest_framework_components + + # Seems to be a Tastypie Resource. Need to resort to some stack inspection + # to find a better name since its decorators don't wrap very well + if view_name == "tastypie.resources.wrapper": + tastypie_components = _get_tastypie_components(request, view_func) + if tastypie_components is not None: + request_components = tastypie_components + return request_components + + +def _get_django_admin_components(view_func): + if hasattr(view_func, "model_admin"): + # Seems to comes from Django admin (attribute only set on Django 1.9+) + admin_class = view_func.model_admin.__class__ + return RequestComponents( + module=admin_class.__module__, + controller=admin_class.__name__, + action=view_func.__name__, + ) + return None + + +def _get_django_rest_framework_components(request, view_func): + try: + from rest_framework.viewsets import ViewSetMixin + except ImportError: + return None + + kls = getattr(view_func, "cls", None) + if isinstance(kls, type) and not issubclass(kls, ViewSetMixin): + return None + + # Get 'actions' set in ViewSetMixin.as_view + actions = getattr(view_func, "actions", None) + if not actions or not isinstance(actions, dict): + return None + + method_lower = request.method.lower() + if method_lower not in actions: + return None + + return RequestComponents( + module=view_func.__module__, + controller=view_func.__name__, + action=actions[method_lower], + ) + + +def _get_tastypie_components(request, view_func): + try: + from tastypie.resources import Resource + except ImportError: + return None + + if sys.version_info[0] == 2: # pragma: no cover + try: + wrapper = view_func.__closure__[0].cell_contents + except (AttributeError, IndexError): + return None + else: + try: + wrapper = view_func.__wrapped__ + except AttributeError: + return None + + if not hasattr(wrapper, "__closure__") or len(wrapper.__closure__) != 2: + return None + + instance = wrapper.__closure__[0].cell_contents + if not isinstance(instance, Resource): # pragma: no cover + return None + + method_name = wrapper.__closure__[1].cell_contents + if not isinstance(method_name, string_types): # pragma: no cover + return None + + if method_name.startswith("dispatch_"): # pragma: no cover + method_name = request.method.lower() + method_name.split("dispatch", 1)[1] + + return RequestComponents( + module=instance.__module__, + controller=instance.__class__.__name__, + action=method_name, + ) diff --git a/src/scout_apm/instruments/urllib3.py b/src/scout_apm/instruments/urllib3.py index 67b69859..8be7c21b 100644 --- a/src/scout_apm/instruments/urllib3.py +++ b/src/scout_apm/instruments/urllib3.py @@ -6,6 +6,7 @@ import wrapt from scout_apm.compat import text_type +from scout_apm.core.config import scout_config from scout_apm.core.tracked_request import TrackedRequest try: @@ -57,6 +58,10 @@ def _extract_method(method, *args, **kwargs): logger.exception("Could not get URL for HTTPConnectionPool") url = "Unknown" + # Don't instrument ErrorMonitor calls + if text_type(url).startswith(scout_config.value("errors_host")): + return wrapped(*args, **kwargs) + tracked_request = TrackedRequest.instance() with tracked_request.span(operation="HTTP/{}".format(method)) as span: span.tag("url", text_type(url)) diff --git a/tests/compat.py b/tests/compat.py index 72c2b416..a0598d30 100644 --- a/tests/compat.py +++ b/tests/compat.py @@ -1,6 +1,7 @@ # coding=utf-8 from __future__ import absolute_import, division, print_function, unicode_literals +import gzip import sys if sys.version_info >= (3, 0): @@ -57,4 +58,19 @@ def suppress(*exceptions): pass -__all__ = ["mock", "nullcontext", "suppress", "TemporaryDirectory"] +if sys.version_info >= (3, 2): + + def gzip_decompress(data): + return gzip.decompress(data) + + +else: + import io + + def gzip_decompress(data): + """Reimplementation gzip.compress for python 2.7""" + with gzip.GzipFile(fileobj=io.BytesIO(data), mode="rb") as f: + return f.read() + + +__all__ = ["gzip_decompress", "mock", "nullcontext", "suppress", "TemporaryDirectory"] diff --git a/tests/conftest.py b/tests/conftest.py index 4e318603..b350e3eb 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -11,9 +11,11 @@ import wrapt from webtest import TestApp +from scout_apm.core import error_service as scout_apm_core_error_service from scout_apm.core.agent import socket as scout_apm_core_socket from scout_apm.core.agent.manager import CoreAgentManager from scout_apm.core.config import SCOUT_PYTHON_VALUES, scout_config +from scout_apm.core.error_service import ErrorServiceThread from scout_apm.core.tracked_request import TrackedRequest from tests.compat import TemporaryDirectory @@ -38,11 +40,40 @@ TestApp.__test__ = False +class ExcludeDebugLogFilter(logging.Filter): + excluded_logs = [ + # Name, level, [values to see if they are contained in the message] + ( + "httpretty.core", + 10, + ("error closing file", "'super' object has no attribute 'flush'"), + ), + ("httpretty.core", 10, ("error closing file", "flush of closed file")), + ] + + def filter(self, record): + """ + Exclude debug logs that are generated from other libraries that unduly + influence our logging assertions. + + Is the specified record to be logged? Returns False for no, True for + yes. + """ + for name, level, excluded_message_parts in self.excluded_logs: + if record.name == name and record.levelno == level: + message = record.getMessage() + if all(part in message for part in excluded_message_parts): + # Return False to prevent the log from being recorded + return False + return True + + # Override built-in caplog fixture to always be at DEBUG level since we have # many DEBUG log messages @pytest.fixture() def caplog(caplog): caplog.set_level(logging.DEBUG) + caplog.handler.addFilter(ExcludeDebugLogFilter("scout_test")) yield caplog @@ -153,10 +184,12 @@ def terminate_core_agent_processes(): @pytest.fixture(autouse=True, scope="session") def short_timeouts(): scout_apm_core_socket.SECOND = 0.01 + scout_apm_core_error_service.SECOND = 0.01 try: yield finally: scout_apm_core_socket.SECOND = 1 + scout_apm_core_error_service.SECOND = 1 @pytest.fixture(autouse=True) @@ -169,6 +202,16 @@ def stop_and_empty_core_agent_socket(): command_queue.task_done() +@pytest.fixture(autouse=True) +def stop_and_empty_core_error_service(): + yield + scout_apm_core_error_service.ErrorServiceThread.ensure_stopped() + queue = scout_apm_core_error_service.ErrorServiceThread._queue + while not queue.empty(): + queue.get() + queue.task_done() + + @pytest.fixture def tracked_request(): """ @@ -200,3 +243,24 @@ def capture_requests(wrapped, instance, args, kwargs): yield requests finally: TrackedRequest.finish = orig + + +@pytest.fixture +def error_monitor_errors(): + """ + Mock calls made to the error service thread. + Returns a list of error dicts + """ + errors = [] + + @wrapt.decorator + def capture_error(wrapped, instance, args, kwargs): + errors.append(kwargs["error"]) + return wrapped(*args, **kwargs) + + orig = ErrorServiceThread.send + ErrorServiceThread.send = capture_error(orig) + try: + yield errors + finally: + ErrorServiceThread.send = orig diff --git a/tests/integration/core/agent/test_socket.py b/tests/integration/core/agent/test_socket.py index fe3cf626..0081814b 100644 --- a/tests/integration/core/agent/test_socket.py +++ b/tests/integration/core/agent/test_socket.py @@ -37,7 +37,7 @@ def socket(running_agent): time.sleep(0.01) yield socket - # ensure_stopped() already called by global auto_stop_core_agent_socket + # ensure_stopped() already called by global stop_and_empty_core_error_service class Command(object): diff --git a/tests/integration/core/test_error_service.py b/tests/integration/core/test_error_service.py new file mode 100644 index 00000000..114d1cbd --- /dev/null +++ b/tests/integration/core/test_error_service.py @@ -0,0 +1,134 @@ +# coding=utf-8 +from __future__ import absolute_import, division, print_function, unicode_literals + +import logging +from datetime import datetime +from time import sleep + +import httpretty +import pytest + +from scout_apm.core.config import scout_config +from scout_apm.core.error_service import ErrorServiceThread +from tests.compat import gzip_decompress + + +@pytest.fixture +def error_service_thread(): + service_thread = ErrorServiceThread.ensure_started() + yield service_thread + # ensure_stopped() already called by global stop_and_empty_core_agent_socket + + +@pytest.mark.parametrize( + "config, decompressed_body, expected_headers, expected_uri", + [ + ( + { + "key": "scout-app-key", + "app": "scout test app", + "hostname": "example.com", + "environment": "scout-test", + "application_root": "/tmp/", + "errors_host": "https://testserver", + }, + b'{"notifier": "scout_apm_python", "environment": "scout-test", ' + b'"root": "/tmp/", "problems": [{"foo": "bar"}]}', + {"Agent-Hostname": "example.com", "X-Error-Count": "1"}, + "https://testserver/apps/error.scout?key=scout-app-key" + "&name=scout+test+app", + ), + ( + {}, + b'{"notifier": "scout_apm_python", "environment": null, ' + b'"root": "", "problems": [{"foo": "bar"}]}', + {"Agent-Hostname": None, "X-Error-Count": "1"}, + "https://errors.scoutapm.com/apps/error.scout" "?name=Python+App", + ), + ], +) +def test_send( + config, decompressed_body, expected_headers, expected_uri, error_service_thread +): + scout_config.set(**config) + + def request_callback(request, uri, response_headers): + assert uri == expected_uri + for key, value in expected_headers.items(): + assert request.headers.get(key) == value + assert gzip_decompress(request.body) == decompressed_body + return [200, response_headers, "Hello world!"] + + try: + with httpretty.enabled(allow_net_connect=False): + httpretty.register_uri( + httpretty.POST, + "https://errors.scoutapm.com/apps/error.scout", + body=request_callback, + ) + ErrorServiceThread.send({"foo": "bar"}) + ErrorServiceThread.wait_until_drained() + finally: + scout_config.reset_all() + + +def test_send_batch(error_service_thread): + def request_callback(request, uri, response_headers): + decompressed_body = ( + b'{"notifier": "scout_apm_python", "environment": null, ' + b'"root": "", "problems": [{"foo": 0}, {"foo": 1}, ' + b'{"foo": 2}, {"foo": 3}, {"foo": 4}]}' + ) + assert gzip_decompress(request.body) == decompressed_body + assert request.headers.get("X-Error-Count") == "5" + return [200, response_headers, "Hello world!"] + + try: + with httpretty.enabled(allow_net_connect=False): + httpretty.register_uri( + httpretty.POST, + "https://errors.scoutapm.com/apps/error.scout", + body=request_callback, + ) + for i in range(5): + ErrorServiceThread.send({"foo": i}) + ErrorServiceThread.wait_until_drained() + finally: + scout_config.reset_all() + + +def test_send_api_error(error_service_thread, caplog): + try: + with httpretty.enabled(allow_net_connect=False): + httpretty.register_uri( + httpretty.POST, + "https://errors.scoutapm.com/apps/error.scout", + body="Unexpected Error", + status=500, + ) + ErrorServiceThread.send({"foo": "bar"}) + ErrorServiceThread.wait_until_drained() + finally: + scout_config.reset_all() + assert caplog.record_tuples[-1][0] == "scout_apm.core.error_service" + assert caplog.record_tuples[-1][1] == logging.DEBUG + assert caplog.record_tuples[-1][2].startswith( + "ErrorServiceThread exception on _send:" + ) + + +def test_send_unserializable_data(error_service_thread, caplog): + with httpretty.enabled(allow_net_connect=False): + ErrorServiceThread.send({"value": datetime.now()}) + ErrorServiceThread.wait_until_drained() + + if ErrorServiceThread._queue.empty() and not caplog.record_tuples: + # py38-django20 and py36-django11 tend to fail + # here by indicating the log never occurred despite + # the message being pushed down. + sleep(2) + assert caplog.record_tuples[-1][0] == "scout_apm.core.error_service" + assert caplog.record_tuples[-1][1] == logging.DEBUG + assert caplog.record_tuples[-1][2].startswith( + "Exception when serializing error message:" + ) diff --git a/tests/integration/django_app.py b/tests/integration/django_app.py index 4ec7d181..9fe5353d 100644 --- a/tests/integration/django_app.py +++ b/tests/integration/django_app.py @@ -182,8 +182,16 @@ class UserViewSet(viewsets.ModelViewSet): queryset = User.objects.all() serializer_class = UserSerializer + class ErrorViewSet(viewsets.ModelViewSet): + queryset = User.objects.all() + + def get_queryset(self, *args, **kwargs): + raise ValueError("BØØM!") + router = routers.SimpleRouter() router.register(r"users", UserViewSet) + router.register(r"crash", ErrorViewSet) + return router @@ -206,8 +214,17 @@ class Meta: queryset = User.objects.all() allowed_methods = ["get"] + class CrashResource(TastypieModelResource): + class Meta: + queryset = User.objects.all() + allowed_methods = ["get"] + + def build_filters(self, *args, **kwargs): + raise ValueError("BØØM!") + api = TastypieApi(api_name="v1") api.register(UserResource()) + api.register(CrashResource()) return api diff --git a/tests/integration/instruments/test_urllib3.py b/tests/integration/instruments/test_urllib3.py index ea2ae35a..07e0c73e 100644 --- a/tests/integration/instruments/test_urllib3.py +++ b/tests/integration/instruments/test_urllib3.py @@ -121,3 +121,18 @@ def test_request_no_absolute_url(caplog, tracked_request): span = tracked_request.complete_spans[0] assert span.operation == "HTTP/GET" assert span.tags["url"] == "Unknown" + + +def test_request_ignore_errors_host(tracked_request): + ensure_installed() + with httpretty.enabled(allow_net_connect=False): + httpretty.register_uri( + httpretty.POST, "https://errors.scoutapm.com", body="Hello World!" + ) + + http = urllib3_cert_pool_manager() + response = http.request("POST", "https://errors.scoutapm.com") + + assert response.status == 200 + assert response.data == b"Hello World!" + assert len(tracked_request.complete_spans) == 0 diff --git a/tests/integration/test_api.py b/tests/integration/test_api.py index 0844edc4..98f4cc33 100644 --- a/tests/integration/test_api.py +++ b/tests/integration/test_api.py @@ -1,10 +1,13 @@ # coding=utf-8 from __future__ import absolute_import, division, print_function, unicode_literals +import pytest + from scout_apm.api import ( BackgroundTransaction, Config, Context, + Error, WebTransaction, ignore_transaction, instrument, @@ -315,3 +318,67 @@ def test_rename_transaction_none(tracked_request): rename_transaction(None) assert "transaction.name" not in tracked_request.tags + + +def test_error_capture(error_monitor_errors, tracked_request): + scout_config.set(errors_enabled=True) + tracked_request.tag("spam", "eggs") + + request_path = "/test/" + request_params = {"page": 1} + session = {"step": 0} + custom_controller = "test-controller" + custom_params = {"foo": "bar"} + try: + try: + 1 / 0 + except ZeroDivisionError as exc: + Error.capture( + exc, + request_path=request_path, + request_params=request_params, + session=session, + custom_controller=custom_controller, + custom_params=custom_params, + ) + finally: + scout_config.reset_all() + + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + assert error["trace"][0]["function"] == "test_error_capture" + assert error["exception_class"] == "ZeroDivisionError" + assert error["message"] == "division by zero" + assert error["context"] == { + "spam": "eggs", + "custom_params": {"foo": "bar"}, + } + assert error["request_uri"] == request_path + assert error["request_params"] == {"page": "1"} + assert error["request_session"] == {"step": "0"} + assert error["request_components"] == { + "module": None, + "controller": custom_controller, + "action": None, + } + + +@pytest.mark.parametrize( + "value", + [ + None, + 0, + 1, + "foo", + True, + ], +) +def test_error_capture_skip(value, error_monitor_errors): + scout_config.set(errors_enabled=True) + + try: + Error.capture(value) + finally: + scout_config.reset_all() + + assert len(error_monitor_errors) == 0 diff --git a/tests/integration/test_celery.py b/tests/integration/test_celery.py index 6281c67d..1516337f 100644 --- a/tests/integration/test_celery.py +++ b/tests/integration/test_celery.py @@ -1,17 +1,19 @@ # coding=utf-8 from __future__ import absolute_import, division, print_function, unicode_literals +import logging from contextlib import contextmanager import celery import pytest from celery.signals import setup_logging +from django.core.exceptions import ImproperlyConfigured import scout_apm.celery from scout_apm.api import Config from scout_apm.compat import kwargs_only from scout_apm.core.config import scout_config -from tests.compat import SimpleNamespace +from tests.compat import SimpleNamespace, mock # http://docs.celeryproject.org/en/latest/userguide/testing.html#py-test skip_unless_celery_4_plus = pytest.mark.skipif( @@ -51,7 +53,7 @@ def hello(): return "Hello World!" @app.task - def crash(): + def crash(foo, spam=None): raise ValueError("Boom!") # Setup according to https://docs.scoutapm.com/#celery @@ -98,7 +100,7 @@ def test_hello_eager(tracked_requests): def test_error_task(tracked_requests): with app_with_scout() as app: - result = app.tasks["tests.integration.test_celery.crash"].apply() + result = app.tasks["tests.integration.test_celery.crash"].si(None).apply() assert isinstance(result.result, ValueError) assert len(tracked_requests) == 1 @@ -110,6 +112,93 @@ def test_error_task(tracked_requests): assert tracked_request.tags["error"] +def test_error_task_error_monitor(error_monitor_errors, mock_get_safe_settings): + mock_get_safe_settings.return_value = {"setting1": "value"} + with app_with_scout(config={"errors_enabled": True, "monitor": True}) as app: + result = ( + app.tasks["tests.integration.test_celery.crash"].si("arg1", spam=2).apply() + ) + + assert isinstance(result.result, ValueError) + + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + filepath, line, func_str = error["trace"][0].split(":") + assert filepath.endswith("tests/integration/test_celery.py") + # The line number changes between python versions. Make sure it's not empty. + assert line + assert func_str == "in crash" + assert error["exception_class"] == "ValueError" + assert error["message"] == "Boom!" + assert error["request_components"] == { + "module": None, + "controller": "tests.integration.test_celery.crash", + "action": None, + } + assert error["context"]["custom_params"] == { + "celery": { + "args": ("arg1",), + "kwargs": {"spam": 2}, + "task_id": result.task_id, + }, + } + + +@pytest.fixture +def mock_get_safe_settings(): + """We're unable to mock.patch the function so monkey-patch it.""" + original = scout_apm.celery.get_safe_settings + scout_apm.celery.get_safe_settings = mock.Mock() + yield scout_apm.celery.get_safe_settings + scout_apm.celery.get_safe_settings = original + + +@pytest.mark.parametrize( + "thrown, log_starts_with", + [ + [ + ImproperlyConfigured("invalid"), + "Celery integration does not have django configured properly: " + "ImproperlyConfigured", + ], + [ + Exception("other"), + "Celery task_failure callback exception: Exception", + ], + ], +) +def test_error_task_error_monitor_exception( + thrown, log_starts_with, mock_get_safe_settings, error_monitor_errors, caplog +): + mock_get_safe_settings.side_effect = thrown + with app_with_scout(config={"errors_enabled": True, "monitor": True}) as app: + result = app.tasks["tests.integration.test_celery.crash"].si(None).apply() + + assert isinstance(result.result, ValueError) + + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + assert error["context"]["custom_params"] == { + "celery": { + "args": (None,), + "kwargs": {}, + "task_id": result.task_id, + }, + } + assert error["request_components"] == { + "module": None, + "controller": "tests.integration.test_celery.crash", + "action": None, + } + actual_debugs = [ + log + for source, level, log in caplog.record_tuples + if source == "scout_apm.celery" and level == logging.DEBUG + ] + assert len(actual_debugs) == 1 + assert actual_debugs[0].startswith(log_starts_with) + + @skip_unless_celery_4_plus def test_hello_worker(celery_app, celery_worker, tracked_requests): with app_with_scout(app=celery_app) as app: diff --git a/tests/integration/test_django.py b/tests/integration/test_django.py index 507b68af..a70a08f8 100644 --- a/tests/integration/test_django.py +++ b/tests/integration/test_django.py @@ -77,6 +77,8 @@ def app_with_scout(**settings): uninstall and reinstall scout per test. """ settings.setdefault("SCOUT_MONITOR", True) + settings.setdefault("SCOUT_ERRORS_ENABLED", True) + settings["SCOUT_CORE_AGENT_LAUNCH"] = False with override_settings(**settings): # Have to create a new WSGI app each time because the middleware stack @@ -243,6 +245,16 @@ def test_server_error(tracked_requests): assert operations == expected_operations +def test_server_error_error_monitor(tracked_requests, error_monitor_errors): + with app_with_scout(DEBUG_PROPAGATE_EXCEPTIONS=False) as app: + TestApp(app).get("/crash/", expect_errors=True) + + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + assert error["exception_class"] == "ValueError" + assert error["message"] == "BØØM!" + + def test_return_error(tracked_requests): with app_with_scout() as app: response = TestApp(app).get("/return-error/", expect_errors=True) @@ -258,6 +270,13 @@ def test_return_error(tracked_requests): ] +def test_return_error_error_monitor(tracked_requests, error_monitor_errors): + with app_with_scout() as app: + TestApp(app).get("/return-error/", expect_errors=True) + + assert len(error_monitor_errors) == 0 + + def test_cbv(tracked_requests): with app_with_scout() as app: response = TestApp(app).get("/cbv/") @@ -465,6 +484,36 @@ def test_django_rest_framework_api_operation_name( ] +@pytest.mark.parametrize( + "url, expected_action", + [ + [ + "/drf-router/crash/", + "list", + ], + [ + "/drf-router/crash/1/", + "retrieve", + ], + ], +) +def test_django_rest_framework_api_request_components( + url, expected_action, tracked_requests, error_monitor_errors +): + with app_with_scout(DEBUG_PROPAGATE_EXCEPTIONS=False) as app: + make_admin_user() + response = TestApp(app).get(url, expect_errors=True) + + assert response.status_int == 500 + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + assert error["request_components"] == { + "module": "tests.integration.django_app", + "controller": "ErrorViewSet", + "action": expected_action, + } + + def skip_if_no_tastypie(): # This would make more sense as a test decorator, but can't be one because # it requires the Django application to be constructed first, under @@ -499,6 +548,57 @@ def test_tastypie_api_operation_name(url, expected_op_name, tracked_requests): assert span.operation == expected_op_name +@pytest.mark.parametrize( + "url, expected_action", + [ + [ + "/tastypie-api/v1/crash/1/", + "get_detail", + ], + [ + "/tastypie-api/v1/crash/", + "get_list", + ], + ], +) +def test_error_monitor_tastypie_request_components( + url, expected_action, tracked_requests, error_monitor_errors +): + with app_with_scout(DEBUG_PROPAGATE_EXCEPTIONS=False) as app: + skip_if_no_tastypie() + make_admin_user() + response = TestApp(app).get(url, {"format": "json"}, expect_errors=True) + + assert response.status_int == 500 + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + assert error["request_components"] == { + "module": "tests.integration.django_app", + "controller": "CrashResource", + "action": expected_action, + } + + +def test_error_monitor_tastypie_request_components_fail_no_tastypie( + tracked_requests, error_monitor_errors +): + with app_with_scout(DEBUG_PROPAGATE_EXCEPTIONS=False) as app: + skip_if_no_tastypie() + with pretend_package_unavailable("tastypie"): + response = TestApp(app).get( + "/tastypie-api/v1/crash/1/", {"format": "json"}, expect_errors=True + ) + + assert response.status_int == 500 + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + assert error["request_components"] == { + "module": "tastypie.resources", + "controller": "wrapper", + "action": "GET", + } + + def test_tastypie_api_operation_name_fail_no_tastypie(tracked_requests): with app_with_scout() as app: skip_if_no_tastypie() @@ -538,6 +638,70 @@ def test_tastypie_api_operation_name_fail_no_closure(tracked_requests): assert span.operation == "Controller/tastypie.resources.wrapper" +def crash_middleware_no_resolver(get_response): + def middleware(request): + raise ValueError("BØØM!") + + return middleware + + +def crash_middleware(get_response): + def middleware(request): + get_response(request) + # Error after the view processes so request.resolver_match is set + raise ValueError("BØØM!") + + return middleware + + +@skip_unless_new_style_middleware +@pytest.mark.parametrize( + "middleware, expected_request_components", + [ + [ + __name__ + ".crash_middleware_no_resolver", + None, + ], + [ + __name__ + ".crash_middleware", + { + "action": "GET", + "controller": "hello", + "module": "tests.integration.django_app", + }, + ], + ], +) +def test_error_monitor_middleware_crash( + middleware, + expected_request_components, + tracked_requests, + error_monitor_errors, +): + new_middleware = settings.MIDDLEWARE + [middleware] + with app_with_scout( + MIDDLEWARE=new_middleware, DEBUG_PROPAGATE_EXCEPTIONS=False + ) as app: + response = TestApp(app).get("/hello/", expect_errors=True) + + assert response.status_int == 500 + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + assert error["request_components"] == expected_request_components + + +@skip_unless_new_style_middleware +def test_error_monitor_sanitized_environment(tracked_requests, error_monitor_errors): + with app_with_scout(DEBUG_PROPAGATE_EXCEPTIONS=False) as app: + response = TestApp(app).get("/crash/", expect_errors=True) + + assert response.status_int == 500 + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + assert error["environment"]["SECRET_KEY"] == "********************" + assert error["environment"]["DATABASES"]["default"]["PASSWORD"] == "[FILTERED]" + + def test_no_monitor(tracked_requests): with app_with_scout(SCOUT_MONITOR=False) as app: response = TestApp(app).get("/hello/") @@ -554,6 +718,16 @@ def test_no_monitor_server_error(tracked_requests): assert tracked_requests == [] +def test_no_error_monitoring_server_error(tracked_requests, error_monitor_errors): + with app_with_scout( + SCOUT_ERRORS_ENABLED=False, DEBUG_PROPAGATE_EXCEPTIONS=False + ) as app: + response = TestApp(app).get("/crash/", expect_errors=True) + + assert response.status_int == 500 + assert error_monitor_errors == [] + + def test_username_anonymous(tracked_request): with app_with_scout() as app: response = TestApp(app).get("/get-username/") @@ -875,6 +1049,32 @@ def test_old_style_exception_on_request_middleware(middleware_index, tracked_req assert len(tracked_requests) == 0 +@skip_unless_old_style_middleware +@pytest.mark.parametrize("middleware_index", [0, 1, 999]) +def test_old_style_exception_on_request_middleware_error_monitor( + middleware_index, tracked_requests, error_monitor_errors +): + """ + Test the case the old style middleware has the errors monitored. + """ + new_middleware = ( + settings.MIDDLEWARE_CLASSES[:middleware_index] + + [__name__ + "." + OldStyleExceptionOnRequestMiddleware.__name__] + + settings.MIDDLEWARE_CLASSES[middleware_index:] + ) + with app_with_scout( + MIDDLEWARE_CLASSES=new_middleware, + DEBUG_PROPAGATE_EXCEPTIONS=False, + SCOUT_ERRORS_ENABLED=True, + ) as app: + TestApp(app).get("/", expect_errors=True) + + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + assert error["exception_class"] == "ValueError" + assert error["message"] == "Woops!" + + @skip_unless_old_style_middleware @pytest.mark.parametrize("url,expected_status", [("/", 200), ("/crash/", 500)]) def test_old_style_timing_middleware_deleted(url, expected_status, tracked_requests): diff --git a/tests/unit/core/test_backtrace.py b/tests/unit/core/test_backtrace.py index c59e5b58..b45b28c5 100644 --- a/tests/unit/core/test_backtrace.py +++ b/tests/unit/core/test_backtrace.py @@ -41,6 +41,30 @@ def capture_recursive_bottom(limit): assert len(stack) == backtrace.LIMIT +def test_capture_with_frame(): + def error(): + # Python 2 compatible way of getting the current frame. + try: + raise ZeroDivisionError + except ZeroDivisionError: + # Get the current frame + return sys.exc_info()[2].tb_frame + + stack = backtrace.capture(error(), apply_filter=False) + + assert len(stack) >= 1 + for frame in stack: + assert isinstance(frame, dict) + assert set(frame.keys()) == {"file", "line", "function"} + assert isinstance(frame["file"], str) + assert isinstance(frame["line"], int) + assert isinstance(frame["function"], str) + + assert stack[0]["file"] == format_py_filename(__file__) + assert stack[0]["function"] == "error" + assert stack[1]["function"] == "test_capture_with_frame" + + def test_filter_frames(): """Verify the frames from the library paths are excluded.""" paths = sysconfig.get_paths() diff --git a/tests/unit/core/test_error.py b/tests/unit/core/test_error.py new file mode 100644 index 00000000..1e946ed9 --- /dev/null +++ b/tests/unit/core/test_error.py @@ -0,0 +1,196 @@ +# coding=utf-8 +from __future__ import absolute_import, division, print_function, unicode_literals + +import sys +from contextlib import contextmanager + +import pytest + +from scout_apm.api import Config +from scout_apm.compat import kwargs_only +from scout_apm.core.error import ErrorMonitor +from scout_apm.core.web_requests import RequestComponents + + +@contextmanager +@kwargs_only +def app_with_scout(scout_config=None): + """ + Context manager that configures and installs the Scout plugin. + """ + # Enable Scout by default in tests. + if scout_config is None: + scout_config = {} + + scout_config.setdefault("monitor", True) + scout_config.setdefault("errors_enabled", True) + Config.set(**scout_config) + + try: + yield + finally: + # Reset Scout configuration. + Config.reset_all() + + +def test_monitor_not_configured(error_monitor_errors): + with app_with_scout(scout_config={"errors_enabled": False}): + ErrorMonitor.send(None) + assert len(error_monitor_errors) == 0 + + +def test_monitor_ignore_exceptions(error_monitor_errors): + with app_with_scout( + scout_config={"errors_ignored_exceptions": [ZeroDivisionError]} + ): + try: + 1 / 0 + except ZeroDivisionError: + exc_info = sys.exc_info() + ErrorMonitor.send(exc_info, request_path="") + assert len(error_monitor_errors) == 0 + + +@pytest.mark.parametrize( + "path, params, session, environment, request_components, " + "custom_controller, custom_params, expected_error", + [ + ( + "/test/", + None, + None, + None, + None, + None, + None, + { + "exception_class": "ZeroDivisionError", + "message": "division by zero", + "request_id": "sample_id", + "request_uri": "/test/", + "request_params": None, + "request_session": None, + "environment": None, + "request_components": None, + "context": {"spam": "foo"}, + "host": None, + "revision_sha": "", + }, + ), + ( + "/test/", + None, + None, + None, + None, + "test-controller", + None, + { + "exception_class": "ZeroDivisionError", + "message": "division by zero", + "request_id": "sample_id", + "request_uri": "/test/", + "request_params": None, + "request_session": None, + "environment": None, + "request_components": { + "module": None, + "controller": "test-controller", + "action": None, + }, + "context": {"spam": "foo"}, + "host": None, + "revision_sha": "", + }, + ), + ( + "/test/", + [("foo", "bar")], + {"spam": "eggs"}, + {"PASSWORD": "hunter2"}, + RequestComponents("sample.app", "DataView", "detail"), + None, + None, + { + "exception_class": "ZeroDivisionError", + "message": "division by zero", + "request_id": "sample_id", + "request_uri": "/test/", + "request_params": [("foo", "bar")], + "request_session": {"spam": "eggs"}, + "environment": {"PASSWORD": "[FILTERED]"}, + "request_components": { + "module": "sample.app", + "controller": "DataView", + "action": "detail", + }, + "context": {"spam": "foo"}, + "host": None, + "revision_sha": "", + }, + ), + ( + "/test/", + [("foo", "bar")], + {"spam": "eggs"}, + {"PASSWORD": "hunter2"}, + RequestComponents("sample.app", "DataView", "detail"), + "test-controller", + {"baz": 3}, + { + "exception_class": "ZeroDivisionError", + "message": "division by zero", + "request_id": "sample_id", + "request_uri": "/test/", + "request_params": [("foo", "bar")], + "request_session": {"spam": "eggs"}, + "environment": {"PASSWORD": "[FILTERED]"}, + "request_components": { + "module": "sample.app", + "controller": "test-controller", + "action": "detail", + }, + "context": {"spam": "foo", "custom_params": {"baz": 3}}, + "host": None, + "revision_sha": "", + }, + ), + ], +) +def test_monitor( + path, + params, + session, + environment, + request_components, + custom_controller, + custom_params, + expected_error, + tracked_request, + error_monitor_errors, +): + with app_with_scout(): + tracked_request.request_id = "sample_id" + tracked_request.tags["spam"] = "foo" + exc_info = 0 + try: + 1 / 0 + except ZeroDivisionError: + exc_info = sys.exc_info() + ErrorMonitor.send( + exc_info, + request_components=request_components, + request_path=path, + request_params=params, + session=session, + environment=environment, + custom_controller=custom_controller, + custom_params=custom_params, + ) + + assert len(error_monitor_errors) == 1 + error = error_monitor_errors[0] + # Remove the trace from the error as it bloats the test. + trace = error.pop("trace") + assert trace[0]["function"] == "test_monitor" + assert error == expected_error diff --git a/tests/unit/core/test_web_requests.py b/tests/unit/core/test_web_requests.py index d48f31cb..936d0c60 100644 --- a/tests/unit/core/test_web_requests.py +++ b/tests/unit/core/test_web_requests.py @@ -12,6 +12,7 @@ CUTOFF_EPOCH_S, convert_ambiguous_timestamp_to_ns, create_filtered_path, + filter_element, ignore_path, track_request_queue_time, ) @@ -44,6 +45,26 @@ def test_create_filtered_path(path, params, expected): assert create_filtered_path(path, params) == expected +@pytest.mark.parametrize( + "key, value, expected", + [ + ("bar", "baz", "baz"), + ("password", "baz", "[FILTERED]"), + ("bar", {"password": "hunter2"}, {"password": "[FILTERED]"}), + ("bar", [{"password": "hunter2"}], [{"password": "[FILTERED]"}]), + ("bar", {"baz"}, {"baz"}), + ( + "bar", + ({"password": "hunter2"}, "baz"), + ({"password": "[FILTERED]"}, "baz"), + ), + ("", None, None), + ], +) +def test_filter_element(key, value, expected): + assert filter_element(key, value) == expected + + @pytest.mark.parametrize("path, params", [("/", []), ("/", [("foo", "ignored")])]) def test_create_filtered_path_path(path, params): # If config filtered_params is set to "path", expect we always get the path From ff18efdb92839c126b5e4a8fb0ba2d248d41eb41 Mon Sep 17 00:00:00 2001 From: Tim Schilling Date: Fri, 9 Jul 2021 09:23:46 -0500 Subject: [PATCH 2/4] Switch trace element to be a list of strings. --- src/scout_apm/core/error.py | 5 ++++- tests/integration/test_api.py | 6 +++++- tests/unit/core/test_error.py | 7 +++++-- 3 files changed, 14 insertions(+), 4 deletions(-) diff --git a/src/scout_apm/core/error.py b/src/scout_apm/core/error.py index 33495393..acd2d8ca 100644 --- a/src/scout_apm/core/error.py +++ b/src/scout_apm/core/error.py @@ -60,7 +60,10 @@ def send( else None, "request_session": filter_element("", session) if session else None, "environment": filter_element("", environment) if environment else None, - "trace": capture(traceback.tb_frame, apply_filter=False), + "trace": [ + "{file}:{line}:in {function}".format(**frame) + for frame in capture(traceback.tb_frame, apply_filter=False) + ], "request_components": { "module": request_components.module, "controller": request_components.controller, diff --git a/tests/integration/test_api.py b/tests/integration/test_api.py index 98f4cc33..daa8186b 100644 --- a/tests/integration/test_api.py +++ b/tests/integration/test_api.py @@ -346,7 +346,11 @@ def test_error_capture(error_monitor_errors, tracked_request): assert len(error_monitor_errors) == 1 error = error_monitor_errors[0] - assert error["trace"][0]["function"] == "test_error_capture" + filepath, line, func_str = error["trace"][0].split(":") + assert filepath.endswith("tests/integration/test_api.py") + # The line number changes between python versions. Make sure it's not empty. + assert line + assert func_str == "in test_error_capture" assert error["exception_class"] == "ZeroDivisionError" assert error["message"] == "division by zero" assert error["context"] == { diff --git a/tests/unit/core/test_error.py b/tests/unit/core/test_error.py index 1e946ed9..b02b5c66 100644 --- a/tests/unit/core/test_error.py +++ b/tests/unit/core/test_error.py @@ -191,6 +191,9 @@ def test_monitor( assert len(error_monitor_errors) == 1 error = error_monitor_errors[0] # Remove the trace from the error as it bloats the test. - trace = error.pop("trace") - assert trace[0]["function"] == "test_monitor" + filepath, line, func_str = error.pop("trace")[0].split(":") + assert filepath.endswith("tests/unit/core/test_error.py") + # The line number changes between python versions. Make sure it's not empty. + assert line + assert func_str == "in test_monitor" assert error == expected_error From 215f9d5b1a2b3b8b60a943d0f8aed7134e746328 Mon Sep 17 00:00:00 2001 From: Tim Schilling Date: Fri, 9 Jul 2021 17:00:25 -0500 Subject: [PATCH 3/4] Support capturing stacktraces. Deprecates backtrace.capture in favor of backtrace.capture_backtrace. --- CHANGELOG.md | 1 + src/scout_apm/core/backtrace.py | 72 +++++++++++++++++---------- src/scout_apm/core/error.py | 13 +++-- src/scout_apm/core/tracked_request.py | 2 +- tests/unit/core/test_backtrace.py | 45 ++++++++--------- 5 files changed, 81 insertions(+), 52 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e8da855c..1f196282 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ - Support Error Monitoring. See [integration docs](https://scoutapm.com/docs/python/error-monitoring). ([PR #651](https://github.com/scoutapp/scout_apm_python/pull/651)) +- Deprecate `backtrace.capture` in favor of `backtrace.capture_backtrace` ### Fixed - Setup metadata keywords now contains an array of strings. diff --git a/src/scout_apm/core/backtrace.py b/src/scout_apm/core/backtrace.py index eb301003..cadf255d 100644 --- a/src/scout_apm/core/backtrace.py +++ b/src/scout_apm/core/backtrace.py @@ -5,6 +5,7 @@ import sys import sysconfig import traceback +import warnings # Maximum non-Scout frames to target retrieving LIMIT = 50 @@ -23,44 +24,52 @@ def filter_frames(frames): if sys.version_info >= (3, 5): - def frame_walker(start_frame=None): - """Iterate over each frame of the stack. + def stacktrace_walker(tb): + """Iterate over each frame of the stack downards for exceptions.""" + for frame, lineno in traceback.walk_tb(tb): + co = frame.f_code + filename = co.co_filename + name = co.co_name + yield {"file": filename, "line": lineno, "function": name} + + def backtrace_walker(): + """Iterate over each frame of the stack upwards. Taken from python3/traceback.ExtractSummary.extract to support iterating over the entire stack, but without creating a large data structure. """ - if start_frame is None: - start_frame = sys._getframe().f_back + start_frame = sys._getframe().f_back for frame, lineno in traceback.walk_stack(start_frame): co = frame.f_code filename = co.co_filename name = co.co_name yield {"file": filename, "line": lineno, "function": name} - def capture(start_frame=None, apply_filter=True): - walker = frame_walker(start_frame) - if apply_filter: - walker = filter_frames(walker) - return list(itertools.islice(walker, LIMIT)) - else: - def frame_walker(start_frame): - """Iterate over each frame of the stack. + def stacktrace_walker(tb): + """Iterate over each frame of the stack downards for exceptions.""" + while tb is not None: + lineno = tb.tb_lineno + co = tb.tb_frame.f_code + filename = co.co_filename + name = co.co_name + yield {"file": filename, "line": lineno, "function": name} + tb = tb.tb_next + + def backtrace_walker(): + """Iterate over each frame of the stack upwards. Taken from python2.7/traceback.extract_stack to support iterating over the entire stack, but without creating a large data structure. """ - if start_frame is None: - try: - raise ZeroDivisionError - except ZeroDivisionError: - # Get the current frame - f = sys.exc_info()[2].tb_frame.f_back - else: - f = start_frame + try: + raise ZeroDivisionError + except ZeroDivisionError: + # Get the current frame + f = sys.exc_info()[2].tb_frame.f_back while f is not None: lineno = f.f_lineno @@ -70,8 +79,21 @@ def frame_walker(start_frame): yield {"file": filename, "line": lineno, "function": name} f = f.f_back - def capture(start_frame=None, apply_filter=True): - walker = frame_walker(start_frame) - if apply_filter: - walker = filter_frames(walker) - return list(itertools.islice(walker, LIMIT)) + +def capture_backtrace(): + walker = filter_frames(backtrace_walker()) + return list(itertools.islice(walker, LIMIT)) + + +def capture_stacktrace(tb): + walker = stacktrace_walker(tb) + return list(reversed(list(itertools.islice(walker, LIMIT)))) + + +def capture(): + warnings.warn( + "capture is deprecated, instead use capture_backtrace instead.", + DeprecationWarning, + 2, + ) + return capture_backtrace() diff --git a/src/scout_apm/core/error.py b/src/scout_apm/core/error.py index acd2d8ca..0473a75a 100644 --- a/src/scout_apm/core/error.py +++ b/src/scout_apm/core/error.py @@ -3,7 +3,7 @@ import sys -from scout_apm.core.backtrace import capture +from scout_apm.core.backtrace import capture_stacktrace from scout_apm.core.config import scout_config from scout_apm.core.error_service import ErrorServiceThread from scout_apm.core.tracked_request import TrackedRequest @@ -50,6 +50,7 @@ def send( module=None, controller=custom_controller, action=None ) + app_root = scout_config.value("application_root") error = { "exception_class": exc_class.__name__, "message": text_type(exc_value), @@ -61,8 +62,14 @@ def send( "request_session": filter_element("", session) if session else None, "environment": filter_element("", environment) if environment else None, "trace": [ - "{file}:{line}:in {function}".format(**frame) - for frame in capture(traceback.tb_frame, apply_filter=False) + "{file}:{line}:in {function}".format( + file=frame["file"].split(app_root, maxsplit=1)[-1] + if app_root + else frame["file"], + line=frame["line"], + function=frame["function"], + ) + for frame in capture_stacktrace(traceback) ], "request_components": { "module": request_components.module, diff --git a/src/scout_apm/core/tracked_request.py b/src/scout_apm/core/tracked_request.py index 55ed674b..3e6a4037 100644 --- a/src/scout_apm/core/tracked_request.py +++ b/src/scout_apm/core/tracked_request.py @@ -285,4 +285,4 @@ def add_allocation_tags(self): self.tag("stop_allocations", end_allocs) def capture_backtrace(self): - self.tag("stack", backtrace.capture()) + self.tag("stack", backtrace.capture_backtrace()) diff --git a/tests/unit/core/test_backtrace.py b/tests/unit/core/test_backtrace.py index b45b28c5..14a511a6 100644 --- a/tests/unit/core/test_backtrace.py +++ b/tests/unit/core/test_backtrace.py @@ -8,8 +8,8 @@ from scout_apm.core import backtrace -def test_capture(): - stack = backtrace.capture() +def test_capture_backtrace(): + stack = backtrace.capture_backtrace() assert isinstance(stack, list) assert len(stack) >= 1 @@ -30,10 +30,10 @@ def format_py_filename(filename): return filename -def test_capture_limit(): +def test_capture_backtrace_limit(): def capture_recursive_bottom(limit): if limit <= 1: - return backtrace.capture() + return backtrace.capture_backtrace() else: return capture_recursive_bottom(limit - 1) @@ -41,18 +41,32 @@ def capture_recursive_bottom(limit): assert len(stack) == backtrace.LIMIT -def test_capture_with_frame(): +def test_filter_frames(): + """Verify the frames from the library paths are excluded.""" + paths = sysconfig.get_paths() + library_path = {paths["purelib"], paths["platlib"]}.pop() + frames = [ + {"file": os.path.join(library_path, "test"), "line": 1, "function": "foo"}, + {"file": "/valid/path", "line": 1, "function": "foo"}, + ] + + actual = list(backtrace.filter_frames(frames)) + assert len(actual) == 1 + assert actual[0]["file"] == "/valid/path" + + +def test_capture_stacktrace(): def error(): # Python 2 compatible way of getting the current frame. try: raise ZeroDivisionError except ZeroDivisionError: # Get the current frame - return sys.exc_info()[2].tb_frame + return sys.exc_info()[2] - stack = backtrace.capture(error(), apply_filter=False) + stack = backtrace.capture_stacktrace(error()) - assert len(stack) >= 1 + assert len(stack) == 1 for frame in stack: assert isinstance(frame, dict) assert set(frame.keys()) == {"file", "line", "function"} @@ -62,18 +76,3 @@ def error(): assert stack[0]["file"] == format_py_filename(__file__) assert stack[0]["function"] == "error" - assert stack[1]["function"] == "test_capture_with_frame" - - -def test_filter_frames(): - """Verify the frames from the library paths are excluded.""" - paths = sysconfig.get_paths() - library_path = {paths["purelib"], paths["platlib"]}.pop() - frames = [ - {"file": os.path.join(library_path, "test"), "line": 1, "function": "foo"}, - {"file": "/valid/path", "line": 1, "function": "foo"}, - ] - - actual = list(backtrace.filter_frames(frames)) - assert len(actual) == 1 - assert actual[0]["file"] == "/valid/path" From 4b8ef04d04510e4c1dd4ce6c49658cd312ccb731 Mon Sep 17 00:00:00 2001 From: Tim Schilling Date: Tue, 13 Jul 2021 15:35:51 -0500 Subject: [PATCH 4/4] Remove non-project paths from traces. Fixes #416 --- CHANGELOG.md | 3 + src/scout_apm/core/backtrace.py | 62 +++++++++++++------- src/scout_apm/core/config.py | 2 +- src/scout_apm/core/error.py | 5 +- tests/integration/core/test_error_service.py | 9 ++- tests/integration/test_django.py | 5 +- tests/unit/core/test_backtrace.py | 16 +++-- 7 files changed, 63 insertions(+), 39 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1f196282..870d2849 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,9 @@ ### Fixed - Setup metadata keywords now contains an array of strings. +- Remove non-project paths from traces. + ([Issue #416](https://github.com/scoutapp/scout_apm_python/issues/416)) + ## [2.20.0] 2021-07-21 - Removed parsing queue time from Amazon ALB header, X-Amzn-Trace-Id. diff --git a/src/scout_apm/core/backtrace.py b/src/scout_apm/core/backtrace.py index cadf255d..52c4be17 100644 --- a/src/scout_apm/core/backtrace.py +++ b/src/scout_apm/core/backtrace.py @@ -2,6 +2,7 @@ from __future__ import absolute_import, division, print_function, unicode_literals import itertools +import os import sys import sysconfig import traceback @@ -22,15 +23,36 @@ def filter_frames(frames): yield frame +def module_filepath(module, filepath): + """Get the filepath relative to the base module.""" + root_module = module.split(".", 1)[0] + if root_module == module: + return os.path.basename(filepath) + + module_dir = sys.modules[root_module].__file__.rsplit(os.sep, 2)[0] + return filepath.split(module_dir, 1)[-1].lstrip(os.sep) + + +def filepath(frame): + """Get the filepath for frame.""" + module = frame.f_globals.get("__name__", None) + filepath = frame.f_code.co_filename + + if filepath.endswith(".pyc"): + filepath = filepath[:-1] + + if not module: + return filepath + return module_filepath(module, filepath) + + if sys.version_info >= (3, 5): def stacktrace_walker(tb): """Iterate over each frame of the stack downards for exceptions.""" for frame, lineno in traceback.walk_tb(tb): - co = frame.f_code - filename = co.co_filename - name = co.co_name - yield {"file": filename, "line": lineno, "function": name} + name = frame.f_code.co_name + yield {"file": filepath(frame), "line": lineno, "function": name} def backtrace_walker(): """Iterate over each frame of the stack upwards. @@ -41,10 +63,8 @@ def backtrace_walker(): """ start_frame = sys._getframe().f_back for frame, lineno in traceback.walk_stack(start_frame): - co = frame.f_code - filename = co.co_filename - name = co.co_name - yield {"file": filename, "line": lineno, "function": name} + name = frame.f_code.co_name + yield {"file": filepath(frame), "line": lineno, "function": name} else: @@ -53,10 +73,12 @@ def stacktrace_walker(tb): """Iterate over each frame of the stack downards for exceptions.""" while tb is not None: lineno = tb.tb_lineno - co = tb.tb_frame.f_code - filename = co.co_filename - name = co.co_name - yield {"file": filename, "line": lineno, "function": name} + name = tb.tb_frame.f_code.co_name + yield { + "file": filepath(tb.tb_frame), + "line": lineno, + "function": name, + } tb = tb.tb_next def backtrace_walker(): @@ -69,15 +91,13 @@ def backtrace_walker(): raise ZeroDivisionError except ZeroDivisionError: # Get the current frame - f = sys.exc_info()[2].tb_frame.f_back - - while f is not None: - lineno = f.f_lineno - co = f.f_code - filename = co.co_filename - name = co.co_name - yield {"file": filename, "line": lineno, "function": name} - f = f.f_back + frame = sys.exc_info()[2].tb_frame.f_back + + while frame is not None: + lineno = frame.f_lineno + name = frame.f_code.co_name + yield {"file": filepath(frame), "line": lineno, "function": name} + frame = frame.f_back def capture_backtrace(): diff --git a/src/scout_apm/core/config.py b/src/scout_apm/core/config.py index 020cbdf0..46b20bb5 100644 --- a/src/scout_apm/core/config.py +++ b/src/scout_apm/core/config.py @@ -212,7 +212,7 @@ class Defaults(object): def __init__(self): self.defaults = { "app_server": "", - "application_root": "", + "application_root": os.getcwd(), "collect_remote_ip": True, "core_agent_dir": "/tmp/scout_apm_core", "core_agent_download": True, diff --git a/src/scout_apm/core/error.py b/src/scout_apm/core/error.py index 0473a75a..6c50c2a5 100644 --- a/src/scout_apm/core/error.py +++ b/src/scout_apm/core/error.py @@ -50,7 +50,6 @@ def send( module=None, controller=custom_controller, action=None ) - app_root = scout_config.value("application_root") error = { "exception_class": exc_class.__name__, "message": text_type(exc_value), @@ -63,9 +62,7 @@ def send( "environment": filter_element("", environment) if environment else None, "trace": [ "{file}:{line}:in {function}".format( - file=frame["file"].split(app_root, maxsplit=1)[-1] - if app_root - else frame["file"], + file=frame["file"], line=frame["line"], function=frame["function"], ) diff --git a/tests/integration/core/test_error_service.py b/tests/integration/core/test_error_service.py index 114d1cbd..779b54c0 100644 --- a/tests/integration/core/test_error_service.py +++ b/tests/integration/core/test_error_service.py @@ -2,6 +2,7 @@ from __future__ import absolute_import, division, print_function, unicode_literals import logging +import os from datetime import datetime from time import sleep @@ -12,6 +13,8 @@ from scout_apm.core.error_service import ErrorServiceThread from tests.compat import gzip_decompress +WORKING_DIRECTORY = os.getcwd().encode("utf-8") + @pytest.fixture def error_service_thread(): @@ -41,7 +44,7 @@ def error_service_thread(): ( {}, b'{"notifier": "scout_apm_python", "environment": null, ' - b'"root": "", "problems": [{"foo": "bar"}]}', + b'"root": "' + WORKING_DIRECTORY + b'", "problems": [{"foo": "bar"}]}', {"Agent-Hostname": None, "X-Error-Count": "1"}, "https://errors.scoutapm.com/apps/error.scout" "?name=Python+App", ), @@ -76,7 +79,9 @@ def test_send_batch(error_service_thread): def request_callback(request, uri, response_headers): decompressed_body = ( b'{"notifier": "scout_apm_python", "environment": null, ' - b'"root": "", "problems": [{"foo": 0}, {"foo": 1}, ' + b'"root": "' + + WORKING_DIRECTORY + + b'", "problems": [{"foo": 0}, {"foo": 1}, ' b'{"foo": 2}, {"foo": 3}, {"foo": 4}]}' ) assert gzip_decompress(request.body) == decompressed_body diff --git a/tests/integration/test_django.py b/tests/integration/test_django.py index a70a08f8..0f30a561 100644 --- a/tests/integration/test_django.py +++ b/tests/integration/test_django.py @@ -2,6 +2,7 @@ from __future__ import absolute_import, division, print_function, unicode_literals import datetime as dt +import os import sys from contextlib import contextmanager @@ -117,7 +118,7 @@ def test_instruments_idempotent(func): def test_on_setting_changed_application_root(): with app_with_scout(BASE_DIR="/tmp/foobar"): assert scout_config.value("application_root") == "/tmp/foobar" - assert scout_config.value("application_root") == "" + assert scout_config.value("application_root") == os.getcwd() @skip_if_python_2 @@ -126,7 +127,7 @@ def test_on_setting_changed_application_root_pathlib(): value = scout_config.value("application_root") assert isinstance(value, str) assert value == "/tmp/foobar" - assert scout_config.value("application_root") == "" + assert scout_config.value("application_root") == os.getcwd() def test_on_setting_changed_monitor(): diff --git a/tests/unit/core/test_backtrace.py b/tests/unit/core/test_backtrace.py index 14a511a6..fa4c3a48 100644 --- a/tests/unit/core/test_backtrace.py +++ b/tests/unit/core/test_backtrace.py @@ -20,14 +20,12 @@ def test_capture_backtrace(): assert isinstance(frame["line"], int) assert isinstance(frame["function"], str) - assert stack[0]["file"] == format_py_filename(__file__) - - -def format_py_filename(filename): - if sys.version_info[0] == 2 and filename.endswith(".pyc"): - # Python 2 will include .pyc filename if it's used, so strip that - return filename[:-1] - return filename + assert stack[0]["file"] == "scout_apm/core/backtrace.py" + assert stack[0]["function"] == "filter_frames" + assert stack[1]["file"] == "scout_apm/core/backtrace.py" + assert stack[1]["function"] == "capture_backtrace" + assert stack[2]["file"] == "tests/unit/core/test_backtrace.py" + assert stack[2]["function"] == "test_capture_backtrace" def test_capture_backtrace_limit(): @@ -74,5 +72,5 @@ def error(): assert isinstance(frame["line"], int) assert isinstance(frame["function"], str) - assert stack[0]["file"] == format_py_filename(__file__) + assert stack[0]["file"] == "tests/unit/core/test_backtrace.py" assert stack[0]["function"] == "error"