diff --git a/azure_functions_worker/dispatcher.py b/azure_functions_worker/dispatcher.py index 66f89e219..87e5729b8 100644 --- a/azure_functions_worker/dispatcher.py +++ b/azure_functions_worker/dispatcher.py @@ -286,10 +286,7 @@ async def _handle__worker_init_request(self, request): constants.SHARED_MEMORY_DATA_TRANSFER: _TRUE, } - # Can detech worker packages only when customer's code is present - # This only works in dedicated and premium sku. - # The consumption sku will switch on environment_reload request. - if not DependencyManager.is_in_linux_consumption(): + if DependencyManager.should_load_cx_dependencies(): DependencyManager.prioritize_customer_dependencies() if DependencyManager.is_in_linux_consumption(): @@ -544,6 +541,8 @@ async def _handle__invocation_request(self, request): async def _handle__function_environment_reload_request(self, request): """Only runs on Linux Consumption placeholder specialization. + This is called only when placeholder mode is true. On worker restarts + worker init request will be called directly. """ try: logger.info('Received FunctionEnvironmentReloadRequest, ' diff --git a/azure_functions_worker/logging.py b/azure_functions_worker/logging.py index 91a64c3b4..adb5ff294 100644 --- a/azure_functions_worker/logging.py +++ b/azure_functions_worker/logging.py @@ -11,11 +11,12 @@ CONSOLE_LOG_PREFIX = "LanguageWorkerConsoleLog" SYSTEM_LOG_PREFIX = "azure_functions_worker" SDK_LOG_PREFIX = "azure.functions" +SYSTEM_ERROR_LOG_PREFIX = "azure_functions_worker_errors" -logger: logging.Logger = logging.getLogger('azure_functions_worker') +logger: logging.Logger = logging.getLogger(SYSTEM_LOG_PREFIX) error_logger: logging.Logger = ( - logging.getLogger('azure_functions_worker_errors')) + logging.getLogger(SYSTEM_ERROR_LOG_PREFIX)) handler: Optional[logging.Handler] = None error_handler: Optional[logging.Handler] = None diff --git a/azure_functions_worker/utils/dependency.py b/azure_functions_worker/utils/dependency.py index a213b5e8e..c3455aa06 100644 --- a/azure_functions_worker/utils/dependency.py +++ b/azure_functions_worker/utils/dependency.py @@ -8,7 +8,7 @@ from types import ModuleType from typing import List, Optional -from azure_functions_worker.utils.common import is_true_like +from azure_functions_worker.utils.common import is_true_like, is_envvar_true from ..constants import ( AZURE_WEBJOBS_SCRIPT_ROOT, CONTAINER_NAME, @@ -74,14 +74,23 @@ def initialize(cls): def is_in_linux_consumption(cls): return CONTAINER_NAME in os.environ + @classmethod + def should_load_cx_dependencies(cls): + """ + Customer dependencies should be loaded when dependency + isolation is enabled and + 1) App is a dedicated app + 2) App is linux consumption but not in placeholder mode. + This can happen when the worker restarts for any reason + (OOM, timeouts etc) and env reload request is not called. + """ + return not (DependencyManager.is_in_linux_consumption() + and is_envvar_true("WEBSITE_PLACEHOLDER_MODE")) + @classmethod @enable_feature_by( flag=PYTHON_ISOLATE_WORKER_DEPENDENCIES, - flag_default=( - PYTHON_ISOLATE_WORKER_DEPENDENCIES_DEFAULT_310 if - is_python_version('3.10') else - PYTHON_ISOLATE_WORKER_DEPENDENCIES_DEFAULT - ) + flag_default=PYTHON_ISOLATE_WORKER_DEPENDENCIES_DEFAULT ) def use_worker_dependencies(cls): """Switch the sys.path and ensure the worker imports are loaded from @@ -109,11 +118,7 @@ def use_worker_dependencies(cls): @classmethod @enable_feature_by( flag=PYTHON_ISOLATE_WORKER_DEPENDENCIES, - flag_default=( - PYTHON_ISOLATE_WORKER_DEPENDENCIES_DEFAULT_310 if - is_python_version('3.10') else - PYTHON_ISOLATE_WORKER_DEPENDENCIES_DEFAULT - ) + flag_default=PYTHON_ISOLATE_WORKER_DEPENDENCIES_DEFAULT ) def prioritize_customer_dependencies(cls, cx_working_dir=None): """Switch the sys.path and ensure the customer's code import are loaded @@ -147,9 +152,12 @@ def prioritize_customer_dependencies(cls, cx_working_dir=None): cx_deps_path = cls.cx_deps_path logger.info( - 'Applying prioritize_customer_dependencies: worker_dependencies: ' - '%s, customer_dependencies: %s, working_directory: %s', - cls.worker_deps_path, cx_deps_path, working_directory) + 'Applying prioritize_customer_dependencies: ' + 'worker_dependencies_path: %s, customer_dependencies_path: %s, ' + 'working_directory: %s, Linux Consumption: %s, Placeholder: %s', + cls.worker_deps_path, cx_deps_path, working_directory, + DependencyManager.is_in_linux_consumption(), + is_envvar_true("WEBSITE_PLACEHOLDER_MODE")) cls._remove_from_sys_path(cls.worker_deps_path) cls._add_to_sys_path(cls.cx_deps_path, True) @@ -176,6 +184,9 @@ def reload_customer_libraries(cls, cx_working_dir: str): Depends on the PYTHON_ISOLATE_WORKER_DEPENDENCIES, the actual behavior differs. + This is called only when placeholder mode is true. In the case of a + worker restart, this will not be called. + Parameters ---------- cx_working_dir: str diff --git a/tests/consumption_tests/test_linux_consumption.py b/tests/consumption_tests/test_linux_consumption.py index 99280119c..4cba07184 100644 --- a/tests/consumption_tests/test_linux_consumption.py +++ b/tests/consumption_tests/test_linux_consumption.py @@ -2,6 +2,7 @@ # Licensed under the MIT License. import os import sys +from time import sleep from unittest import TestCase, skipIf from requests import Request @@ -248,6 +249,76 @@ def test_opencensus_with_extensions_enabled(self): resp = ctrl.send_request(req) self.assertEqual(resp.status_code, 200) + @skipIf(sys.version_info.minor != 9, + "This is testing only for python39 where extensions" + "enabled by default") + def test_reload_variables_after_timeout_error(self): + """ + A function app with HTTPtrigger which has a function timeout of + 20s. The app as a sleep of 30s which should trigger a timeout + """ + 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( + "TimeoutError"), + "PYTHON_ISOLATE_WORKER_DEPENDENCIES": "1", + "AzureWebJobsFeatureFlags": "EnableWorkerIndexing" + }) + req = Request('GET', f'{ctrl.url}/api/hello') + resp = ctrl.send_request(req) + self.assertEqual(resp.status_code, 500) + + sleep(2) + logs = ctrl.get_container_logs() + self.assertRegex( + logs, + r"Applying prioritize_customer_dependencies: " + r"worker_dependencies_path: \/azure-functions-host\/" + r"workers\/python\/.*?\/LINUX\/X64," + r" customer_dependencies_path: \/home\/site\/wwwroot\/" + r"\.python_packages\/lib\/site-packages, working_directory:" + r" \/home\/site\/wwwroot, Linux Consumption: True," + r" Placeholder: False") + self.assertNotIn("Failure Exception: ModuleNotFoundError", + logs) + + @skipIf(sys.version_info.minor != 9, + "This is testing only for python39 where extensions" + "enabled by default") + def test_reload_variables_after_oom_error(self): + """ + A function app with HTTPtrigger mocking error code 137 + """ + 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( + "OOMError"), + "PYTHON_ISOLATE_WORKER_DEPENDENCIES": "1", + "AzureWebJobsFeatureFlags": "EnableWorkerIndexing" + }) + req = Request('GET', f'{ctrl.url}/api/httptrigger') + resp = ctrl.send_request(req) + self.assertEqual(resp.status_code, 500) + + sleep(2) + logs = ctrl.get_container_logs() + self.assertRegex( + logs, + r"Applying prioritize_customer_dependencies: " + r"worker_dependencies_path: \/azure-functions-host\/" + r"workers\/python\/.*?\/LINUX\/X64," + r" customer_dependencies_path: \/home\/site\/wwwroot\/" + r"\.python_packages\/lib\/site-packages, working_directory:" + r" \/home\/site\/wwwroot, Linux Consumption: True," + r" Placeholder: False") + + self.assertNotIn("Failure Exception: ModuleNotFoundError", + logs) + 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 index c7b127dad..d983de8fb 100644 --- a/tests/unittests/test_dispatcher.py +++ b/tests/unittests/test_dispatcher.py @@ -589,7 +589,7 @@ async def test_dispatcher_functions_metadata_request_legacy_fallback(self): protos.StatusResult.Success) -class TestDispatcherLoadFunctionInInitRequest(testutils.AsyncTestCase): +class TestDispatcherInitRequest(testutils.AsyncTestCase): def setUp(self): self._ctrl = testutils.start_mockhost( @@ -606,8 +606,7 @@ def tearDown(self): self.mock_version_info.stop() async def test_dispatcher_load_azfunc_in_init(self): - """Test if the dispatcher's log can be flushed out during worker - initialization + """Test if azure functions is loaded during init """ async with self._ctrl as host: r = await host.init_worker('4.15.1') @@ -618,3 +617,53 @@ async def test_dispatcher_load_azfunc_in_init(self): 1 ) self.assertIn("azure.functions", sys.modules) + + async def test_dispatcher_load_modules_dedicated_app(self): + """Test modules are loaded in dedicated apps + """ + os.environ["PYTHON_ISOLATE_WORKER_DEPENDENCIES"] = "1" + + # Dedicated Apps where placeholder mode is not set + async with self._ctrl as host: + r = await host.init_worker('4.15.1') + logs = [log.message for log in r.logs] + self.assertIn( + "Applying prioritize_customer_dependencies: " + "worker_dependencies_path: , customer_dependencies_path: , " + "working_directory: , Linux Consumption: False," + " Placeholder: False", logs + ) + + async def test_dispatcher_load_modules_con_placeholder_enabled(self): + """Test modules are loaded in consumption apps with placeholder mode + enabled. + """ + # Consumption apps with placeholder mode enabled + os.environ["PYTHON_ISOLATE_WORKER_DEPENDENCIES"] = "1" + os.environ["CONTAINER_NAME"] = "test" + os.environ["WEBSITE_PLACEHOLDER_MODE"] = "1" + async with self._ctrl as host: + r = await host.init_worker('4.15.1') + logs = [log.message for log in r.logs] + self.assertNotIn( + "Applying prioritize_customer_dependencies: " + "worker_dependencies_path: , customer_dependencies_path: , " + "working_directory: , Linux Consumption: True,", logs) + + async def test_dispatcher_load_modules_con_app_placeholder_disabled(self): + """Test modules are loaded in consumption apps with placeholder mode + disabled. + """ + # Consumption apps with placeholder mode disabled i.e. worker + # is specialized + os.environ["PYTHON_ISOLATE_WORKER_DEPENDENCIES"] = "1" + os.environ["WEBSITE_PLACEHOLDER_MODE"] = "0" + os.environ["CONTAINER_NAME"] = "test" + async with self._ctrl as host: + r = await host.init_worker('4.15.1') + logs = [log.message for log in r.logs] + self.assertIn( + "Applying prioritize_customer_dependencies: " + "worker_dependencies_path: , customer_dependencies_path: , " + "working_directory: , Linux Consumption: True," + " Placeholder: False", logs)