Merge pull request #183 from getappmap/sw/dont_show_warning_when_appmap_is_enabled

feat: downgrade logging level when AppMap recording is enabled

Author: symwell

appmap/__init__.py

@@ -1,8 +1,8 @@
 """AppMap recorder for Python"""
 from ._implementation import generation  # noqa: F401
 from ._implementation.env import Env  # noqa: F401
-from ._implementation.labels import labels  # noqa: F401
 from ._implementation.importer import instrument_module  # noqa: F401
+from ._implementation.labels import labels  # noqa: F401
 from ._implementation.recording import Recording  # noqa: F401
 
 try:

appmap/_implementation/__init__.py

@@ -1,14 +1,12 @@
 from . import configuration
 from . import env as appmapenv
 from . import event, importer, metadata, recorder
-from .detect_enabled import DetectEnabled
 from .py_version_check import check_py_version
 
 
 def initialize(**kwargs):
     check_py_version()
     appmapenv.initialize(**kwargs)
-    DetectEnabled.initialize()
     event.initialize()
     importer.initialize()
     recorder.initialize()

appmap/_implementation/configuration.py

@@ -383,6 +383,7 @@ def __init__(self, *args, **kwargs):
 
 
 def initialize():
+    DetectEnabled.initialize()
     Config().initialize()
     Importer.use_filter(BuiltinFilter)
     Importer.use_filter(ConfigFilter)

appmap/_implementation/detect_enabled.py

@@ -19,6 +19,8 @@
 # environment variables.
 class DetectEnabled:
     _instance = None
+    _initialized = False
+    _logged_at_least_once = False
 
     def __new__(cls):
         if cls._instance is None:
@@ -58,60 +60,88 @@ def should_enable(cls, recording_method):
         if recording_method in cls._detected_for_method:
             return cls._detected_for_method[recording_method]
         else:
-            message, enabled = cls._detect_should_enable(recording_method)
+            enabled, log_level, message = cls._detect_should_enable(recording_method)
             cls._detected_for_method[recording_method] = enabled
-            if enabled:
-                logger.warning(dedent(f"AppMap recording is enabled because {message}"))
+            # don't log enabled messages more than once
+            if (not cls._logged_at_least_once and logger.isEnabledFor(log_level)):
+                cls._logged_at_least_once = True
+                logger.log(log_level, message)
             return enabled
 
     @classmethod
     def any_enabled(cls):
         for m in RECORDING_METHODS:
-            _, enabled = cls._detect_should_enable(m)
-            if enabled:
+            if cls.should_enable(m):
                 return True
         return False
 
+    @classmethod
+    def _log_prefix(cls, should_enable, log_message):
+        enabled_prefix = ""
+        if not should_enable:
+            enabled_prefix = "not "
+
+        return dedent(
+            f"AppMap recording is {enabled_prefix}enabled because {log_message}."
+        )
+
     @classmethod
     def _detect_should_enable(cls, recording_method):
         if not recording_method:
-            return ["no recording method is set", False]
+            return False, logging.WARNING, cls._log_prefix(False, "no recording method is set")
 
         if recording_method not in RECORDING_METHODS:
-            return ["invalid recording method", False]
+            return False, logging.WARNING, cls._log_prefix(
+                    False, f"{recording_method} is an invalid recording method"
+            )
 
         # explicitly disabled or enabled
         if "APPMAP" in os.environ:
-            if os.environ["APPMAP"] == "false":
-                return ["APPMAP=false", False]
-            elif os.environ["APPMAP"] == "true":
-                return ["APPMAP=true", True]
+            if os.environ["APPMAP"].lower() == "false":
+                return False, logging.INFO, cls._log_prefix(False, f"APPMAP=false")
+            elif os.environ["APPMAP"].lower() == "true":
+                return True, logging.INFO, cls._log_prefix(True, f"APPMAP=true")
+            else:
+                return False, logging.WARNING, cls._log_prefix(False, f"APPMAP={os.environ['APPMAP']} is an invalid option")
 
         # recording method explicitly disabled or enabled
         if recording_method:
             for one_recording_method in RECORDING_METHODS:
                 if one_recording_method == recording_method.lower():
                     env_var = "_".join(["APPMAP", "RECORD", recording_method.upper()])
                     if env_var in os.environ:
