Merge branch 'dev' into hallvictoria/fix-syspath-log

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():
@@ -543,6 +540,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, '

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

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

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/'

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)