From 56f5caf097b0cacefae827960971292f0fb779f7 Mon Sep 17 00:00:00 2001 From: hallvictoria <59299039+hallvictoria@users.noreply.github.com> Date: Tue, 14 Nov 2023 15:32:30 -0600 Subject: [PATCH] python specific app setting logs added (#1353) * python specific app setting logs added * lint * refactor * codeowner * manual convert dict to string * moved to utils, more efficient * added to old tests, created new * addressing comments * fixing tests, efficiency * python worker ext * removed comma * FLAKE --------- Co-authored-by: Varad Meru --- CODEOWNERS | 2 +- azure_functions_worker/dispatcher.py | 18 +++- .../utils/app_setting_manager.py | 43 +++++++++ tests/unittests/test_app_setting_manager.py | 93 +++++++++++++++++++ tests/unittests/test_dispatcher.py | 22 +++++ 5 files changed, 172 insertions(+), 6 deletions(-) create mode 100644 azure_functions_worker/utils/app_setting_manager.py create mode 100644 tests/unittests/test_app_setting_manager.py diff --git a/CODEOWNERS b/CODEOWNERS index 05f32378..f9350110 100644 --- a/CODEOWNERS +++ b/CODEOWNERS @@ -10,4 +10,4 @@ # For all file changes, github would automatically # include the following people in the PRs. -* @vrdmr @gavin-aguiar @YunchuWang @pdthummar +* @vrdmr @gavin-aguiar @YunchuWang @pdthummar @hallvictoria diff --git a/azure_functions_worker/dispatcher.py b/azure_functions_worker/dispatcher.py index 073a04c0..625397f5 100644 --- a/azure_functions_worker/dispatcher.py +++ b/azure_functions_worker/dispatcher.py @@ -21,16 +21,19 @@ from . import bindings, constants, functions, loader, protos from .bindings.shared_memory_data_transfer import SharedMemoryManager -from .constants import (PYTHON_THREADPOOL_THREAD_COUNT, +from .constants import (PYTHON_ROLLBACK_CWD_PATH, + PYTHON_THREADPOOL_THREAD_COUNT, 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_LANGUAGE_RUNTIME, CUSTOMER_PACKAGES_PATH) from .extension import ExtensionManager from .logging import disable_console_logging, enable_console_logging from .logging import (logger, error_logger, is_system_log_category, CONSOLE_LOG_PREFIX, format_exception) +from .utils.app_setting_manager import get_python_appsetting_state from .utils.common import get_app_setting, is_envvar_true from .utils.dependency import DependencyManager from .utils.tracing import marshall_exception_trace @@ -265,11 +268,14 @@ async def _handle__worker_init_request(self, request): 'python version %s, ' 'worker version %s, ' 'request ID %s.' + 'App Settings state: %s.' ' To enable debug level logging, please refer to ' 'https://aka.ms/python-enable-debug-logging', sys.version, VERSION, - self.request_id) + self.request_id, + get_python_appsetting_state() + ) worker_init_request = request.worker_init_request host_capabilities = worker_init_request.capabilities @@ -546,9 +552,11 @@ async def _handle__function_environment_reload_request(self, request): try: logger.info('Received FunctionEnvironmentReloadRequest, ' 'request ID: %s,' + 'App Settings state: %s.' ' To enable debug level logging, please refer to ' 'https://aka.ms/python-enable-debug-logging', - self.request_id) + self.request_id, + get_python_appsetting_state()) func_env_reload_request = \ request.function_environment_reload_request @@ -689,7 +697,7 @@ def _get_context(invoc_request: protos.InvocationRequest, name: str, name, directory, invoc_request.invocation_id, _invocation_id_local, trace_context, retry_context) - @disable_feature_by(constants.PYTHON_ROLLBACK_CWD_PATH) + @disable_feature_by(PYTHON_ROLLBACK_CWD_PATH) def _change_cwd(self, new_cwd: str): if os.path.exists(new_cwd): os.chdir(new_cwd) diff --git a/azure_functions_worker/utils/app_setting_manager.py b/azure_functions_worker/utils/app_setting_manager.py new file mode 100644 index 00000000..00394f7d --- /dev/null +++ b/azure_functions_worker/utils/app_setting_manager.py @@ -0,0 +1,43 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. +import os +import sys + +from ..constants import (PYTHON_ROLLBACK_CWD_PATH, + PYTHON_THREADPOOL_THREAD_COUNT, + PYTHON_ISOLATE_WORKER_DEPENDENCIES, + PYTHON_ENABLE_WORKER_EXTENSIONS, + PYTHON_ENABLE_WORKER_EXTENSIONS_DEFAULT, + PYTHON_ENABLE_WORKER_EXTENSIONS_DEFAULT_39, + PYTHON_ENABLE_DEBUG_LOGGING, + FUNCTIONS_WORKER_SHARED_MEMORY_DATA_TRANSFER_ENABLED) + + +def get_python_appsetting_state(): + current_vars = os.environ.copy() + python_specific_settings = \ + [PYTHON_ROLLBACK_CWD_PATH, + PYTHON_THREADPOOL_THREAD_COUNT, + PYTHON_ISOLATE_WORKER_DEPENDENCIES, + PYTHON_ENABLE_DEBUG_LOGGING, + PYTHON_ENABLE_WORKER_EXTENSIONS, + FUNCTIONS_WORKER_SHARED_MEMORY_DATA_TRANSFER_ENABLED] + + app_setting_states = "".join( + f"{app_setting}: {current_vars[app_setting]} " + for app_setting in python_specific_settings + if app_setting in current_vars + ) + + # Special case for extensions + if 'PYTHON_ENABLE_WORKER_EXTENSIONS' not in current_vars: + if sys.version_info.minor == 9: + app_setting_states += \ + (f"{PYTHON_ENABLE_WORKER_EXTENSIONS}: " + f"{str(PYTHON_ENABLE_WORKER_EXTENSIONS_DEFAULT_39)}") + else: + app_setting_states += \ + (f"{PYTHON_ENABLE_WORKER_EXTENSIONS}: " + f"{str(PYTHON_ENABLE_WORKER_EXTENSIONS_DEFAULT)} ") + + return app_setting_states diff --git a/tests/unittests/test_app_setting_manager.py b/tests/unittests/test_app_setting_manager.py new file mode 100644 index 00000000..7c665067 --- /dev/null +++ b/tests/unittests/test_app_setting_manager.py @@ -0,0 +1,93 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. +import collections as col +import os + +from unittest.mock import patch + +from tests.utils import testutils +from azure_functions_worker.utils.app_setting_manager import \ + get_python_appsetting_state +from azure_functions_worker.constants import PYTHON_THREADPOOL_THREAD_COUNT, \ + PYTHON_ENABLE_DEBUG_LOGGING + +SysVersionInfo = col.namedtuple("VersionInfo", ["major", "minor", "micro", + "releaselevel", "serial"]) +DISPATCHER_FUNCTIONS_DIR = testutils.UNIT_TESTS_FOLDER / 'dispatcher_functions' +DISPATCHER_STEIN_FUNCTIONS_DIR = testutils.UNIT_TESTS_FOLDER / \ + 'dispatcher_functions' / \ + 'dispatcher_functions_stein' +DISPATCHER_STEIN_INVALID_FUNCTIONS_DIR = testutils.UNIT_TESTS_FOLDER / \ + 'broken_functions' / \ + 'invalid_stein' + + +class TestDefaultAppSettingsLogs(testutils.AsyncTestCase): + """Tests for default app settings logs.""" + + @classmethod + def setUpClass(cls): + cls._ctrl = testutils.start_mockhost( + script_root=DISPATCHER_FUNCTIONS_DIR) + 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() + + async def test_initialize_worker_logging(self): + """Test if the dispatcher's log can be flushed out during worker + initialization + """ + async with self._ctrl as host: + r = await host.init_worker('3.0.12345') + self.assertTrue('App Settings state: ' in log for log in r.logs) + self.assertTrue('PYTHON_ENABLE_WORKER_EXTENSIONS: ' + in log for log in r.logs) + + def test_get_python_appsetting_state(self): + app_setting_state = get_python_appsetting_state() + expected_string = "PYTHON_ENABLE_WORKER_EXTENSIONS: " + self.assertIn(expected_string, app_setting_state) + + +class TestNonDefaultAppSettingsLogs(testutils.AsyncTestCase): + """Tests for non-default app settings logs.""" + + @classmethod + def setUpClass(cls): + cls._ctrl = testutils.start_mockhost( + script_root=DISPATCHER_FUNCTIONS_DIR) + os_environ = os.environ.copy() + os_environ[PYTHON_THREADPOOL_THREAD_COUNT] = '20' + os_environ[PYTHON_ENABLE_DEBUG_LOGGING] = '1' + 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() + + async def test_initialize_worker_logging(self): + """Test if the dispatcher's log can be flushed out during worker + initialization + """ + async with self._ctrl as host: + r = await host.init_worker('3.0.12345') + self.assertTrue('App Settings state: ' in log for log in r.logs) + self.assertTrue('PYTHON_THREADPOOL_THREAD_COUNT: ' + in log for log in r.logs) + self.assertTrue('PYTHON_ENABLE_DEBUG_LOGGING: ' + in log for log in r.logs) + + def test_get_python_appsetting_state(self): + app_setting_state = get_python_appsetting_state() + self.assertIn("PYTHON_THREADPOOL_THREAD_COUNT: 20 ", app_setting_state) + self.assertIn("PYTHON_ENABLE_DEBUG_LOGGING: 1 ", app_setting_state) + self.assertIn("PYTHON_ENABLE_WORKER_EXTENSIONS: ", app_setting_state) diff --git a/tests/unittests/test_dispatcher.py b/tests/unittests/test_dispatcher.py index eac056e1..43df8819 100644 --- a/tests/unittests/test_dispatcher.py +++ b/tests/unittests/test_dispatcher.py @@ -98,6 +98,15 @@ async def test_dispatcher_initialize_worker_logging(self): 1 ) + async def test_dispatcher_initialize_worker_settings_logs(self): + """Test if the dispatcher's log can be flushed out during worker + initialization + """ + async with self._ctrl as host: + r = await host.init_worker('3.0.12345') + self.assertTrue('PYTHON_ENABLE_WORKER_EXTENSIONS: ' + in log for log in r.logs) + async def test_dispatcher_environment_reload_logging(self): """Test if the sync threadpool will pick up app setting in placeholder mode (Linux Consumption) @@ -115,6 +124,19 @@ async def test_dispatcher_environment_reload_logging(self): 1 ) + async def test_dispatcher_environment_reload_settings_logs(self): + """Test if the sync threadpool will pick up app setting in placeholder + mode (Linux Consumption) + """ + async with self._ctrl as host: + await host.init_worker() + await self._check_if_function_is_ok(host) + + # Reload environment variable on specialization + r = await host.reload_environment(environment={}) + self.assertTrue('PYTHON_ENABLE_WORKER_EXTENSIONS: ' + in log for log in r.logs) + async def test_dispatcher_send_worker_request(self): """Test if the worker status response will be sent correctly when a worker status request is received