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 <vrdmr@users.noreply.github.com>

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

azure_functions_worker/dispatcher.py

@@ -21,16 +21,19 @@ import grpc
 
 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 @@ class Dispatcher(metaclass=DispatcherMeta):
                     '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 @@ class Dispatcher(metaclass=DispatcherMeta):
         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 @@ class Dispatcher(metaclass=DispatcherMeta):
             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)

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

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)

tests/unittests/test_dispatcher.py

@@ -98,6 +98,15 @@ class TestThreadPoolSettingsPython37(testutils.AsyncTestCase):
                 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 @@ class TestThreadPoolSettingsPython37(testutils.AsyncTestCase):
                 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