Repository: Azure/azure-functions-python-worker (language: python)

Issue:
[BUG] Module Not Found in Consumption when worker crashes (OOM/TO/sys.exit)
<!--
Before creating a new issue, please check if the issue already exists in the [open issues panel](https://github.com/Azure/azure-functions-python-worker/issues?q=is%3Aissue+is%3Aopen) and please check the [Troubleshooting Guides](https://github.com/Azure/azure-functions-python-worker/wiki#troubleshooting-guides) in our wiki.
Please describe your issue or feature request below.
-->

### Issue Background
We've recently identified a critical issue related to the worker environment reload and Azure Function initialization process. This issue has been going on for some time, and we wanted to bring it to your attention to make sure it's clear and resolved.

During the specialization call in consumption mode, the worker receives an environment reload request, which triggers various setup processes related to worker functionality and dependency isolation. However, if, for any reason, the host decides to restart the worker (e.g., due to a legitimate need like Timeouts or worker crashes due to OOM), the worker goes through the full language worker life cycle but does not receive an environment reload request. As a result, the application is not set up correctly because certain checks in the initialization request are skipped, assuming that the worker will receive a reload request in a consumption scenario. This primarily affects apps using dependency isolation ([`PYTHON_ISOLATE_WORKER_DEPENDENCIES`](https://learn.microsoft.com/en-us/azure/azure-functions/functions-app-settings#python_isolate_worker_dependencies) to 1).

The result of the above behavior is a `ModuleNotFound` error hit in the function app, which could affect the app's availability. This issue doesn't affect Elastic Premium or Dedicated Function apps.
 
### Expected behavior
The Python worker should correctly handle the restart case irrespective of the SKU being used.

### Known workarounds
###### Provide a description of any known workarounds.
- Restart the function app. This should reload all the modules needed.
- Try to reduce the reasons workers could need a restart.
- Move the app to Dedicated or EP for the time being.

Note that these are only temporary workarounds. This issue has been fixed and in the process of being deployed. Fix should be available in runtime version 4.28

### Related information
###### Provide any related information



Discussion / hints:

Fix patch:
diff --git a/azure_functions_worker/dispatcher.py b/azure_functions_worker/dispatcher.py
index 66f89e21..87e5729b 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 91a64c3b..adb5ff29 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 a213b5e8..c3455aa0 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


Test patch:
diff --git a/tests/consumption_tests/test_linux_consumption.py b/tests/consumption_tests/test_linux_consumption.py
index 99280119..4cba0718 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 c7b127da..d983de8f 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)