-                        if os.environ[env_var] == "false":
-                            return [f"{env_var}=false", False]
-                        elif os.environ[env_var] == "true":
-                            return [f"{env_var}=true", True]
+                        if os.environ[env_var].lower() == "false":
+                            return False, logging.INFO, cls._log_prefix(False, f"{env_var}=false")
+                        elif os.environ[env_var].lower() == "true":
+                            return True, logging.INFO, cls._log_prefix(True, f"{env_var}=true")
+                        else:
+                            return False, logging.WARNING, cls._log_prefix(False, f"{env_var}={os.environ[env_var]} is an invalid option")
+
+        # check if name of APPMAP_RECORD_ env variable was defined incorrectly
+        for env_var in os.environ:
+            env_var_as_list = env_var.split("_")
+            if (
+                len(env_var_as_list) > 2
+                and env_var_as_list[0] == "APPMAP"
+                and env_var_as_list[1] == "RECORD"
+            ):
+                if not (env_var_as_list[2].lower() in RECORDING_METHODS):
+                    return False, logging.WARNING, cls._log_prefix(False, f"{env_var} is an invalid recording method")
 
         # it's flask
         message, should_enable = cls.is_flask_and_should_enable()
-        if should_enable == True or should_enable == False:
-            return [message, should_enable]
+        if should_enable in [True, False]:
+            return should_enable, logging.INFO, cls._log_prefix(should_enable, f"{message}")
 
         # it's django
         message, should_enable = cls.is_django_and_should_enable()
-        if should_enable == True or should_enable == False:
-            return [message, should_enable]
+        if should_enable in [True, False]:
+            return should_enable, logging.INFO, cls._log_prefix(should_enable, f"{message}")
 
         if recording_method in RECORDING_METHODS:
-            return ["will record by default", True]
+            return True, logging.INFO, cls._log_prefix(True, f"will record by default")
 
-        return ["it's not enabled by any configuration or framework", False]
+        return False, logging.INFO, cls._log_prefix(False, f"it's not enabled by any configuration or framework")
 
     @classmethod
     def is_flask_and_should_enable(cls):

appmap/_implementation/env.py

@@ -36,6 +36,8 @@ def __init__(self, env=None, cwd=None):
         self._env = _bootenv.copy()
         if env:
             self._env.update(env)
+
+        self._configure_logging()
         self._enabled = DetectEnabled.any_enabled()
 
         self._root_dir = str(self._cwd) + "/"
@@ -44,8 +46,6 @@ def __init__(self, env=None, cwd=None):
         output_dir = Path(self.get("APPMAP_OUTPUT_DIR", "tmp/appmap"))
         self._output_dir = output_dir.resolve()
 
-        self._configure_logging()
-
     def set(self, name, value):
         self._env[name] = value
 
@@ -120,5 +120,6 @@ def _configure_logging(self):
 
 
 def initialize(**kwargs):
+    DetectEnabled.initialize()
     Env.reset(**kwargs)
     logging.info("appmap enabled: %s", Env.current.enabled)

appmap/_implementation/testing_framework.py

@@ -140,6 +140,7 @@ def collect_result_metadata(metadata):
         metadata["exception"] = {"class": exn.__class__.__name__, "message": str(exn)}
         raise
 
+
 def file_delete(filename):
     try:
         os.remove(filename)

appmap/_implementation/web_framework.py

@@ -135,7 +135,9 @@ def __init__(self):
         self.record_url = "/_appmap/record"
 
     def should_record(self):
-        return DetectEnabled.should_enable("remote") or DetectEnabled.should_enable("requests")
+        return DetectEnabled.should_enable("remote") or DetectEnabled.should_enable(
+            "requests"
+        )
 
     def before_request_hook(self, request, request_path, recording_is_running):
         if request_path == self.record_url:

