Enable dependency logging filtering v2

azure_functions_worker/constants.py

@@ -22,6 +22,8 @@
 PYTHON_ISOLATE_WORKER_DEPENDENCIES = "PYTHON_ISOLATE_WORKER_DEPENDENCIES"
 PYTHON_ENABLE_WORKER_EXTENSIONS = "PYTHON_ENABLE_WORKER_EXTENSIONS"
 PYTHON_ENABLE_DEBUG_LOGGING = "PYTHON_ENABLE_DEBUG_LOGGING"
+PYTHON_ENABLE_DEPENDENCY_LOG_FILTERING_MODULES = \
+    "PYTHON_ENABLE_DEPENDENCY_LOG_FILTERING_MODULES"
 FUNCTIONS_WORKER_SHARED_MEMORY_DATA_TRANSFER_ENABLED = \
     "FUNCTIONS_WORKER_SHARED_MEMORY_DATA_TRANSFER_ENABLED"
 """

azure_functions_worker/dispatcher.py

@@ -24,9 +24,11 @@
                         PYTHON_THREADPOOL_THREAD_COUNT_DEFAULT,
                         PYTHON_THREADPOOL_THREAD_COUNT_MAX_37,
                         PYTHON_THREADPOOL_THREAD_COUNT_MIN,
-                        PYTHON_ENABLE_DEBUG_LOGGING, SCRIPT_FILE_NAME)
+                        PYTHON_ENABLE_DEBUG_LOGGING, SCRIPT_FILE_NAME,
+                        PYTHON_ENABLE_DEPENDENCY_LOG_FILTERING_MODULES)
 from .extension import ExtensionManager
-from .logging import disable_console_logging, enable_console_logging
+from .logging import disable_console_logging, enable_console_logging, \
+    enable_dependency_log_filtering
 from .logging import enable_debug_logging_recommendation
 from .logging import (logger, error_logger, is_system_log_category,
                       CONSOLE_LOG_PREFIX, format_exception)
@@ -98,7 +100,8 @@ def get_sync_tp_workers_set(self):
          3.9 scenarios (as we'll start passing only None by default), and we
          need to get that information.
 
-         Ref: concurrent.futures.thread.ThreadPoolExecutor.__init__._max_workers
+         Ref: concurrent.futures.thread.ThreadPoolExecutor.__init__
+         ._max_workers
         """
         return self._sync_call_tp._max_workers
 
@@ -176,7 +179,8 @@ def stop(self) -> None:
 
         self._stop_sync_call_tp()
 
-    def on_logging(self, record: logging.LogRecord, formatted_msg: str) -> None:
+    def on_logging(self, record: logging.LogRecord,
+                   formatted_msg: str) -> None:
         if record.levelno >= logging.CRITICAL:
             log_level = protos.RpcLog.Critical
         elif record.levelno >= logging.ERROR:
@@ -312,6 +316,13 @@ async def _handle__functions_metadata_request(self, request):
                         status=protos.StatusResult.Success)))
 
         try:
+            # Filter function app dependency logs by root logger if
+            # logging filtering setting is specified
+            if os.getenv(PYTHON_ENABLE_DEPENDENCY_LOG_FILTERING_MODULES) is \
+                    not None:
+                enable_dependency_log_filtering(
+                    os.environ[PYTHON_ENABLE_DEPENDENCY_LOG_FILTERING_MODULES])
+
             fx_metadata_results = self.index_functions(function_path)
 
             return protos.StreamingMessage(
@@ -367,7 +378,6 @@ async def _handle__function_load_request(self, request):
                         function_name,
                         func_request.metadata.directory
                     )
-
                     logger.info('Successfully processed FunctionLoadRequest, '
                                 'request ID: %s, '
                                 'function ID: %s,'
@@ -436,7 +446,8 @@ async def _handle__invocation_request(self, request):
                     pytype=pb_type_info.pytype,
                     shmem_mgr=self._shmem_mgr)
 
-            fi_context = self._get_context(invoc_request, fi.name, fi.directory)
+            fi_context = self._get_context(invoc_request, fi.name,
+                                           fi.directory)
             if fi.requires_context:
                 args['context'] = fi_context
 
@@ -631,7 +642,8 @@ async def _handle__close_shared_memory_resources_request(self, request):
     @staticmethod
     def _get_context(invoc_request: protos.InvocationRequest, name: str,
                      directory: str) -> bindings.Context:
