Merge pull request #287 from getappmap/fastapi_20240227

Add FastAPI support

_appmap/configuration.py

@@ -2,14 +2,14 @@
 Manage Configuration AppMap recorder for Python.
 """
 
+import importlib.metadata
 import inspect
 import os
 import sys
 from os.path import realpath
 from pathlib import Path
 from textwrap import dedent
 
-import importlib_metadata
 import yaml
 from yaml.parser import ParserError
 
@@ -142,8 +142,6 @@ def __init__(self):
 
         self._load_config()
         self._load_functions()
-        logger.info("config: %s", self._config)
-        logger.debug("package_functions: %s", self.package_functions)
 
         if "labels" in self._config:
             self.labels.append(self._config["labels"])
@@ -314,7 +312,7 @@ class DistMatcher(PathMatcher):
     def __init__(self, dist, *args, **kwargs):
         super().__init__(*args, **kwargs)
         self.dist = dist
-        self.files = [str(pp.locate()) for pp in importlib_metadata.files(dist)]
+        self.files = [str(pp.locate()) for pp in importlib.metadata.files(dist)]
 
     def matches(self, filterable):
         try:
@@ -415,3 +413,8 @@ def initialize():
 
 
 initialize()
+
+c = Config()
+logger.info("config: %s", c._config)
+logger.debug("package_functions: %s", c.package_functions)
+logger.info("env: %r", os.environ)

_appmap/env.py

@@ -4,6 +4,7 @@
 import logging.config
 import os
 from contextlib import contextmanager
+from datetime import datetime
 from os import environ
 from pathlib import Path
 from typing import cast
@@ -124,11 +125,10 @@ def getLogger(self, name) -> trace_logger.TraceLogger:
     def _configure_logging(self):
         trace_logger.install()
 
-        log_level = self.get("APPMAP_LOG_LEVEL", "warning").upper()
-
+        log_level = self.get("APPMAP_LOG_LEVEL", "warn").upper()
+        disable_log = os.environ.get("APPMAP_DISABLE_LOG_FILE", "false").upper() != "FALSE"
         log_config = self.get("APPMAP_LOG_CONFIG")
-        log_stream = self.get("APPMAP_LOG_STREAM", "stderr")
-        log_stream = "ext://sys.%s" % (log_stream)
+        now = datetime.now()
         config_dict = {
             "version": 1,
             "disable_existing_loggers": False,
@@ -138,9 +138,7 @@ def _configure_logging(self):
                     "format": "[{asctime}] {levelname} {name}: {message}",
                 }
             },
-            "handlers": {
-                "default": {"class": "logging.StreamHandler", "formatter": "default"}
-            },
+            "handlers": {"default": {"class": "logging.StreamHandler", "formatter": "default"}},
             "loggers": {
                 "appmap": {
                     "level": log_level,
@@ -154,6 +152,20 @@ def _configure_logging(self):
                 },
             },
         }
+        if not disable_log:
+            # Default to being more verbose if we're logging to a file, but
+            # still allow the level to be overridden.
+            log_level = self.get("APPMAP_LOG_LEVEL", "info").upper()
+            loggers = config_dict["loggers"]
+            loggers["appmap"]["level"] = loggers["_appmap"]["level"] = log_level
+            config_dict["handlers"] = {
+                "default": {
+                    "class": "logging.FileHandler",
+                    "formatter": "default",
+                    "filename": f"appmap-{now:%Y%m%d%H%M%S}-{os.getpid()}.log",
+                }
+            }
+
         if log_config is not None:
             name, level = log_config.split("=", 2)
             config_dict["loggers"].update(

_appmap/event.py

@@ -10,11 +10,11 @@
 from .recorder import Recorder
 from .utils import (
     FnType,
+    FqFnName,
     appmap_tls,
     compact_dict,
     fqname,
     get_function_location,
-    split_function_name,
 )
 
 logger = Env.current.getLogger(__name__)
@@ -173,7 +173,7 @@ def to_dict(self, value):
 
 
 class CallEvent(Event):
-    __slots__ = ["_fn", "static", "receiver", "parameters", "labels"]
+    __slots__ = ["_fn", "_fqfn", "static", "receiver", "parameters", "labels"]
 
     @staticmethod
     def make(fn, fntype):
@@ -209,10 +209,9 @@ def make_params(filterable):
             # going to log a message about a mismatch.
             wrapped_sig = inspect.signature(fn, follow_wrapped=True)
             if sig != wrapped_sig:
-                logger.debug(
-                    "signature of wrapper %s.%s doesn't match wrapped",
-                    *split_function_name(fn)
-                )
+                logger.debug("signature of wrapper %r doesn't match wrapped", fn)
+                logger.debug("sig: %r", sig)
+                logger.debug("wrapped_sig: %r", wrapped_sig)
 
         return [Param(p) for p in sig.parameters.values()]
 
@@ -270,17 +269,17 @@ def set_params(params, instance, args, kwargs):
     @property
     @lru_cache(maxsize=None)
     def function_name(self):
-        return split_function_name(self._fn)
+        return self._fqfn.fqfn
 
     @property
     @lru_cache(maxsize=None)
     def defined_class(self):
-        return self.function_name[0]
+        return self._fqfn.fqclass
 
     @property
     @lru_cache(maxsize=None)
     def method_id(self):
-        return self.function_name[1]
+        return self._fqfn.fqfn[1]
 
     @property
     @lru_cache(maxsize=None)
@@ -308,6 +307,7 @@ def comment(self):
     def __init__(self, fn, fntype, parameters, labels):
         super().__init__("call")
         self._fn = fn
+        self._fqfn = FqFnName(fn)
         self.static = fntype in FnType.STATIC | FnType.CLASS | FnType.MODULE
         self.receiver = None
         if fntype in FnType.CLASS | FnType.INSTANCE:
@@ -351,7 +351,15 @@ class MessageEvent(Event):  # pylint: disable=too-few-public-methods
     def __init__(self, message_parameters):
         super().__init__("call")
         self.message = []
-        for name, value in message_parameters.items():
+        self.message_parameters = message_parameters
+
+    @property
+    def message_parameters(self):
+        return self.message
+
+    @message_parameters.setter
+    def message_parameters(self, params):
+        for name, value in params.items():
             message_object = describe_value(name, value)
             self.message.append(message_object)
 
@@ -386,6 +394,7 @@ def __init__(self, request_method, url, message_parameters, headers=None):
 
 
 # pylint: disable=too-few-public-methods
+_NORMALIZED_PATH_INFO_ATTR = "normalized_path_info"
 class HttpServerRequestEvent(MessageEvent):
     """A call AppMap event representing an HTTP server request."""
 
@@ -406,7 +415,7 @@ def __init__(
             "request_method": request_method,
             "protocol": protocol,
             "path_info": path_info,
-            "normalized_path_info": normalized_path_info,
+            _NORMALIZED_PATH_INFO_ATTR: normalized_path_info,
         }
 
         if headers is not None:
@@ -420,6 +429,14 @@ def __init__(
 
         self.http_server_request = compact_dict(request)
 
+    @property
+    def normalized_path_info(self):
+        return self.http_server_request.get(_NORMALIZED_PATH_INFO_ATTR, None)
+
+    @normalized_path_info.setter
+    def normalized_path_info(self, npi):
+        self.http_server_request[_NORMALIZED_PATH_INFO_ATTR] = npi
+
 
 class ReturnEvent(Event):
     __slots__ = ["parent_id", "elapsed"]

_appmap/fastapi.py

@@ -0,0 +1,32 @@
+"""
+This file contains a FastAPI app that is mounted on /_appmap to expose the remote-recording endpoint
+in a user's app.
+
+It should only be imported if other code has already verified that FastAPI is available.
+"""
+
+from fastapi import FastAPI, Response
+
+from . import remote_recording
+
+app = FastAPI()
+
+
+def _rr_response(fn):
+    body, rrstatus = fn()
+    return Response(content=body, status_code=rrstatus, media_type="application/json")
+
+
+@app.get("/record")
+def status():
+    return _rr_response(remote_recording.status)
+
+
+@app.post("/record")
+def start():
+    return _rr_response(remote_recording.start)
+
+
+@app.delete("/record")
+def stop():
+    return _rr_response(remote_recording.stop)

_appmap/importer.py

@@ -10,56 +10,49 @@
 from _appmap import wrapt
 
 from .env import Env
-from .utils import FnType
+from .utils import FnType, Scope
 
 logger = Env.current.getLogger(__name__)
 
 
-Filterable = namedtuple("Filterable", "fqname obj")
+Filterable = namedtuple("Filterable", "scope fqname obj")
 
 
 class FilterableMod(Filterable):
     __slots__ = ()
 
     def __new__(cls, mod):
         fqname = mod.__name__
-        return super(FilterableMod, cls).__new__(cls, fqname, mod)
-
-    def classify_fn(self, _):
-        return FnType.MODULE
+        return super(FilterableMod, cls).__new__(cls, Scope.MODULE, fqname, mod)
 
 
 class FilterableCls(Filterable):
     __slots__ = ()
 
     def __new__(cls, clazz):
         fqname = "%s.%s" % (clazz.__module__, clazz.__qualname__)
-        return super(FilterableCls, cls).__new__(cls, fqname, clazz)
-
-    def classify_fn(self, static_fn):
-        return FnType.classify(static_fn)
+        return super(FilterableCls, cls).__new__(cls, Scope.CLASS, fqname, clazz)
 
 
 class FilterableFn(
     namedtuple(
         "FilterableFn",
-        Filterable._fields
-        + (
-            "scope",
-            "static_fn",
-        ),
+        Filterable._fields + ("static_fn",),
     )
 ):
     __slots__ = ()
 
     def __new__(cls, scope, fn, static_fn):
         fqname = "%s.%s" % (scope.fqname, fn.__name__)
-        self = super(FilterableFn, cls).__new__(cls, fqname, fn, scope, static_fn)
+        self = super(FilterableFn, cls).__new__(cls, scope.scope, fqname, fn, static_fn)
         return self
 
     @property
     def fntype(self):
-        return self.scope.classify_fn(self.static_fn)
+        if self.scope == Scope.MODULE:
+            return FnType.MODULE
+
+        return FnType.classify(self.static_fn)
 
 
 class Filter(ABC):  # pylint: disable=too-few-public-methods
@@ -161,6 +154,17 @@ def initialize(cls):
     def use_filter(cls, filter_class):
         cls.filter_stack.append(filter_class)
 
+    @classmethod
+    def instrument_function(cls, fn_name, filterableFn: FilterableFn, selected_functions=None):
+        # Only instrument the function if it was specifically called out for the package
+        # (e.g. because it should be labeled), or it's included by the filters
+        matched = cls.filter_chain.filter(filterableFn)
+        selected = selected_functions and fn_name in selected_functions
+        if selected or matched:
+            return cls.filter_chain.wrap(filterableFn)
+
+        return filterableFn.obj
+
     @classmethod
     def do_import(cls, *args, **kwargs):
         mod = args[0]
@@ -177,15 +181,10 @@ def instrument_functions(filterable, selected_functions=None):
             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
-                # (e.g. because it should be labeled), or it's included by the filters
                 filterableFn = FilterableFn(filterable, fn, static_fn)
-                matched = cls.filter_chain.filter(filterableFn)
-                selected = selected_functions and fn_name in selected_functions
-                if selected or matched:
-                    new_fn = cls.filter_chain.wrap(filterableFn)
-                    if fn != new_fn:
-                        wrapt.wrap_function_wrapper(filterable.obj, fn_name, new_fn)
+                new_fn = cls.instrument_function(fn_name, filterableFn, selected_functions)
+                if new_fn != fn:
+                    wrapt.wrap_function_wrapper(filterable.obj, fn_name, new_fn)
 
         # Import Config here, to avoid circular top-level imports.
         from .configuration import Config  # pylint: disable=import-outside-toplevel

_appmap/metadata.py

@@ -1,7 +1,6 @@
 """Shared metadata gathering"""
 
 import platform
-import re
 from functools import lru_cache
 
 from . import utils

_appmap/remote_recording.py

@@ -1,4 +1,5 @@
-""" remote_recording is a Flask app that can be mounted to expose the remote-recording endpoint. """
+""" remote_recording contains the functions neccessary to implement a remote-recording endpoint. """
+
 import json
 from threading import Lock
 

_appmap/test/__init__.py

@@ -0,0 +1,5 @@
+import pytest
+
+# Make sure assertions in web_framework get rewritten (e.g. to show
+# diffs in generated appmaps)
+pytest.register_assert_rewrite("_appmap.test.web_framework")

_appmap/test/appmap_test_base.py

@@ -1,6 +1,7 @@
 import json
 import platform
 import re
+from importlib.metadata import version as dist_version
 from operator import itemgetter
 
 import pytest
@@ -60,7 +61,7 @@ def normalize_metadata(metadata):
             for f in frameworks:
                 if f["name"] == "pytest":
                     v = f.pop("version")
-                    assert v == pytest.__version__
+                    assert v == dist_version("pytest")
 
     def normalize_appmap(self, generated_appmap):
         """

_appmap/test/bin/server_runner

@@ -0,0 +1,12 @@
+#!/usr/bin/env bash
+
+set -x
+
+cd "$1"; shift
+
+set -a
+PYTHONUNBUFFERED=1
+APPMAP_OUTPUT_DIR=/tmp
+PYTHONPATH=./init
+
+exec $@