appmap/test/test_detect_enabled.py

@@ -20,11 +20,23 @@ def setup_method():
     def test_none__appmap_disabled(self):
         assert DetectEnabled.should_enable(None) == False
 
+    @patch.dict(os.environ, {"APPMAP": "False"})
+    def test_none__appmap_disabled_mixed_case(self):
+        assert DetectEnabled.should_enable(None) == False
+
     @patch.dict(os.environ, {"APPMAP": "true"})
     def test_none__appmap_enabled(self):
         # if there's no recording method then it's disabled
         assert DetectEnabled.should_enable(None) == False
 
+    @patch.dict(os.environ, {"APPMAP": "True"})
+    def test_none__appmap_enabled_mixed_case(self):
+        assert DetectEnabled.should_enable(None) == False
+
+    @patch.dict(os.environ, {"APPMAP": "invalid_value"})
+    def test_none__appmap_invalid_value(self):
+        assert DetectEnabled.should_enable(None) == False
+
     def test_invalid__no_envvar(self):
         assert DetectEnabled.should_enable("invalid_recording_method") == False
 
@@ -52,6 +64,22 @@ def test_some__recording_method_enabled(self):
         for recording_method in RECORDING_METHODS:
             assert DetectEnabled.should_enable(recording_method) == True
 
+    recording_methods_as_true_mixed_case = {
+        key: "True" for key in recording_methods_as_true.keys()
+    }
+
+    @patch.dict(os.environ, recording_methods_as_true_mixed_case)
+    def test_some__recording_method_enabled_mixed_case(self):
+        for recording_method in RECORDING_METHODS:
+            assert DetectEnabled.should_enable(recording_method) == True
+
+    recording_methods_as_true_invalid = {"APPMAP_RECORD_INVALID": "true"}
+
+    @patch.dict(os.environ, recording_methods_as_true_invalid)
+    def test_some__recording_method_enabled_invalid(self):
+        for recording_method in RECORDING_METHODS:
+            assert DetectEnabled.should_enable(recording_method) == False
+
     recording_methods_as_false = {
         "_".join(["APPMAP", "RECORD", recording_method.upper()]): "false"
         for recording_method in RECORDING_METHODS
@@ -62,6 +90,15 @@ def test_some__recording_method_disabled(self):
         for recording_method in RECORDING_METHODS:
             assert DetectEnabled.should_enable(recording_method) == False
 
+    recording_methods_as_false_mixed_case = {
+        key: "False" for key in recording_methods_as_false.keys()
+    }
+
+    @patch.dict(os.environ, recording_methods_as_false_mixed_case)
+    def test_some__recording_method_disabled_mixed_case(self):
+        for recording_method in RECORDING_METHODS:
+            assert DetectEnabled.should_enable(recording_method) == False
+
 
 class TestDetectEnabledFlask:
     @staticmethod

appmap/test/test_django.py

@@ -64,7 +64,9 @@ def test_framework_metadata(
 
 
 @pytest.mark.appmap_enabled
-def test_app_can_read_body(client, events, monkeypatch):  # pylint: disable=unused-argument
+def test_app_can_read_body(
+    client, events, monkeypatch
+):  # pylint: disable=unused-argument
     monkeypatch.setenv("APPMAP_RECORD_REQUESTS", "false")
     response = client.post("/echo", json={"test": "json"})
     assert response.content == b'{"test": "json"}'

appmap/test/test_test_frameworks.py

@@ -41,7 +41,8 @@ def test_appmap_unittest_runner_disabled(testdir, monkeypatch):
     )
     assert result.ret == 0
     r = re.compile(r"AppMap disabled")
-    assert [l for l in filter(r.search, result.errlines)], "Warning not found"
+    # when APPMAP=false it no longer prints a warning
+    assert [l for l in filter(r.search, result.errlines)] == []
 
 
 def test_pytest_runner_unittests(testdir):