SettingsApi ModuleNotFoundError fix when extensions enabled (#1305)

gavin-aguiar · Gavin Aguiar · web-flow · commit b68941361230 · 2023-08-25T15:58:21.000-05:00
* ModuleNotFound error fix when extensions is enabled

* Fixed flake8 errors

* Fixed flake8 validation

* Fixed unit tests

* Addressed comments

* Fixed log formatiting

* Fixed flake8 validation

* Removed debug logging check from unittest

* Added py311 tests for TPTC

* Skipped TestThreadPoolSettingsPython38 for py37

* Fixed flake8 validation

* Updated threadpool tests

* Test unit tests failures

* Fixing unit tests failures

* Added exception message to test case

* Fixed logging error

* Addressed comments

* Address comments

* Fixed unit tests

---------

Co-authored-by: Gavin Aguiar &lt;gavin@GavinPC&gt;
diff --git a/azure_functions_worker/constants.py b/azure_functions_worker/constants.py
@@ -1,6 +1,7 @@
 # Copyright (c) Microsoft Corporation. All rights reserved.
 # Licensed under the MIT License.
-
+import os
+import pathlib
 import sys
 
 # Capabilities
@@ -40,14 +41,19 @@
 PYTHON_ISOLATE_WORKER_DEPENDENCIES_DEFAULT_310 = False
 PYTHON_ENABLE_WORKER_EXTENSIONS_DEFAULT = False
 PYTHON_ENABLE_WORKER_EXTENSIONS_DEFAULT_39 = True
+PYTHON_EXTENSIONS_RELOAD_FUNCTIONS = "PYTHON_EXTENSIONS_RELOAD_FUNCTIONS"
 
 # External Site URLs
 MODULE_NOT_FOUND_TS_URL = "https://aka.ms/functions-modulenotfound"
 
 # new programming model script file name
 SCRIPT_FILE_NAME = "function_app.py"
-
 PYTHON_LANGUAGE_RUNTIME = "python"
 
 # Settings for V2 programming model
 RETRY_POLICY = "retry_policy"
+
+# Paths
+CUSTOMER_PACKAGES_PATH = os.path.join(pathlib.Path.home(),
+                                      pathlib.Path(
+                                          "site/wwwroot/.python_packages"))
diff --git a/azure_functions_worker/dispatcher.py b/azure_functions_worker/dispatcher.py
@@ -26,10 +26,9 @@
                         PYTHON_THREADPOOL_THREAD_COUNT_MAX_37,
                         PYTHON_THREADPOOL_THREAD_COUNT_MIN,
                         PYTHON_ENABLE_DEBUG_LOGGING, SCRIPT_FILE_NAME,
-                        PYTHON_LANGUAGE_RUNTIME)
+                        PYTHON_LANGUAGE_RUNTIME, CUSTOMER_PACKAGES_PATH)
 from .extension import ExtensionManager
 from .logging import disable_console_logging, enable_console_logging
-from .logging import enable_debug_logging_recommendation
 from .logging import (logger, error_logger, is_system_log_category,
                       CONSOLE_LOG_PREFIX, format_exception)
 from .utils.common import get_app_setting, is_envvar_true
@@ -263,9 +262,14 @@ async def _dispatch_grpc_request(self, request):
 
     async def _handle__worker_init_request(self, request):
         logger.info('Received WorkerInitRequest, '
-                    'python version %s, worker version %s, request ID %s',
-                    sys.version, VERSION, self.request_id)
-        enable_debug_logging_recommendation()
+                    'python version %s, '
+                    'worker version %s, '
+                    'request ID %s.'
+                    ' To enable debug level logging, please refer to '
+                    'https://aka.ms/python-enable-debug-logging',
+                    sys.version,
+                    VERSION,
+                    self.request_id)
 
         worker_init_request = request.worker_init_request
         host_capabilities = worker_init_request.capabilities
@@ -293,6 +297,10 @@ async def _handle__worker_init_request(self, request):
                 "Importing azure functions in WorkerInitRequest")
             import azure.functions  # NoQA
 
