diff --git a/azure_functions_worker/constants.py b/azure_functions_worker/constants.py index 86a9dd59b..95f384473 100644 --- a/azure_functions_worker/constants.py +++ b/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" """ diff --git a/azure_functions_worker/dispatcher.py b/azure_functions_worker/dispatcher.py index 24c25ece1..7681dab2a 100644 --- a/azure_functions_worker/dispatcher.py +++ b/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, diff --git a/azure_functions_worker/logging.py b/azure_functions_worker/logging.py index 0e6bc79c6..df1a17834 100644 --- a/azure_functions_worker/logging.py +++ b/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): diff --git a/tests/unittests/log_filtering_functions/dependency_logging_filter/blueprint/blueprint.py b/tests/unittests/log_filtering_functions/dependency_logging_filter/blueprint/blueprint.py new file mode 100644 index 000000000..1969465fd --- /dev/null +++ b/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') diff --git a/tests/unittests/log_filtering_functions/dependency_logging_filter/blueprint/external_lib.py b/tests/unittests/log_filtering_functions/dependency_logging_filter/blueprint/external_lib.py new file mode 100644 index 000000000..dc9b37582 --- /dev/null +++ b/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') diff --git a/tests/unittests/log_filtering_functions/dependency_logging_filter/external_lib.py b/tests/unittests/log_filtering_functions/dependency_logging_filter/external_lib.py new file mode 100644 index 000000000..dc9b37582 --- /dev/null +++ b/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') diff --git a/tests/unittests/log_filtering_functions/dependency_logging_filter/function_app.py b/tests/unittests/log_filtering_functions/dependency_logging_filter/function_app.py new file mode 100644 index 000000000..c0771f3b1 --- /dev/null +++ b/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') diff --git a/tests/unittests/test_enable_dependency_logging_filtering.py b/tests/unittests/test_enable_dependency_logging_filtering.py new file mode 100644 index 000000000..3a64d8cdc --- /dev/null +++ b/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)