update logs + lint

Author: hallvictoria

.flake8

@@ -6,10 +6,12 @@
 ignore = W503,E402,E731
 
 exclude = .git, __pycache__, build, dist, .eggs, .github, .local, docs/,
-          Samples, azure_functions_worker/protos/, proxy_worker/protos/,
-          azure_functions_worker/_thirdparty/typing_inspect.py,
-          tests/unittests/test_typing_inspect.py,
-          tests/unittests/broken_functions/syntax_error/main.py,
-          .env*, .vscode, venv*, *.venv*
+          Samples, workers/azure_functions_worker/protos/, workers/proxy_worker/protos/,
+          workers/azure_functions_worker/_thirdparty/typing_inspect.py,
+          workers/tests/unittests/test_typing_inspect.py,
+          workers/tests/unittests/broken_functions/syntax_error/main.py,
+          .env*, .vscode, venv*, *.venv*,
+          azure_functions_worker_v2/tests/protos/*,
+          azure_functions_worker_v2/azure_functions_worker_v2/utils/typing_inspect.py
 
 max-line-length = 88

azure_functions_worker_v2/azure_functions_worker_v2/bindings/meta.py

@@ -67,7 +67,7 @@ def load_binding_registry() -> None:
 
     if func is None:
         import azure.functions as func
-    
+
     set_sdk_version(func.__version__)  # type: ignore
 
     global BINDING_REGISTRY

azure_functions_worker_v2/azure_functions_worker_v2/handle_event.py

@@ -48,7 +48,7 @@
                               WORKER_STATUS)
 from .utils.executor import get_current_loop, execute_async, run_sync_func
 from .utils.helpers import change_cwd, get_sdk_version, get_worker_metadata
-from .utils.tracing import serialize_exception, serialize_exception_as_str
+from .utils.tracing import serialize_exception
 from .utils.validators import validate_script_file_name
 
 _metadata_result: Optional[List] = None
@@ -60,8 +60,8 @@
 
 
 async def worker_init_request(request):
-    logger.info("V2 Library Worker: received WorkerInitRequest,"
-                "Version %s", VERSION)
+    logger.debug("V2 Library Worker: received WorkerInitRequest,"
+                 "Version %s", VERSION)
     global _host, protos, _function_data_cache_enabled, _metadata_exception
     init_request = request.request.worker_init_request
     host_capabilities = init_request.capabilities
@@ -93,7 +93,7 @@ async def worker_init_request(request):
     # dictionary which will be later used in the invocation request
     load_binding_registry()
 
-    # Index in init by default
+    # Index in init by default. Fail if an exception occurs.
     try:
         load_function_metadata(
             init_request.function_app_directory,
@@ -105,15 +105,23 @@ async def worker_init_request(request):
                     initialize_http_server(_host)
                 capabilities[REQUIRES_ROUTE_PARAMETERS] = TRUE
         except HttpServerInitError as ex:
-            logger.error("HTTP server init error has occurred")
-            _metadata_exception = ex
+            return protos.WorkerInitResponse(
+                capabilities=capabilities,
+                worker_metadata=get_worker_metadata(protos),
+                result=protos.StatusResult(
+                    status=protos.StatusResult.Failure,
+                    exception=serialize_exception(
+                        ex, protos))
+            )
     except Exception as ex:
-        # This is catching an exception that happens during indexing while the init
-        # request is still in progress. The proxy worker will do nothing with this,
-        # but metadata will fail
-        _metadata_exception = ex
-        logger.error("An exception in WorkerInitRequest has occurred: %s",
-                     serialize_exception_as_str(ex))
+        return protos.WorkerInitResponse(
+            capabilities=capabilities,
+            worker_metadata=get_worker_metadata(protos),
+            result=protos.StatusResult(
+                status=protos.StatusResult.Failure,
+                exception=serialize_exception(
+                    ex, protos))
+        )
 
     logger.debug("Successfully completed WorkerInitRequest")
     return protos.WorkerInitResponse(
@@ -126,26 +134,17 @@ async def worker_init_request(request):
 # worker_status_request can be done in the proxy worker
 
 async def functions_metadata_request(request):
-    global protos, _metadata_result, _metadata_exception
+    global protos, _metadata_result
     logger.debug("V2 Library Worker: received WorkerMetadataRequest."
-                 " Metadata Result: %s, Metadata Exception: %s,"
+                 " Metadata Result: %s,"
                  " azure-functions version: %s",
-                 _metadata_result, _metadata_exception, get_sdk_version())
-
-    if _metadata_exception:
-        return protos.FunctionMetadataResponse(
-            result=protos.StatusResult(
-                status=protos.StatusResult.Failure,
-                exception=serialize_exception(
-                    _metadata_exception, protos)))
+                 _metadata_result, get_sdk_version())
 
-    else:
-        logger.debug("Successfully completed WorkerMetadataRequest.")
-        return protos.FunctionMetadataResponse(
-            use_default_metadata_indexing=False,
-            function_metadata_results=_metadata_result,
-            result=protos.StatusResult(
-                status=protos.StatusResult.Success))
+    return protos.FunctionMetadataResponse(
+        use_default_metadata_indexing=False,
+        function_metadata_results=_metadata_result,
+        result=protos.StatusResult(
+            status=protos.StatusResult.Success))
 
 
 async def function_load_request(request):
@@ -154,7 +153,6 @@ async def function_load_request(request):
     func_request = request.request.function_load_request
     function_id = func_request.function_id
 
-    logger.debug("Successfully completed WorkerLoadRequest.")
     return protos.FunctionLoadResponse(
         function_id=function_id,
         result=protos.StatusResult(
@@ -177,9 +175,9 @@ async def invocation_request(request):
         fi: FunctionInfo = _functions.get_function(
             function_id)
         assert fi is not None
-        logger.debug("Function name: %s, Function Type: %s",
-                     fi.name,
-                     ("async" if fi.is_async else "sync"))
+        logger.info("Function name: %s, Function Type: %s",
+                    fi.name,
+                    ("async" if fi.is_async else "sync"))
 
         args = {}
 
@@ -295,8 +293,8 @@ async def function_environment_reload_request(request):
     This is called only when placeholder mode is true. On worker restarts
     worker init request will be called directly.
     """
-    logger.info("V2 Library Worker: received WorkerEnvReloadRequest,"
-                "Version %s", VERSION)
+    logger.debug("V2 Library Worker: received WorkerEnvReloadRequest,"
+                 "Version %s", VERSION)
     global _host, protos, _metadata_exception
     try:
 
@@ -349,7 +347,10 @@ async def function_environment_reload_request(request):
                     initialize_http_server(_host)
                 capabilities[REQUIRES_ROUTE_PARAMETERS] = TRUE
         except HttpServerInitError as ex:
-            _metadata_exception = ex
+            return protos.FunctionEnvironmentReloadResponse(
+                result=protos.StatusResult(
+                    status=protos.StatusResult.Failure,
+                    exception=serialize_exception(ex, protos)))
 
         # Change function app directory
         if getattr(func_env_reload_request,
@@ -365,7 +366,6 @@ async def function_environment_reload_request(request):
                 status=protos.StatusResult.Success))
 
     except Exception as ex:
-        _metadata_exception = ex
         return protos.FunctionEnvironmentReloadResponse(
             result=protos.StatusResult(
                 status=protos.StatusResult.Failure,
@@ -385,7 +385,7 @@ def load_function_metadata(function_app_directory, caller_info):
             default_value=PYTHON_SCRIPT_FILE_NAME_DEFAULT)
 
         logger.debug(
-            'Received load metadata request from %s, '
+            'Received load_function_metadata request from %s, '
             'script_file_name: %s',
             caller_info, script_file_name)
 
@@ -406,10 +406,6 @@ def load_function_metadata(function_app_directory, caller_info):
 def index_functions(function_path: str, function_dir: str):
     global protos
     indexed_functions = index_function_app(function_path)
-    logger.info(
-        "Indexed function app and found %s functions",
-        len(indexed_functions)
-    )
 
     if indexed_functions:
         fx__metadata_results, fx_bindings_logs = (
@@ -436,7 +432,8 @@ def index_functions(function_path: str, function_dir: str):
             indexed_function_logs.append(function_log)
 
         log_data = {
-            "message": "Successfully processed FunctionMetadataRequest",
+            "message": "Successfully indexed function app.",
+            "function_count": len(indexed_functions),
             "functions": " ".join(indexed_function_logs),
             "deferred_bindings_enabled": _functions.deferred_bindings_enabled(),
             "app_settings": get_python_appsetting_state()

azure_functions_worker_v2/azure_functions_worker_v2/http_v2.py

@@ -277,10 +277,15 @@ def ext_base(cls):
 
     @classmethod
     def _check_http_v2_enabled(cls):
-        import azurefunctions.extensions.base as ext_base
-        cls._ext_base = ext_base
-
-        return cls._ext_base.HttpV2FeatureChecker.http_v2_enabled()
+        try:
+            # Attempt to import the base extension module
+            import azurefunctions.extensions.base as ext_base
+            cls._ext_base = ext_base
+
+            return cls._ext_base.HttpV2FeatureChecker.http_v2_enabled()
+        except ImportError:
+            logger.debug("ImportError when importing base extension.")
+            return False
 
 
 http_coordinator = HttpCoordinator()

azure_functions_worker_v2/tests/unittests/test_code_quality.py

@@ -5,7 +5,7 @@
 import sys
 import unittest
 
-ROOT_PATH = pathlib.Path(__file__).parent.parent.parent
+ROOT_PATH = pathlib.Path(__file__).parent.parent.parent.parent
 
 
 class TestCodeQuality(unittest.TestCase):

azure_functions_worker_v2/tests/unittests/test_utilities.py

@@ -257,22 +257,25 @@ def test_app_settings_should_return_value(self):
         self.assertEqual(app_setting, '42')
 
     def test_app_settings_not_set_should_return_default_value(self):
-        app_setting = app_setting_manager.get_app_setting(TEST_APP_SETTING_NAME, 'default')
+        app_setting = app_setting_manager.get_app_setting(TEST_APP_SETTING_NAME,
+                                                          'default')
         self.assertEqual(app_setting, 'default')
 
     def test_app_settings_should_ignore_default_value(self):
         # Set application setting by os.setenv
         os.environ.update({TEST_APP_SETTING_NAME: '42'})
 
         # Try using utility to acquire application setting
-        app_setting = app_setting_manager.get_app_setting(TEST_APP_SETTING_NAME, 'default')
+        app_setting = app_setting_manager.get_app_setting(TEST_APP_SETTING_NAME,
+                                                          'default')
         self.assertEqual(app_setting, '42')
 
     def test_app_settings_should_not_trigger_validator_when_not_set(self):
         def raise_excpt(value: str):
             raise Exception('Should not raise on app setting not found')
 
-        app_setting_manager.get_app_setting(TEST_APP_SETTING_NAME, validator=raise_excpt)
+        app_setting_manager.get_app_setting(TEST_APP_SETTING_NAME,
+                                            validator=raise_excpt)
 
     def test_app_settings_return_default_value_when_validation_fail(self):
         def parse_int_no_raise(value: str):
@@ -322,13 +325,12 @@ def test_invalid_script_file_name(self):
         file_name = 'test'
         with self.assertRaises(validators.InvalidFileNameError):
             validators.validate_script_file_name(file_name)
-    
+
     def test_set_get_sdk_version(self):
         test_version = '1.2.3'
         helpers.set_sdk_version(test_version)
         self.assertEqual(helpers.get_sdk_version(), test_version)
 
-
     def _unset_feature_flag(self):
         try:
             os.environ.pop(TEST_FEATURE_FLAG)

workers/proxy_worker/dispatcher.py

@@ -409,13 +409,17 @@ async def _handle__worker_init_request(self, request):
                     self.request_id)
 
         if DependencyManager.is_in_linux_consumption():
-            import azure_functions_worker_v2
+            import azure_functions_worker_v2  # NoQA
 
         if DependencyManager.should_load_cx_dependencies():
             DependencyManager.prioritize_customer_dependencies()
 
         directory = request.worker_init_request.function_app_directory
         self.reload_library_worker(directory)
+        logger.info('Using library: %s, '
+                    'library version: %s',
+                    _library_worker,
+                    _library_worker.version.VERSION)  # type: ignore[union-attr]
 
         init_request = WorkerRequest(name="WorkerInitRequest",
                                      request=request,
@@ -442,6 +446,10 @@ async def _handle__function_environment_reload_request(self, request):
 
         DependencyManager.prioritize_customer_dependencies(directory)
         self.reload_library_worker(directory)
+        logger.info('Using library: %s, '
+                    'library version: %s',
+                    _library_worker,
+                    _library_worker.version.VERSION)  # type: ignore[union-attr]
 
         env_reload_request = WorkerRequest(name="FunctionEnvironmentReloadRequest",
                                            request=request,

workers/proxy_worker/start_worker.py

@@ -7,6 +7,7 @@
 
 _GRPC_CONNECTION_TIMEOUT = 5.0
 
+
 def parse_args():
     parser = argparse.ArgumentParser(
         description='Python Azure Functions Worker')

workers/proxy_worker/utils/constants.py

@@ -12,4 +12,3 @@
 # new programming model default script file name
 PYTHON_SCRIPT_FILE_NAME = "PYTHON_SCRIPT_FILE_NAME"
 PYTHON_SCRIPT_FILE_NAME_DEFAULT = "function_app.py"
-

workers/proxy_worker/utils/dependency.py

@@ -134,21 +134,18 @@ def prioritize_customer_dependencies(cls, cx_working_dir=None):
         if not cx_deps_path:
             cx_deps_path = cls.cx_deps_path
 
-        logger.info(
-            'Applying prioritize_customer_dependencies: '
-            'worker_dependencies_path: %s, customer_dependencies_path: %s, '
-            'working_directory: %s, Linux Consumption: %s, Placeholder: %s, '
-            'sys.path: %s',
-            cls.worker_deps_path, cx_deps_path, working_directory,
-            DependencyManager.is_in_linux_consumption(),
-            is_envvar_true("WEBSITE_PLACEHOLDER_MODE"), sys.path)
-
         cls._remove_from_sys_path(cls.worker_deps_path)
         cls._add_to_sys_path(cls.worker_deps_path, True)
         cls._add_to_sys_path(cls.cx_deps_path, True)
         cls._add_to_sys_path(working_directory, False)
 
-        logger.info(f'Finished prioritize_customer_dependencies: {sys.path}')
+        logger.info(
+            'Finished prioritize_customer_dependencies: '
+            'worker_dependencies_path: %s, customer_dependencies_path: %s, '
+            'working_directory: %s, Placeholder: %s, '
+            'sys.path: %s',
+            cls.worker_deps_path, cx_deps_path, working_directory,
+            is_envvar_true("WEBSITE_PLACEHOLDER_MODE"), sys.path)
 
     @classmethod
     def _add_to_sys_path(cls, path: str, add_to_first: bool):