+        if CUSTOMER_PACKAGES_PATH not in sys.path:
+            logger.warning("Customer packages not in sys path. "
+                           "This should never happen! ")
+
         # loading bindings registry and saving results to a static
         # dictionary which will be later used in the invocation request
         bindings.load_binding_registry()
@@ -363,6 +371,7 @@ async def _handle__function_load_request(self, request):
             'Received WorkerLoadRequest, request ID %s, function_id: %s,'
             'function_name: %s,', self.request_id, function_id, function_name)
 
+        programming_model = "V1"
         try:
             if not self._functions.get_function(function_id):
                 if function_metadata.properties.get("worker_indexed", False) \
@@ -371,8 +380,7 @@ async def _handle__function_load_request(self, request):
                     # indexing is enabled and load request is called without
                     # calling the metadata request. In this case we index the
                     # function and update the workers registry
-                    logger.info(f"Indexing function {function_name} in the "
-                                f"load request")
+                    programming_model = "V2"
                     _ = self.index_functions(function_path)
                 else:
                     # legacy function
@@ -385,17 +393,24 @@ async def _handle__function_load_request(self, request):
                     self._functions.add_function(
                         function_id, func, func_request.metadata)
 
-                    ExtensionManager.function_load_extension(
+            try:
+                ExtensionManager.function_load_extension(
+                    function_name,
+                    func_request.metadata.directory
+                )
+            except Exception as ex:
+                logging.error("Failed to load extensions: ", ex)
+                raise
+
+            logger.info('Successfully processed FunctionLoadRequest, '
+                        'request ID: %s, '
+                        'function ID: %s,'
+                        'function Name: %s,'
+                        'programming model: %s',
+                        self.request_id,
+                        function_id,
                         function_name,
-                        func_request.metadata.directory
-                    )
-
-                    logger.info('Successfully processed FunctionLoadRequest, '
-                                'request ID: %s, '
-                                'function ID: %s,'
-                                'function Name: %s', self.request_id,
-                                function_id,
-                                function_name)
+                        programming_model)
 
             return protos.StreamingMessage(
                 request_id=self.request_id,
@@ -532,8 +547,10 @@ async def _handle__function_environment_reload_request(self, request):
         """
         try:
             logger.info('Received FunctionEnvironmentReloadRequest, '
-                        'request ID: %s', self.request_id)
-            enable_debug_logging_recommendation()
+                        'request ID: %s,'
+                        ' To enable debug level logging, please refer to '
+                        'https://aka.ms/python-enable-debug-logging',
+                        self.request_id)
 
             func_env_reload_request = \
                 request.function_environment_reload_request
diff --git a/azure_functions_worker/extension.py b/azure_functions_worker/extension.py
@@ -236,9 +236,8 @@ def _try_get_sdk_with_extension_enabled(cls) -> Optional[ModuleType]:
     @classmethod
     def _info_extension_is_enabled(cls, sdk):
         logger.info(
-            'Python Worker Extension is enabled in azure.functions (%s).',
-            get_sdk_version(sdk)
-        )
+            'Python Worker Extension is enabled in azure.functions (%s). '
+            'Sdk path: %s', get_sdk_version(sdk), sdk.__file__)
 
     @classmethod
     def _info_discover_extension_list(cls, function_name, sdk):
diff --git a/azure_functions_worker/loader.py b/azure_functions_worker/loader.py
@@ -18,18 +18,12 @@
 from . import protos, functions
 from .bindings.retrycontext import RetryPolicy
 from .constants import MODULE_NOT_FOUND_TS_URL, SCRIPT_FILE_NAME, \
-    PYTHON_LANGUAGE_RUNTIME, RETRY_POLICY
+    PYTHON_LANGUAGE_RUNTIME, RETRY_POLICY, CUSTOMER_PACKAGES_PATH
 from .utils.wrappers import attach_message_to_exception
 
 _AZURE_NAMESPACE = '__app__'
 _DEFAULT_SCRIPT_FILENAME = '__init__.py'
 _DEFAULT_ENTRY_POINT = 'main'
-
-PKGS_PATH = pathlib.Path("site/wwwroot/.python_packages")
-home = pathlib.Path.home()
-pkgs_path = os.path.join(home, PKGS_PATH)
-
-
 _submodule_dirs = []
 
 
@@ -140,7 +134,8 @@ def process_indexed_function(functions_registry: functions.Registry,
             f' guide: {MODULE_NOT_FOUND_TS_URL} ',
     debug_logs='Error in load_function. '
                f'Sys Path: {sys.path}, Sys Module: {sys.modules},'
-               f'python-packages Path exists: {os.path.exists(pkgs_path)}')
+               'python-packages Path exists: '
+               f'{os.path.exists(CUSTOMER_PACKAGES_PATH)}')
 def load_function(name: str, directory: str, script_file: str,
                   entry_point: Optional[str]):
     dir_path = pathlib.Path(directory)
@@ -191,7 +186,8 @@ def load_function(name: str, directory: str, script_file: str,
     message=f'Troubleshooting Guide: {MODULE_NOT_FOUND_TS_URL}',
     debug_logs='Error in index_function_app. '
                f'Sys Path: {sys.path}, Sys Module: {sys.modules},'
-               f'python-packages Path exists: {os.path.exists(pkgs_path)}')
+               'python-packages Path exists: '
+               f'{os.path.exists(CUSTOMER_PACKAGES_PATH)}')
 def index_function_app(function_path: str):
     module_name = pathlib.Path(function_path).stem
     imported_module = importlib.import_module(module_name)
diff --git a/azure_functions_worker/logging.py b/azure_functions_worker/logging.py
@@ -91,11 +91,6 @@ def enable_console_logging() -> None:
         logger.addHandler(handler)
 
 
-def enable_debug_logging_recommendation():
-    logging.info("To enable debug level logging, please refer to "
-                 "https://aka.ms/python-enable-debug-logging")
-
-
 def is_system_log_category(ctg: str) -> bool:
     """Check if the logging namespace belongs to system logs. Category starts
     with the following name will be treated as system logs.
diff --git a/azure_functions_worker/utils/common.py b/azure_functions_worker/utils/common.py
@@ -1,10 +1,13 @@
 # Copyright (c) Microsoft Corporation. All rights reserved.
 # Licensed under the MIT License.
-from typing import Optional, Callable
-from types import ModuleType
+import importlib
 import os
 import sys
-import importlib
+from types import ModuleType
+from typing import Optional, Callable
+
+from azure_functions_worker.constants import CUSTOMER_PACKAGES_PATH, \
+    PYTHON_EXTENSIONS_RELOAD_FUNCTIONS
 
 
 def is_true_like(setting: str) -> bool:
@@ -110,19 +113,26 @@ def get_sdk_from_sys_path() -> ModuleType:
     ModuleType
         The azure.functions that is loaded from the first sys.path entry
     """
-    backup_azure_functions = None
-    backup_azure = None
 
-    if 'azure.functions' in sys.modules:
-        backup_azure_functions = sys.modules.pop('azure.functions')
-    if 'azure' in sys.modules:
-        backup_azure = sys.modules.pop('azure')
+    if is_envvar_true(PYTHON_EXTENSIONS_RELOAD_FUNCTIONS):
+        backup_azure_functions = None
+        backup_azure = None
+
+        if 'azure.functions' in sys.modules:
+            backup_azure_functions = sys.modules.pop('azure.functions')
+        if 'azure' in sys.modules:
+            backup_azure = sys.modules.pop('azure')
+
+        module = importlib.import_module('azure.functions')
+
+        if backup_azure:
+            sys.modules['azure'] = backup_azure
+        if backup_azure_functions:
+            sys.modules['azure.functions'] = backup_azure_functions
 
-    module = importlib.import_module('azure.functions')
+        return module
 
-    if backup_azure:
-        sys.modules['azure'] = backup_azure
-    if backup_azure_functions:
-        sys.modules['azure.functions'] = backup_azure_functions
+    if CUSTOMER_PACKAGES_PATH not in sys.path:
+        sys.path.insert(0, CUSTOMER_PACKAGES_PATH)
 
-    return module
+    return importlib.import_module('azure.functions')
diff --git a/azure_functions_worker/utils/dependency.py b/azure_functions_worker/utils/dependency.py
@@ -1,22 +1,22 @@
 # Copyright (c) Microsoft Corporation. All rights reserved.
 # Licensed under the MIT License.
-from azure_functions_worker.utils.common import is_true_like
-from typing import List, Optional
-from types import ModuleType
 import importlib
 import inspect
 import os
 import re
 import sys
+from types import ModuleType
+from typing import List, Optional
 
-from ..logging import logger
+from azure_functions_worker.utils.common import is_true_like
 from ..constants import (
     AZURE_WEBJOBS_SCRIPT_ROOT,
     CONTAINER_NAME,
     PYTHON_ISOLATE_WORKER_DEPENDENCIES,
     PYTHON_ISOLATE_WORKER_DEPENDENCIES_DEFAULT,
     PYTHON_ISOLATE_WORKER_DEPENDENCIES_DEFAULT_310
 )
+from ..logging import logger
 from ..utils.common import is_python_version
 from ..utils.wrappers import enable_feature_by
 
@@ -226,7 +226,7 @@ def reload_azure_google_namespace_from_worker_deps(cls):
             logger.info('Reloaded azure.functions module now at %s',
                         inspect.getfile(sys.modules['azure.functions']))
         except Exception as ex:
-            logger.info(
+            logger.warning(
                 'Unable to reload azure.functions. Using default. '
                 'Exception:\n%s', ex)
 
diff --git a/tests/consumption_tests/test_linux_consumption.py b/tests/consumption_tests/test_linux_consumption.py
@@ -217,14 +217,37 @@ def test_pinning_functions_to_older_version(self):
                 "AzureWebJobsStorage": self._storage,
                 "SCM_RUN_FROM_PACKAGE": self._get_blob_url(
                     "PinningFunctions"),
-                "PYTHON_ISOLATE_WORKER_DEPENDENCIES": "1"
+                "PYTHON_ISOLATE_WORKER_DEPENDENCIES": "1",
             })
             req = Request('GET', f'{ctrl.url}/api/HttpTrigger1')
             resp = ctrl.send_request(req)
 
             self.assertEqual(resp.status_code, 200)
             self.assertIn("Func Version: 1.11.1", resp.text)
 
+    @skipIf(sys.version_info.minor != 10,
+            "This is testing only for python310")
+    def test_opencensus_with_extensions_enabled(self):
+        """A function app with extensions enabled containing the
+         following libraries:
+
+        azure-functions, azure-eventhub, azure-storage-blob, numpy,
+        cryptography, pyodbc, requests
+
+        should return 200 after importing all libraries.
+        """
+        with LinuxConsumptionWebHostController(_DEFAULT_HOST_VERSION,
+                                               self._py_version) as ctrl:
+            ctrl.assign_container(env={
+                "AzureWebJobsStorage": self._storage,
+                "SCM_RUN_FROM_PACKAGE": self._get_blob_url("Opencensus"),
+                "PYTHON_ENABLE_WORKER_EXTENSIONS": "1",
+                "AzureWebJobsFeatureFlags": "EnableWorkerIndexing"
+            })
+            req = Request('GET', f'{ctrl.url}/api/opencensus')
+            resp = ctrl.send_request(req)
+            self.assertEqual(resp.status_code, 200)
+
     def _get_blob_url(self, scenario_name: str) -> str:
         return (
             f'https://pythonworker{self._py_shortform}sa.blob.core.windows.net/'
diff --git a/tests/unittests/test_dispatcher.py b/tests/unittests/test_dispatcher.py
diff --git a/tests/unittests/test_extension.py b/tests/unittests/test_extension.py
diff --git a/tests/unittests/test_rpc_messages.py b/tests/unittests/test_rpc_messages.py
diff --git a/tests/unittests/test_utilities.py b/tests/unittests/test_utilities.py
