Improve indexing related logs

azure_functions_worker/dispatcher.py

@@ -296,6 +296,10 @@ async def _handle__functions_metadata_request(self, request):
         directory = metadata_request.function_app_directory
         function_path = os.path.join(directory, SCRIPT_FILE_NAME)
 
+        logger.info(
+            'Received WorkerMetadataRequest, request ID %s, directory: %s',
+            self.request_id, directory)
+
         if not os.path.exists(function_path):
             # Fallback to legacy model
             logger.info(f"{SCRIPT_FILE_NAME} does not exist. "
@@ -310,13 +314,15 @@ async def _handle__functions_metadata_request(self, request):
         try:
             fx_metadata_results = []
             indexed_functions = loader.index_function_app(function_path)
+            logger.info('Indexed function app and found {} functions',
+                        len(indexed_functions))
             if indexed_functions:
                 indexed_function_logs: List[str] = []
                 for func in indexed_functions:
-                    function_log = \
-                        f"Function Name: {func.get_function_name()} " \
-                        "Function Binding: " \
-                        f"{[binding.name for binding in func.get_bindings()]}"
+                    function_log = "Function Name: {}, Function Binding: {}" \
+                        .format(func.get_function_name(),
+                                [(binding.type, binding.name) for binding in
+                                 func.get_bindings()])
                     indexed_function_logs.append(function_log)
 
                 logger.info(
@@ -327,8 +333,8 @@ async def _handle__functions_metadata_request(self, request):
                     self._functions,
                     indexed_functions)
             else:
-                logger.warning("No functions indexed. Please refer to the "
-                               "documentation.")
+                logger.warning("No functions indexed. Please refer to "
+                               "aka.ms/pythonprogrammingmodel for more info.")
 
             return protos.StreamingMessage(
                 request_id=request.request_id,
@@ -350,6 +356,10 @@ async def _handle__function_load_request(self, request):
         function_id = func_request.function_id
         function_name = func_request.metadata.name
 
+        logger.info(
+            'Received WorkerLoadRequest, request ID %s, function_id: %s,'
+            'function_name: %s,', self.request_id, function_id, function_name)
+
         try:
             if not self._functions.get_function(function_id):
                 func = loader.load_function(

azure_functions_worker/loader.py

@@ -21,6 +21,11 @@
 _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 = []
 
 
@@ -88,8 +93,10 @@ def process_indexed_function(functions_registry: functions.Registry,
     expt_type=ImportError,
     message=f'Please check the requirements.txt file for the missing module. '
             f'For more info, please refer the troubleshooting'
-            f' guide: {MODULE_NOT_FOUND_TS_URL} '
-)
+            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)}')
 def load_function(name: str, directory: str, script_file: str,
                   entry_point: Optional[str]):
     dir_path = pathlib.Path(directory)
@@ -137,8 +144,10 @@ def load_function(name: str, directory: str, script_file: str,
 
 @attach_message_to_exception(
     expt_type=ImportError,
-    message=f'Troubleshooting Guide: {MODULE_NOT_FOUND_TS_URL}'
-)
+    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)}')
 def index_function_app(function_path: str):
     module_name = pathlib.Path(function_path).stem
     imported_module = importlib.import_module(module_name)

azure_functions_worker/utils/wrappers.py

@@ -1,8 +1,11 @@
 # Copyright (c) Microsoft Corporation. All rights reserved.
 # Licensed under the MIT License.
+
+from typing import Callable, Any
+
 from .common import is_envvar_true, is_envvar_false
 from .tracing import extend_exception_message
-from typing import Callable, Any
+from ..logging import logger
 
 
 def enable_feature_by(flag: str,
@@ -33,12 +36,15 @@ def call(*args, **kwargs):
     return decorate
 
 
-def attach_message_to_exception(expt_type: Exception, message: str) -> Callable:
+def attach_message_to_exception(expt_type: Exception, message: str,
+                                debug_logs=None) -> Callable:
     def decorate(func):
         def call(*args, **kwargs):
             try:
                 return func(*args, **kwargs)
             except expt_type as e:
+                if debug_logs is not None:
+                    logger.error(debug_logs)
                 raise extend_exception_message(e, message)
         return call
     return decorate

setup.py

@@ -118,7 +118,7 @@
         "azure-eventhub~=5.7.0",  # Used for EventHub E2E tests
         "azure-functions-durable",  # Used for Durable E2E tests
         "flask",
-        "fastapi",
+        "fastapi~=0.85.0",  # Used for ASGIMiddleware test
         "pydantic",
         "pycryptodome~=3.10.1",
         "flake8~=4.0.1",

tests/endtoend/test_sql_functions.py

@@ -1,10 +1,12 @@
 # Copyright (c) Microsoft Corporation. All rights reserved.
 # Licensed under the MIT License.
 import json
+from unittest import skip
 
 from azure_functions_worker import testutils
 
 
+@skip("Unskip when azure functions with SQL is released.")
 class TestSqlFunctions(testutils.WebHostTestCase):
 
     @classmethod