Merge pull request #285 from getappmap/flask-exc_20240227

Make sure an Exception in a Flask route gets captured, test Flask 3

Author: apotterri

.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*)?$/
@@ -21,6 +20,7 @@ install: pip -q install --upgrade "tox < 4" tox-travis
 script: tox
 
 cache:
+  cargo: true
   pip: true
   directories:
   - $TRAVIS_BUILD_DIR/.tox/

_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
 

_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")

_appmap/env.py

@@ -1,11 +1,14 @@
 """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
 
 _cwd = Path.cwd()
 _bootenv = environ.copy()
@@ -115,10 +118,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")

_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)
 

_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)

_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(

_appmap/test/data/flask/app.py

@@ -45,3 +45,8 @@ def show_user_post(username, post_id):
 @app.route("/<int:org>/posts/<username>")
 def show_org_user_posts(org, username):
     return f"org {org} username {username}"
+
+
+@app.route("/exception")
+def raise_exception():
+    raise Exception("An exception")

_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")

_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"})