-        """ For more information refer: https://aka.ms/azfunc-invocation-context
+        """ For more information refer:
+        https://aka.ms/azfunc-invocation-context
         """
         trace_context = bindings.TraceContext(
             invoc_request.trace_context.trace_parent,

azure_functions_worker/logging.py

@@ -12,7 +12,6 @@
 SYSTEM_LOG_PREFIX = "azure_functions_worker"
 SDK_LOG_PREFIX = "azure.functions"
 
-
 logger: logging.Logger = logging.getLogger('azure_functions_worker')
 error_logger: logging.Logger = (
     logging.getLogger('azure_functions_worker_errors'))
@@ -21,6 +20,14 @@
 error_handler: Optional[logging.Handler] = None
 
 
+def enable_dependency_log_filtering(module_names, *args) -> None:
+    class DependencyLoggingFilter(logging.Filter):
+        def filter(self, record):
+            return record.module in module_names
+
+    logging.getLogger().addFilter(DependencyLoggingFilter())
+
+
 def format_exception(exception: Exception) -> str:
     msg = str(exception) + "\n"
     if (sys.version_info.major, sys.version_info.minor) < (3, 10):

tests/unittests/log_filtering_functions/dependency_logging_filter/blueprint/blueprint.py

@@ -0,0 +1,12 @@
+import logging
+import azure.functions as func
+import external_lib
+
+bp = func.Blueprint()
+
+
+@bp.route(route="test_blueprint_logging")
+def test_blueprint_logging(req: func.HttpRequest) -> func.HttpResponse:
+    logging.info('logging from blueprint')
+    external_lib.ExternalLib()
+    return func.HttpResponse('ok')

tests/unittests/log_filtering_functions/dependency_logging_filter/blueprint/external_lib.py

@@ -0,0 +1,6 @@
+import logging
+
+
+class ExternalLib:
+    def __init__(self):
+        logging.info('logging from external library')

tests/unittests/log_filtering_functions/dependency_logging_filter/external_lib.py

@@ -0,0 +1,6 @@
+import logging
+
+
+class ExternalLib:
+    def __init__(self):
+        logging.info('logging from external library')

tests/unittests/log_filtering_functions/dependency_logging_filter/function_app.py

@@ -0,0 +1,19 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License.
+
+import logging
+
+import azure.functions as func
+import external_lib
+from blueprint.blueprint import bp
+
+app = func.FunctionApp()
+app.register_functions(bp)
+
+
+@app.route(route="default_template")
+def default_template(req: func.HttpRequest) -> func.HttpResponse:
+    logging.info('Python HTTP trigger function processed a request.')
+    external_lib.ExternalLib()
+
+    return func.HttpResponse('ok')

tests/unittests/test_enable_dependency_logging_filtering.py

@@ -0,0 +1,188 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License.
+import typing
+import os
+from unittest.mock import patch
+from tests.utils import testutils
+from azure_functions_worker.constants import \
+    PYTHON_ENABLE_DEPENDENCY_LOG_FILTERING_MODULES
+
+HOST_JSON_TEMPLATE_WITH_LOGLEVEL_INFO = """\
+{
+    "version": "2.0",
+    "logging": {
+        "logLevel": {
+           "default": "Information"
+        }
+    }
+}
+"""
+
+
+class TestDependencyLoggingEnabledFunctions(testutils.WebHostTestCase):
+    """
+    Tests for cx dependency logging filtering enabled case.
+    """
+
+    @classmethod
+    def setUpClass(cls):
+        os_environ = os.environ.copy()
+        # Turn on feature flag
+        os_environ[
+            PYTHON_ENABLE_DEPENDENCY_LOG_FILTERING_MODULES] = 'function_app'
+        cls._patch_environ = patch.dict('os.environ', os_environ)
+        cls._patch_environ.start()
+        super().setUpClass()
+
+    @classmethod
+    def tearDownClass(cls):
+        super().tearDownClass()
+        cls._patch_environ.stop()
+
+    @classmethod
+    def get_script_dir(cls):
+        return testutils.UNIT_TESTS_FOLDER / 'log_filtering_functions' / \
+            'dependency_logging_filter'
+
+    def test_dependency_logging_filter_enabled(self):
+        """
+        Verify when cx dependency logging filter is enabled, cx function
+        dependencies logs are not captured.
+        """
+        r = self.webhost.request('GET', 'default_template')
+        self.assertEqual(r.status_code, 200)
+        self.assertEqual(r.text, 'ok')
+
+    def check_log_dependency_logging_filter_enabled(self,
+                                                    host_out: typing.List[
+                                                        str]):
+        self.assertIn('Python HTTP trigger function processed a request.',
+                      host_out)
+        self.assertNotIn('logging from external library', host_out)
+
+
+class TestDependencyLoggingDisabledFunctions(testutils.WebHostTestCase):
+    """
+    Tests for cx dependency logging filtering disabled case.
+    """
+
+    @classmethod
+    def setUpClass(cls):
+        os_environ = os.environ.copy()
+        # Turn off feature flag
+        cls._patch_environ = patch.dict('os.environ', os_environ)
+        cls._patch_environ.start()
+        super().setUpClass()
+
+    @classmethod
+    def tearDownClass(cls):
+        super().tearDownClass()
+        cls._patch_environ.stop()
+
+    @classmethod
+    def get_script_dir(cls):
+        return testutils.UNIT_TESTS_FOLDER / 'log_filtering_functions' / \
+            'dependency_logging_filter'
+
+    def test_dependency_logging_filter_disabled(self):
+        """
+        Verify when cx dependency logging filter is disabled, dependencies logs
+        are captured.
+        """
+        r = self.webhost.request('GET', 'default_template')
+        self.assertEqual(r.status_code, 200)
+        self.assertEqual(r.text, 'ok')
+
+    def check_log_dependency_logging_filter_disabled(self,
+                                                     host_out: typing.List[
+                                                         str]):
+        self.assertIn('Python HTTP trigger function processed a request.',
+                      host_out)
+        self.assertIn('logging from external library', host_out)
+
+
+class TestDependencyLoggingEnabledBluePrintFunctions(testutils.WebHostTestCase):
+    """
+    Tests for cx dependency logging filtering with blueprint func enabled case.
+    """
+
+    @classmethod
+    def setUpClass(cls):
+        os_environ = os.environ.copy()
+        # Turn off feature flag
+        os_environ[
+            PYTHON_ENABLE_DEPENDENCY_LOG_FILTERING_MODULES] = 'function_app,' \
+                                                              'blueprint'
+        cls._patch_environ = patch.dict('os.environ', os_environ)
+        cls._patch_environ.start()
+        super().setUpClass()
+
+    @classmethod
+    def tearDownClass(cls):
+        super().tearDownClass()
+        cls._patch_environ.stop()
+
+    @classmethod
+    def get_script_dir(cls):
+        return testutils.UNIT_TESTS_FOLDER / 'log_filtering_functions' / \
+            'dependency_logging_filter'
+
+    def test_dependency_logging_filter_blueprint_enabled(self):
+        """
+        Verify when cx dependency logging filter with blueprint func is
+        enabled, dependencies logs
+        are filtered out.
+        """
+        r = self.webhost.request('GET', 'test_blueprint_logging')
+        self.assertEqual(r.status_code, 200)
+        self.assertEqual(r.text, 'ok')
+
+    def check_log_dependency_logging_filter_blueprint_enabled(self,
+                                                              host_out:
+                                                              typing.List[
+                                                                  str]):
+        self.assertIn('logging from blueprint',
+                      host_out)
+        self.assertNotIn('logging from external library', host_out)
+
+
+class TestDependencyLoggingDisabledBluePrintFunctions(
+        testutils.WebHostTestCase):
+    """
+    Tests for cx dependency logging filtering with blueprint func disabled
+    case.
+    """
+
+    @classmethod
+    def setUpClass(cls):
+        os_environ = os.environ.copy()
+        cls._patch_environ = patch.dict('os.environ', os_environ)
+        cls._patch_environ.start()
+        super().setUpClass()
+
+    @classmethod
+    def tearDownClass(cls):
+        super().tearDownClass()
+        cls._patch_environ.stop()
+
+    @classmethod
+    def get_script_dir(cls):
+        return testutils.UNIT_TESTS_FOLDER / 'log_filtering_functions' / \
+            'dependency_logging_filter'
+
+    def test_dependency_logging_filter_disabled_blueprint(self):
+        """
+        Verify when cx dependency logging filter with blueprint functions is
+        disabled, dependencies logs are captured.
+        """
+        r = self.webhost.request('GET', 'test_blueprint_logging')
+        self.assertEqual(r.status_code, 200)
+        self.assertEqual(r.text, 'ok')
+
+    def check_log_dependency_logging_filter_disabled_blueprint(self,
+                                                               host_out:
+                                                               typing.List[
+                                                                   str]):
+        self.assertIn('logging from blueprint',
+                      host_out)
+        self.assertIn('logging from external library', host_out)