From 99d33c9de1e5aea980c6a8561e7822f9359bb76d Mon Sep 17 00:00:00 2001 From: Alan Potter Date: Tue, 20 Feb 2024 09:32:50 -0500 Subject: [PATCH 1/7] fix: drop python 3.7 support 3.7 was EOLed 27-Jun-2023. --- .travis.yml | 1 - pyproject.toml | 13 +++++-------- tool-versions.example | 2 +- tox.ini | 2 +- vendor/vendor.txt | 2 +- 5 files changed, 8 insertions(+), 12 deletions(-) diff --git a/.travis.yml b/.travis.yml index dabab0c0..cbcd319b 100644 --- a/.travis.yml +++ b/.travis.yml @@ -7,7 +7,6 @@ python: - "3.10" - "3.9.14" - "3.8" -- "3.7" # https://github.com/travis-ci/travis-ci/issues/1147#issuecomment-441393807 if: type != push OR branch = master OR branch =~ /^v\d+\.\d+(\.\d+)?(-\S*)?$/ diff --git a/pyproject.toml b/pyproject.toml index 4c594ba7..3485cf75 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -38,7 +38,7 @@ packages = [ [tool.poetry.dependencies] # Please update the documentation if changing the supported python version # https://github.com/applandinc/applandinc.github.io/blob/master/_docs/reference/appmap-python.md#supported-versions -python = "^3.7.2" +python = "^3.8" PyYAML = ">=5.3.0" inflection = ">=0.3.0" importlib-metadata = ">=0.8" @@ -46,8 +46,8 @@ importlib-resources = "^5.4.0" packaging = ">=19.0" # If you include "Django" as an optional dependency here, you'll be able to use poetry to install it # in your dev environment. However, doing so causes poetry v1.2.0 to remove it from the virtualenv -# *created and managed by tox*, i.e. not your dev environment. -# +# *created and managed by tox*, i.e. not your dev environment. +# # So, if you'd like to run the tests outside of tox, run `pip install -r requirements-dev.txt` to # install it and the rest of the dev dependencies. @@ -56,16 +56,13 @@ httpretty = "^1.0.5" pytest = "^7.3.2" pytest-randomly = "^3.5.0" pylint = "^2.6.0" -pytest-django = [ - { version = "~4.7", python = ">=3.8" }, - { version = "<4.7", python = "3.7" } -] +pytest-django = "~4.7" flake8 = "^3.8.4" pyfakefs = "^5.3.5" pprintpp = ">=0.4.0" coverage = "^5.3" pytest-mock = "^3.5.1" -SQLAlchemy = { version = "^1.4.11", python = "^3.7"} +SQLAlchemy = "^1.4.11" tox = "^3.22.0" Twisted = "^22.4.0" requests = "^2.25.1" diff --git a/tool-versions.example b/tool-versions.example index e3cc7d7a..4a4d044f 100644 --- a/tool-versions.example +++ b/tool-versions.example @@ -1 +1 @@ -python 3.7.14 3.8.14 3.9.14 3.10.7 +python 3.8.18 3.9.18 3.10.13 3.11.7 3.12.1 diff --git a/tox.ini b/tox.ini index 7deeb8e0..5dfa9829 100644 --- a/tox.ini +++ b/tox.ini @@ -2,7 +2,7 @@ isolated_build = true # The *-web environments test the latest versions of Django and Flask with the full test suite. For # older version of the web frameworks, just run the tests that are specific to them. -envlist = py3{8,9,10,11,12}-web, py3{7,8,9,10,11,12}-flask1-django3 +envlist = py3{8,9,10,11,12}-web, py3{8,9,10,11,12}-flask1-django3 [testenv] allowlist_externals = diff --git a/vendor/vendor.txt b/vendor/vendor.txt index 79b49d28..49878927 100644 --- a/vendor/vendor.txt +++ b/vendor/vendor.txt @@ -1 +1 @@ -wrapt==1.15.0 ; python_version >= "3.7" and python_version < "4.0" \ No newline at end of file +wrapt==1.15.0 ; python_version >= "3.8" and python_version < "4.0" \ No newline at end of file From 81f286f806104a956b8f5d694361c772f47539e9 Mon Sep 17 00:00:00 2001 From: Alan Potter Date: Fri, 16 Feb 2024 13:55:54 -0500 Subject: [PATCH 2/7] refactor: add a little typing, fix issues Adding some typing revealed some issues, fix them. --- _appmap/django.py | 2 ++ _appmap/web_framework.py | 41 ++++++++++++++++++++++------------------ appmap/django.py | 6 ++++-- appmap/flask.py | 5 ++--- 4 files changed, 31 insertions(+), 23 deletions(-) diff --git a/_appmap/django.py b/_appmap/django.py index 69c11d58..ab74d141 100644 --- a/_appmap/django.py +++ b/_appmap/django.py @@ -30,5 +30,7 @@ def __call__(self, request: HttpRequest): def not_allowed(): return "", HTTPStatus.METHOD_NOT_ALLOWED + assert request.method is not None body, status = handlers.get(request.method, not_allowed)() + return HttpResponse(body, status=status, content_type="application/json") diff --git a/_appmap/web_framework.py b/_appmap/web_framework.py index 85aafd98..85c2e1b1 100644 --- a/_appmap/web_framework.py +++ b/_appmap/web_framework.py @@ -11,17 +11,18 @@ from contextvars import ContextVar from hashlib import sha256 from json.decoder import JSONDecodeError +from typing import Any, Optional, Protocol, Tuple from _appmap import recording -from . import generation, remote_recording +from . import remote_recording from .env import Env from .event import Event, ReturnEvent, describe_value from .recorder import Recorder, ThreadRecorder from .utils import root_relative_path, scenario_filename logger = Env.current.getLogger(__name__) -request_recorder = ContextVar("appmap_request_recorder") +request_recorder: ContextVar[Optional[Recorder]] = ContextVar("appmap_request_recorder") # These are the errors that can get raised when trying to update params based on the results of # parsing the body of an application/json request: @@ -51,7 +52,11 @@ def to_dict(self, attrs=None): return result -class TemplateHandler: # pylint: disable=too-few-public-methods +class HasFilename(Protocol): + filename: str + + +class TemplateHandler(HasFilename): # pylint: disable=too-few-public-methods """Patch for a template class to capture and record template rendering (if recording is enabled). @@ -66,10 +71,11 @@ def render(self, orig, *args, **kwargs): If recording is enabled, adds appropriate TemplateEvent and ReturnEvent. """ + rec = Recorder.get_current() if rec.get_enabled(): start = time.monotonic() - call_event = TemplateEvent(self.filename, self) # pylint: disable=no-member + call_event = TemplateEvent(self.filename, self) Recorder.add_event(call_event) try: return orig(self, *args, **kwargs) @@ -122,6 +128,14 @@ def create_appmap_file( class AppmapMiddleware(ABC): + @abstractmethod + def before_request_main(self, rec, req) -> Tuple[float, int]: + """Specify the main operations to be performed by a request is processed.""" + + @abstractmethod + def after_request_main(self, rec, response, start, call_event_id) -> None: + """Specify the main operations to be performed after a request is processed.""" + def __init__(self, framework_name): self.record_url = "/_appmap/record" env = Env.current @@ -131,13 +145,10 @@ def __init__(self, framework_name): self.should_record = env.enables("remote") or record_requests - def before_request_hook(self, request, request_path): - if request_path == self.record_url: - return None, None, None - + def before_request_hook(self, request, _) -> Tuple[Optional[Recorder], float, int]: rec = None - start = None - call_event_id = None + start = 0 + call_event_id = 0 env = Env.current if env.enables("requests"): rec = ThreadRecorder() @@ -152,10 +163,6 @@ def before_request_hook(self, request, request_path): return rec, start, call_event_id - @abstractmethod - def before_request_main(self, rec, req): - """Specify the main operations to be performed by a request is processed.""" - def after_request_hook( self, request_path, @@ -172,6 +179,8 @@ def after_request_hook( env = Env.current if env.enables("requests"): rec = request_recorder.get() + assert rec is not None + try: self.after_request_main(rec, response, start, call_event_id) @@ -196,10 +205,6 @@ def after_request_hook( return response - @abstractmethod - def after_request_main(self, rec, response, start, call_event_id): - """Specify the main operations to be performed after a request is processed.""" - class MiddlewareInserter(ABC): def __init__(self, debug): diff --git a/appmap/django.py b/appmap/django.py index 95afbefd..de56b6d6 100644 --- a/appmap/django.py +++ b/appmap/django.py @@ -119,7 +119,7 @@ def wrapped_execute(self, sql, params=None): return original_execute(self, sql, params) -CursorDebugWrapper.execute = wrapped_execute +CursorDebugWrapper.execute = wrapped_execute # type: ignore[method-assign] @receiver(connection_created) @@ -226,6 +226,8 @@ def __call__(self, request): return self.get_response(request) rec, start, call_event_id = self.before_request_hook(request, request.path_info) + if rec is None: + return self.get_response(request) try: response = self.get_response(request) @@ -338,7 +340,7 @@ def load_middleware(*args, **kwargs): return original_load_middleware(*args, **kwargs) -BaseHandler.load_middleware = load_middleware +BaseHandler.load_middleware = load_middleware # type: ignore[method-assign] @patch_class(Template) diff --git a/appmap/flask.py b/appmap/flask.py index 2fb5e037..b5e954dc 100644 --- a/appmap/flask.py +++ b/appmap/flask.py @@ -189,6 +189,5 @@ def install_extension(wrapped, _, args, kwargs): # ScriptInfo.load_app is the function that's used by the Flask cli to load an app, no matter how # the app's module is specified (e.g. with the FLASK_APP env var, the `--app` flag, etc). Hook # it so it installs our extension on the app. - ScriptInfo.load_app = wrapt.wrap_function_wrapper( - "flask.cli", "ScriptInfo.load_app", install_extension - ) + load_app = wrapt.wrap_function_wrapper("flask.cli", "ScriptInfo.load_app", install_extension) + ScriptInfo.load_app = load_app # type: ignore[method-assign] From ffd37381df94ef0f047219480d340c7619301497 Mon Sep 17 00:00:00 2001 From: Alan Potter Date: Wed, 21 Feb 2024 15:50:47 -0500 Subject: [PATCH 3/7] fix: add TRACE log level In spite of the stand library's assertion that it provides all the log levels needed, it really seems useful to have a TRACE level. Add it, and cut down some of the cruft logged at DEBUG. --- _appmap/configuration.py | 22 ++++++++++------------ _appmap/env.py | 8 ++++++-- _appmap/importer.py | 24 ++++++++++++------------ _appmap/instrument.py | 4 ++-- _appmap/trace_logger.py | 14 ++++++++++++++ _appmap/utils.py | 9 +++++++-- 6 files changed, 51 insertions(+), 30 deletions(-) create mode 100644 _appmap/trace_logger.py diff --git a/_appmap/configuration.py b/_appmap/configuration.py index 2883db3c..fed32b07 100644 --- a/_appmap/configuration.py +++ b/_appmap/configuration.py @@ -96,15 +96,15 @@ def find_top_packages(rootdir): def excluded(d): excluded = d == "node_modules" or d[0] == "." if excluded: - logger.debug("excluding dir %s", d) + logger.trace("excluding dir %s", d) return excluded sys_prefix = _get_sys_prefix() for d, dirs, files in os.walk(rootdir): - logger.debug("dir %s dirs %s", d, dirs) + logger.trace("dir %s dirs %s", d, dirs) if realpath(d) == sys_prefix: - logger.debug("skipping sys.prefix %s", sys_prefix) + logger.trace("skipping sys.prefix %s", sys_prefix) dirs.clear() continue @@ -124,7 +124,7 @@ class Config: def __new__(cls): if cls._instance is None: - logger.debug("Creating the Config object") + logger.trace("Creating the Config object") cls._instance = super(Config, cls).__new__(cls) cls._instance._initialized = False @@ -143,7 +143,7 @@ def __init__(self): self._load_config() self._load_functions() logger.info("config: %s", self._config) - logger.info("package_functions: %s", self.package_functions) + logger.debug("package_functions: %s", self.package_functions) if "labels" in self._config: self.labels.append(self._config["labels"]) @@ -299,7 +299,7 @@ def matches(self, filterable): logger.info("%r excluded", fqname) else: result = False - logger.debug("%r.matches(%r) -> %r", self, fqname, result) + logger.trace("%r.matches(%r) -> %r", self, fqname, result) return result def __repr__(self): @@ -319,9 +319,7 @@ def __init__(self, dist, *args, **kwargs): def matches(self, filterable): try: obj = filterable.obj - logger.debug( - "%r.matches(%r): %s in %r", self, obj, inspect.getfile(obj), self.files - ) + logger.trace("%r.matches(%r): %s in %r", self, obj, inspect.getfile(obj), self.files) if inspect.getfile(obj) not in self.files: return False except TypeError: @@ -347,7 +345,7 @@ def filter(self, filterable): result = any( m.matches(filterable) for m in self.matchers ) or self.next_filter.filter(filterable) - logger.debug("ConfigFilter.filter(%r) -> %r", filterable.fqname, result) + logger.trace("ConfigFilter.filter(%r) -> %r", filterable.fqname, result) return result def wrap(self, filterable): @@ -364,13 +362,13 @@ def wrap(self, filterable): rule = self.match(filterable) wrapped = getattr(filterable.obj, "_appmap_wrapped", None) if wrapped is None: - logger.debug(" wrapping %s", filterable.fqname) + logger.trace(" wrapping %s", filterable.fqname) Config().labels.apply(filterable) ret = instrument(filterable) if rule and rule.shallow: setattr(ret, "_appmap_shallow", rule) else: - logger.debug(" already wrapped %s", filterable.fqname) + logger.trace(" already wrapped %s", filterable.fqname) ret = filterable.obj return ret diff --git a/_appmap/env.py b/_appmap/env.py index 4deea6ab..8f230376 100644 --- a/_appmap/env.py +++ b/_appmap/env.py @@ -7,6 +7,8 @@ from os import environ from pathlib import Path +from . import trace_logger + _cwd = Path.cwd() _bootenv = environ.copy() @@ -115,10 +117,12 @@ def is_appmap_repo(self): def display_params(self): return self.get("APPMAP_DISPLAY_PARAMS", "true").lower() == "true" - def getLogger(self, name): - return logging.getLogger(name) + def getLogger(self, name) -> trace_logger.TraceLogger: + return cast(trace_logger.TraceLogger, logging.getLogger(name)) def _configure_logging(self): + trace_logger.install() + log_level = self.get("APPMAP_LOG_LEVEL", "warning").upper() log_config = self.get("APPMAP_LOG_CONFIG") diff --git a/_appmap/importer.py b/_appmap/importer.py index e146de2e..5cbee04e 100644 --- a/_appmap/importer.py +++ b/_appmap/importer.py @@ -167,14 +167,14 @@ def do_import(cls, *args, **kwargs): if mod.__name__.startswith(cls._skip_instrumenting): return - logger.debug("do_import, mod %s args %s kwargs %s", mod, args, kwargs) + logger.trace("do_import, mod %s args %s kwargs %s", mod, args, kwargs) if not cls.filter_chain: cls.filter_chain = reduce(lambda acc, e: e(acc), cls.filter_stack, NullFilter(None)) def instrument_functions(filterable, selected_functions=None): - logger.debug(" looking for members of %s", filterable.obj) + logger.trace(" looking for members of %s", filterable.obj) functions = get_members(filterable.obj) - logger.debug(" functions %s", functions) + logger.trace(" functions %s", functions) for fn_name, static_fn, fn in functions: # Only instrument the function if it was specifically called out for the package @@ -198,11 +198,11 @@ def instrument_functions(filterable, selected_functions=None): instrument_functions(fm) classes = get_classes(mod) - logger.debug(" classes %s", classes) + logger.trace(" classes %s", classes) for c in classes: fc = FilterableCls(c) if fc.fqname.startswith(cls._skip_instrumenting): - logger.debug(" not instrumenting %s", fc.fqname) + logger.trace(" not instrumenting %s", fc.fqname) continue if fc.fqname in package_functions: instrument_functions(fc, package_functions.get(fc.fqname)) @@ -221,18 +221,18 @@ def wrap_finder_function(fn, decorator): obj = fn.__self__ if hasattr(fn, "__self__") else fn if getattr(obj, marker, None) is None: - logger.debug("wrapping %r", fn) + logger.trace("wrapping %r", fn) ret = decorator(fn) setattr(obj, marker, True) else: - logger.debug("already wrapped, %r", fn) + logger.trace("already wrapped, %r", fn) return ret @wrapt.decorator def wrapped_exec_module(exec_module, _, args, kwargs): - logger.debug("exec_module %r args %s kwargs %s", exec_module, args, kwargs) + logger.trace("exec_module %r args %s kwargs %s", exec_module, args, kwargs) exec_module(*args, **kwargs) # Only process imports if we're currently enabled. This # handles the case where we previously hooked the finders, but @@ -264,7 +264,7 @@ def wrapped_find_spec(find_spec, _, args, kwargs): else: loader.exec_module = wrap_exec_module(loader.exec_module) else: - logger.debug("no exec_module for loader %r", spec.loader) + logger.trace("no exec_module for loader %r", spec.loader) return spec @@ -275,14 +275,14 @@ def wrap_finder_find_spec(finder): if sys.version_info[1] < 11: find_spec = getattr(finder, "find_spec", None) if find_spec is None: - logger.debug("no find_spec for finder %r", finder) + logger.trace("no find_spec for finder %r", finder) return finder.find_spec = wrap_finder_function(find_spec, wrapped_find_spec) else: find_spec = inspect.getattr_static(finder, "find_spec", None) if find_spec is None: - logger.debug("no find_spec for finder %r", finder) + logger.trace("no find_spec for finder %r", finder) return if isinstance(find_spec, (classmethod, staticmethod)): @@ -319,7 +319,7 @@ def initialize(): Importer.initialize() # If we're not enabled, there's no reason to hook the finders. if Env.current.enabled: - logger.debug("sys.metapath: %s", sys.meta_path) + logger.trace("sys.metapath: %s", sys.meta_path) for finder in sys.meta_path: wrap_finder_find_spec(finder) diff --git a/_appmap/instrument.py b/_appmap/instrument.py index 914d7458..0e5b1057 100644 --- a/_appmap/instrument.py +++ b/_appmap/instrument.py @@ -48,7 +48,7 @@ def track_shallow(fn): """ tls = appmap_tls() rule = getattr(fn, "_appmap_shallow", None) - logger.debug("track_shallow(%r) [%r]", fn, rule) + logger.trace("track_shallow(%r) [%r]", fn, rule) result = rule and tls.get("last_rule", None) == rule tls["last_rule"] = rule return result @@ -82,7 +82,7 @@ def call_instrumented(f, instance, args, kwargs): return f.fn(*args, **kwargs) with recording_disabled(): - logger.debug("%s args %s kwargs %s", f.fn, args, kwargs) + logger.trace("%s args %s kwargs %s", f.fn, args, kwargs) params = CallEvent.set_params(f.params, instance, args, kwargs) call_event = f.make_call_event(parameters=params) Recorder.add_event(call_event) diff --git a/_appmap/trace_logger.py b/_appmap/trace_logger.py new file mode 100644 index 00000000..a9953636 --- /dev/null +++ b/_appmap/trace_logger.py @@ -0,0 +1,14 @@ +# trace_logger.py +import logging + +TRACE = logging.DEBUG - 5 +# pyright: reportAttributeAccessIssue=false +class TraceLogger(logging.Logger): + def trace(self, msg, /, *args, **kwargs): + if self.isEnabledFor(TRACE): + self._log(TRACE, msg, args, **kwargs) + + +def install(): + logging.setLoggerClass(TraceLogger) + logging.addLevelName(TRACE, "TRACE") diff --git a/_appmap/utils.py b/_appmap/utils.py index 932a287f..69dcf600 100644 --- a/_appmap/utils.py +++ b/_appmap/utils.py @@ -1,3 +1,4 @@ +from contextvars import ContextVar import inspect import os import re @@ -61,11 +62,15 @@ def __len__(self): return len(self.values) -_appmap_tls = ThreadLocalDict() +_appmap_tls = ContextVar("tls") def appmap_tls(): - return _appmap_tls + try: + return _appmap_tls.get() + except LookupError: + _appmap_tls.set({}) + return _appmap_tls.get() def fqname(cls): From 8c625b024f272dd98837e374e81a47503aa18bc9 Mon Sep 17 00:00:00 2001 From: Alan Potter Date: Tue, 27 Feb 2024 05:23:32 -0500 Subject: [PATCH 4/7] fix: Flask integration should record exceptions Make sure an exception in a Flask route handler gets recorded. Also, refactor web_framework a bit. --- _appmap/env.py | 3 +- _appmap/test/data/flask/app.py | 5 +++ _appmap/test/test_django.py | 1 + _appmap/test/test_flask.py | 15 ++++++++ _appmap/web_framework.py | 63 ++++++++++++++++++++++------------ appmap/django.py | 42 ++++------------------- appmap/flask.py | 59 ++++++++++++++++--------------- pylintrc | 3 +- 8 files changed, 103 insertions(+), 88 deletions(-) diff --git a/_appmap/env.py b/_appmap/env.py index 8f230376..8a558c88 100644 --- a/_appmap/env.py +++ b/_appmap/env.py @@ -1,11 +1,12 @@ """Initialize from the environment""" -from contextlib import contextmanager import logging import logging.config import os +from contextlib import contextmanager from os import environ from pathlib import Path +from typing import cast from . import trace_logger diff --git a/_appmap/test/data/flask/app.py b/_appmap/test/data/flask/app.py index 73730b97..a2c819b9 100644 --- a/_appmap/test/data/flask/app.py +++ b/_appmap/test/data/flask/app.py @@ -45,3 +45,8 @@ def show_user_post(username, post_id): @app.route("//posts/") def show_org_user_posts(org, username): return f"org {org} username {username}" + + +@app.route("/exception") +def raise_exception(): + raise Exception("An exception") diff --git a/_appmap/test/test_django.py b/_appmap/test/test_django.py index 65fc2bec..047750e9 100644 --- a/_appmap/test/test_django.py +++ b/_appmap/test/test_django.py @@ -152,6 +152,7 @@ def raise_on_call(*args): {"request_method": "GET", "path_info": "/exception", "protocol": "HTTP/1.1"} ) + assert events[1].event == "return" assert events[1].parent_id == events[0].id assert events[1].exceptions == [ DictIncluding({"class": "builtins.RuntimeError", "message": "An error"}) diff --git a/_appmap/test/test_flask.py b/_appmap/test/test_flask.py index 7951557d..5a324723 100644 --- a/_appmap/test/test_flask.py +++ b/_appmap/test/test_flask.py @@ -59,6 +59,21 @@ def test_framework_metadata(client, events): # pylint: disable=unused-argument assert Metadata()["frameworks"] == [{"name": "flask", "version": flask.__version__}] +@pytest.mark.appmap_enabled(env={"APPMAP_RECORD_REQUESTS": "false"}) +def test_exception(client, events): # pylint: disable=unused-argument + with pytest.raises(Exception): + client.get("/exception") + + assert events[0].http_server_request == DictIncluding( + {"request_method": "GET", "path_info": "/exception", "protocol": "HTTP/1.1"} + ) + assert events[1].event == "return" + assert events[1].parent_id == events[0].id + assert events[1].exceptions == [ + DictIncluding({"class": "builtins.Exception", "message": "An exception"}) + ] + + @pytest.mark.appmap_enabled def test_template(app, events): with app.app_context(): diff --git a/_appmap/web_framework.py b/_appmap/web_framework.py index 85c2e1b1..6cb26efb 100644 --- a/_appmap/web_framework.py +++ b/_appmap/web_framework.py @@ -17,7 +17,13 @@ from . import remote_recording from .env import Env -from .event import Event, ReturnEvent, describe_value +from .event import ( + Event, + ExceptionEvent, + HttpServerResponseEvent, + ReturnEvent, + describe_value, +) from .recorder import Recorder, ThreadRecorder from .utils import root_relative_path, scenario_filename @@ -52,7 +58,7 @@ def to_dict(self, attrs=None): return result -class HasFilename(Protocol): +class HasFilename(Protocol): # pylint: disable=too-few-public-methods filename: str @@ -99,7 +105,7 @@ def create_appmap_file( request_method, request_path_info, request_full_path, - response, + status, headers, rec, ): @@ -109,7 +115,7 @@ def create_appmap_file( + " " + request_path_info + " (" - + str(response.status_code) + + str(status) + ") - " + start_time.strftime("%T.%f")[:-3] ) @@ -129,23 +135,30 @@ def create_appmap_file( class AppmapMiddleware(ABC): @abstractmethod - def before_request_main(self, rec, req) -> Tuple[float, int]: + def before_request_main(self, rec, req: Any) -> Tuple[float, int]: """Specify the main operations to be performed by a request is processed.""" - - @abstractmethod - def after_request_main(self, rec, response, start, call_event_id) -> None: - """Specify the main operations to be performed after a request is processed.""" + raise NotImplementedError + + def after_request_main(self, rec, status, headers, start, call_event_id) -> None: + duration = time.monotonic() - start + return_event = HttpServerResponseEvent( + parent_id=call_event_id, + elapsed=duration, + status_code=status, + headers=dict(headers.items()), + ) + rec.add_event(return_event) def __init__(self, framework_name): self.record_url = "/_appmap/record" env = Env.current record_requests = env.enables("requests") if record_requests: - logger.debug("Requests will be recorded (%s)", framework_name) + logger.info("Requests will be recorded (%s)", framework_name) self.should_record = env.enables("remote") or record_requests - def before_request_hook(self, request, _) -> Tuple[Optional[Recorder], float, int]: + def before_request_hook(self, request) -> Tuple[Optional[Recorder], float, int]: rec = None start = 0 call_event_id = 0 @@ -168,13 +181,13 @@ def after_request_hook( request_path, request_method, request_base_url, - response, - response_headers, + status, + headers, start, call_event_id, - ): + ) -> None: if request_path == self.record_url: - return response + return env = Env.current if env.enables("requests"): @@ -182,7 +195,7 @@ def after_request_hook( assert rec is not None try: - self.after_request_main(rec, response, start, call_event_id) + self.after_request_main(rec, status, headers, start, call_event_id) output_dir = Env.current.output_dir / "requests" create_appmap_file( @@ -190,8 +203,8 @@ def after_request_hook( request_method, request_path, request_base_url, - response, - response_headers, + status, + headers, rec, ) finally: @@ -200,10 +213,18 @@ def after_request_hook( request_recorder.set(None) elif env.enables("remote"): rec = Recorder.get_global() + assert rec is not None if rec.get_enabled(): - self.after_request_main(rec, response, start, call_event_id) - - return response + self.after_request_main(rec, status, headers, start, call_event_id) + + def on_exception(self, rec, start, call_event_id, exc_info): + duration = time.monotonic() - start + exception_event = ExceptionEvent( + parent_id=call_event_id, + elapsed=duration, + exc_info=exc_info, + ) + rec.add_event(exception_event) class MiddlewareInserter(ABC): diff --git a/appmap/django.py b/appmap/django.py index de56b6d6..56b4b83c 100644 --- a/appmap/django.py +++ b/appmap/django.py @@ -19,13 +19,7 @@ from django.urls.exceptions import Resolver404 from _appmap.env import Env -from _appmap.event import ( - ExceptionEvent, - HttpServerRequestEvent, - HttpServerResponseEvent, - ReturnEvent, - SqlEvent, -) +from _appmap.event import HttpServerRequestEvent, ReturnEvent, SqlEvent from _appmap.instrument import is_instrumentation_disabled from _appmap.metadata import Metadata from _appmap.recorder import Recorder @@ -65,9 +59,7 @@ def __init__(self): self.recorder = Recorder.get_current() # This signature is correct, the implementation confuses pylint: - def __call__( - self, execute, sql, params, many, context - ): # pylint: disable=too-many-arguments + def __call__(self, execute, sql, params, many, context): # pylint: disable=too-many-arguments start = time.monotonic() try: return execute(sql, params, many, context) @@ -93,9 +85,7 @@ def __call__( else: cursor = context["cursor"] sql = conn.ops.last_executed_query(cursor, sql, params) - call_event = SqlEvent( - sql, vendor=conn.vendor, version=database_version(conn) - ) + call_event = SqlEvent(sql, vendor=conn.vendor, version=database_version(conn)) Recorder.add_event(call_event) return_event = ReturnEvent(parent_id=call_event.id, elapsed=duration) Recorder.add_event(return_event) @@ -171,8 +161,7 @@ def get_resolved_match(path_info, resolver): match = re.match(regex, path_info[1:]) if not match: raise RuntimeError( - "No match for %s found with resolver %r, regex %s" - % (path_info, resolver, regex) + "No match for %s found with resolver %r, regex %s" % (path_info, resolver, regex) ) return (regex, match) @@ -225,28 +214,21 @@ def __call__(self, request): if not self.should_record: return self.get_response(request) - rec, start, call_event_id = self.before_request_hook(request, request.path_info) + rec, start, call_event_id = self.before_request_hook(request) if rec is None: return self.get_response(request) try: response = self.get_response(request) except: - if rec.get_enabled(): - duration = time.monotonic() - start - exception_event = ExceptionEvent( - parent_id=call_event_id, - elapsed=duration, - exc_info=sys.exc_info(), - ) - rec.add_event(exception_event) + self.on_exception(rec, start, call_event_id, sys.exc_info()) raise self.after_request_hook( request.path_info, request.method, request.build_absolute_uri(), - response, + response.status_code, response, start, call_event_id, @@ -279,16 +261,6 @@ def before_request_main(self, rec, req): return start, call_event.id - def after_request_main(self, rec, response, start, call_event_id): - duration = time.monotonic() - start - return_event = HttpServerResponseEvent( - parent_id=call_event_id, - elapsed=duration, - status_code=response.status_code, - headers=dict(response.items()), - ) - rec.add_event(return_event) - class DjangoInserter(MiddlewareInserter): def __init__(self, settings): diff --git a/appmap/flask.py b/appmap/flask.py index b5e954dc..ef81bd06 100644 --- a/appmap/flask.py +++ b/appmap/flask.py @@ -4,14 +4,14 @@ import flask import flask.cli import jinja2 -from flask import g, request +from flask import g, got_request_exception, request, request_finished, request_started from flask.cli import ScriptInfo from werkzeug.exceptions import BadRequest, UnsupportedMediaType from werkzeug.middleware.dispatcher import DispatcherMiddleware from _appmap import wrapt from _appmap.env import Env -from _appmap.event import HttpServerRequestEvent, HttpServerResponseEvent +from _appmap.event import HttpServerRequestEvent from _appmap.flask import app as remote_recording_app from _appmap.metadata import Metadata from _appmap.utils import patch_class, values_dict @@ -82,20 +82,18 @@ def init_app(self, app): remote_enabled = Env.current.enables("remote", enable_by_default) if remote_enabled: logger.debug("Remote recording is enabled (Flask)") - app.wsgi_app = DispatcherMiddleware( - app.wsgi_app, {"/_appmap": remote_recording_app} - ) + app.wsgi_app = DispatcherMiddleware(app.wsgi_app, {"/_appmap": remote_recording_app}) setattr(app, _REMOTE_ENABLED_ATTR, remote_enabled) - app.before_request(self.before_request) - app.after_request(self.after_request) - setattr(app, _REQUEST_ENABLED_ATTR, True) + request_started.connect(self.request_started, app, weak=False) + request_finished.connect(self.request_finished, app, weak=False) + got_request_exception.connect(self.got_request_exception, app, weak=False) - def before_request(self): - if not self.should_record: - return + setattr(app, _REQUEST_ENABLED_ATTR, True) - self.before_request_hook(request, request.path) + def request_started(self, _, **__): + # request context is bound, we can use flask.request now: + self.before_request_hook(request) def before_request_main(self, rec, req): Metadata.add_framework("flask", flask.__version__) @@ -123,37 +121,38 @@ def before_request_main(self, rec, req): ) rec.add_event(call_event) - # Flask 2 removed the suggestion to use _app_ctx_stack.top, and instead says extensions - # should use g with a private property. + # Save the current recorder in flask.g, so it will be available in + # the got_request_exception signal handler. Flask seems to be resetting the + # current Context before signaling, which removes our ContextVar. + # TODO: enhance AppmapMiddleware so it allows subclasses to specify how + # the request recording should be stored. + g._appmap_recorder = rec # pylint: disable=protected-access g._appmap_request_event = call_event # pylint: disable=protected-access g._appmap_request_start = time.monotonic() # pylint: disable=protected-access return None, None - def after_request(self, response): + def request_finished(self, _, response, **__): if not self.should_record: return response - return self.after_request_hook( + self.after_request_hook( request.path, request.method, request.base_url, - response, + response.status_code, response.headers, - None, - None, + g._appmap_request_start, # pylint: disable=protected-access + g._appmap_request_event.id, # pylint: disable=protected-access ) - - def after_request_main(self, rec, response, start, _): - parent_id = g._appmap_request_event.id # pylint: disable=protected-access - start = g._appmap_request_start # pylint: disable=protected-access - duration = time.monotonic() - start - return_event = HttpServerResponseEvent( - parent_id=parent_id, - elapsed=duration, - status_code=response.status_code, - headers=response.headers, + return response + + def got_request_exception(self, _, exception): + self.on_exception( + g._appmap_recorder, # pylint: disable=protected-access + g._appmap_request_start, # pylint: disable=protected-access + g._appmap_request_event.id, # pylint: disable=protected-access + (type(exception), exception, None), ) - rec.add_event(return_event) @patch_class(jinja2.Template) diff --git a/pylintrc b/pylintrc index 425c3d31..7f95670e 100644 --- a/pylintrc +++ b/pylintrc @@ -428,7 +428,8 @@ disable=raw-checker-failed, missing-function-docstring, missing-class-docstring, missing-module-docstring, - consider-using-f-string + consider-using-f-string, + fixme # Enable the message, report, category or checker with the given id(s). You can # either give multiple identifier separated by comma (,) or put this option From da1eba2a3cfb844d777b0c07e36cf0cb1906710c Mon Sep 17 00:00:00 2001 From: Alan Potter Date: Tue, 27 Feb 2024 06:50:24 -0500 Subject: [PATCH 5/7] fix: drop Flask 1 Flask v1 has been EOLed for a really long time. Flask 3 is out now, which means Flask v2 is also EOL. All the tests still pass, though, so we can continue supporting it for at least a little while. --- _appmap/py_version_check.py | 2 +- _appmap/test/test_command.py | 2 +- appmap/command/appmap_agent_validate.py | 10 +++------- ci/smoketest.sh | 2 +- requirements-dev.txt | 2 +- requirements-flask1.txt | 5 ----- tox.ini | 8 +++----- 7 files changed, 10 insertions(+), 21 deletions(-) delete mode 100644 requirements-flask1.txt diff --git a/_appmap/py_version_check.py b/_appmap/py_version_check.py index 6d8693b5..c89156b9 100644 --- a/_appmap/py_version_check.py +++ b/_appmap/py_version_check.py @@ -17,7 +17,7 @@ def _get_platform_version(): def check_py_version(): - req = (3, 6) + req = (3, 8) actual = _get_platform_version() if _get_py_version() < req: raise AppMapPyVerException( diff --git a/_appmap/test/test_command.py b/_appmap/test/test_command.py index a819c288..0319cec5 100644 --- a/_appmap/test/test_command.py +++ b/_appmap/test/test_command.py @@ -134,4 +134,4 @@ def test_flask_version(self, capsys, mocker): side_effect=lambda d: "1.0" if d == "flask" else version(d), ) - self.check_errors(capsys, 1, 1, "flask must have version >= 1.1, found 1.0") + self.check_errors(capsys, 1, 1, "flask must have version >= 2.0, found 1.0") diff --git a/appmap/command/appmap_agent_validate.py b/appmap/command/appmap_agent_validate.py index 74267bae..6a538045 100644 --- a/appmap/command/appmap_agent_validate.py +++ b/appmap/command/appmap_agent_validate.py @@ -35,9 +35,7 @@ def _check_version(dist, v): actual = parse(dist_version) if actual < required: - raise ValidationFailure( - f"{dist} must have version >= {required}, found {actual}" - ) + raise ValidationFailure(f"{dist} must have version >= {required}, found {actual}") except PackageNotFoundError: pass @@ -51,7 +49,7 @@ def check_django_version(): def check_flask_version(): - return _check_version("flask", "1.1") + return _check_version("flask", "2.0") def check_pytest_version(): @@ -65,9 +63,7 @@ def _run(): django_version = check_django_version() flask_version = check_flask_version() if not (django_version or flask_version): - raise ValidationFailure( - "No web framework found. Expected one of: Django, Flask" - ) + raise ValidationFailure("No web framework found. Expected one of: Django, Flask") check_pytest_version() errors = [] diff --git a/ci/smoketest.sh b/ci/smoketest.sh index 3ad0a89c..07ba0981 100755 --- a/ci/smoketest.sh +++ b/ci/smoketest.sh @@ -1,7 +1,7 @@ #!/usr/bin/env bash set -ex -pip -q install -U pip pytest "flask<2" python-decouple +pip -q install -U pip pytest "flask>=2,<3" python-decouple pip -q install /dist/appmap-*-py3-none-any.whl cp -R /_appmap/test/data/unittest/simple ./. diff --git a/requirements-dev.txt b/requirements-dev.txt index a8da3057..cebc1a3f 100644 --- a/requirements-dev.txt +++ b/requirements-dev.txt @@ -1,5 +1,5 @@ #requirements-dev.txt tox django -flask +flask >=2, < 3 pytest-django<4.8 \ No newline at end of file diff --git a/requirements-flask1.txt b/requirements-flask1.txt deleted file mode 100644 index 11c5ae2b..00000000 --- a/requirements-flask1.txt +++ /dev/null @@ -1,5 +0,0 @@ -flask == 1.1.2 -MarkupSafe == 2.0.1 -jinja2 >=2.10.1, <3 -itsdangerous >=0.24,<2 -Werkzeug >=0.15,<2 \ No newline at end of file diff --git a/tox.ini b/tox.ini index 5dfa9829..741441bc 100644 --- a/tox.ini +++ b/tox.ini @@ -2,18 +2,17 @@ isolated_build = true # The *-web environments test the latest versions of Django and Flask with the full test suite. For # older version of the web frameworks, just run the tests that are specific to them. -envlist = py3{8,9,10,11,12}-web, py3{8,9,10,11,12}-flask1-django3 +envlist = py3{8,9,10,11,12}-web, py3{8,9,10,11,12}-django3 [testenv] allowlist_externals = env - poetry deps= + poetry pytest-django <4.8 web: Django >=4.0, <5.0 - web: Flask >= 2 - flask1: -rrequirements-flask1.txt + web: Flask >= 2, <3 django3: Django >=3.2, <4.0 @@ -23,7 +22,6 @@ commands = env APPMAP_LOG_LEVEL=warning APPMAP=false poetry install -v py310-web: poetry run pylint -j 0 appmap _appmap web: poetry run {posargs:pytest} - flask1: poetry run pytest _appmap/test/test_flask.py django3: poetry run pytest _appmap/test/test_django.py [testenv:vendoring] From 648cdb55a5944d3afb64492823d153d2c579c0f5 Mon Sep 17 00:00:00 2001 From: Alan Potter Date: Tue, 27 Feb 2024 09:39:29 -0500 Subject: [PATCH 6/7] ci: use pylint-exit to check pylint return code pylint exits non-zero, even if there were no errors. pylint-exit interprets the error code, and exits with shell-friendly code. --- pyproject.toml | 1 + tox.ini | 3 ++- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/pyproject.toml b/pyproject.toml index 3485cf75..c9395b15 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -78,6 +78,7 @@ black = "^22.8.0" isort = "^5.10.1" pylint = "^2.16.2" pytest-shell-utilities = "^1.8.0" +pylint-exit = "^1.2.0" [build-system] requires = ["poetry-core>=1.1.0"] diff --git a/tox.ini b/tox.ini index 741441bc..9aa82443 100644 --- a/tox.ini +++ b/tox.ini @@ -7,6 +7,7 @@ envlist = py3{8,9,10,11,12}-web, py3{8,9,10,11,12}-django3 [testenv] allowlist_externals = env + bash deps= poetry @@ -20,7 +21,7 @@ commands = # Turn off recording while installing. It's not necessary, and the warning messages that come # out of the agent confuse poetry. env APPMAP_LOG_LEVEL=warning APPMAP=false poetry install -v - py310-web: poetry run pylint -j 0 appmap _appmap + py310-web: bash -c "poetry run pylint -j 0 appmap _appmap || pylint-exit $?" web: poetry run {posargs:pytest} django3: poetry run pytest _appmap/test/test_django.py From 67cc779ee517537334b4b24c626cb12388c55fc1 Mon Sep 17 00:00:00 2001 From: Alan Potter Date: Tue, 27 Feb 2024 10:27:35 -0500 Subject: [PATCH 7/7] ci: cache rust Installing the rust toolchain takes a long time (especially in the 3.10 job, for some reason). The Travis doc says `cargo: true` will cache $HOME/.cargo, which should help. --- .travis.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.travis.yml b/.travis.yml index cbcd319b..d54311ce 100644 --- a/.travis.yml +++ b/.travis.yml @@ -20,6 +20,7 @@ install: pip -q install --upgrade "tox < 4" tox-travis script: tox cache: + cargo: true pip: true directories: - $TRAVIS_BUILD_DIR/.tox/