Added console logging to show errors during function load & indexing (#1396)

* Added error logger

* Removed log

* fixed unit test

---------

Co-authored-by: gavin-aguiar <root@GavinPC>
Co-authored-by: hallvictoria <victoriahall@microsoft.com>

Author: 3 people

azure_functions_worker/dispatcher.py

@@ -30,7 +30,7 @@
                         PYTHON_ENABLE_DEBUG_LOGGING,
                         PYTHON_SCRIPT_FILE_NAME,
                         PYTHON_SCRIPT_FILE_NAME_DEFAULT,
-                        PYTHON_LANGUAGE_RUNTIME, CUSTOMER_PACKAGES_PATH)
+                        PYTHON_LANGUAGE_RUNTIME)
 from .extension import ExtensionManager
 from .logging import disable_console_logging, enable_console_logging
 from .logging import (logger, error_logger, is_system_log_category,
@@ -299,13 +299,8 @@ async def _handle__worker_init_request(self, request):
             DependencyManager.prioritize_customer_dependencies()
 
         if DependencyManager.is_in_linux_consumption():
-            logger.info(
-                "Importing azure functions in WorkerInitRequest")
             import azure.functions  # NoQA
 
-        if CUSTOMER_PACKAGES_PATH not in sys.path:
-            logger.warning("Customer packages not in sys path.")
-
         # loading bindings registry and saving results to a static
         # dictionary which will be later used in the invocation request
         bindings.load_binding_registry()
@@ -343,8 +338,6 @@ async def _handle__functions_metadata_request(self, request):
 
             if not os.path.exists(function_path):
                 # Fallback to legacy model
-                logger.info("%s does not exist. "
-                            "Switching to host indexing.", script_file_name)
                 return protos.StreamingMessage(
                     request_id=request.request_id,
                     function_metadata_response=protos.FunctionMetadataResponse(
@@ -379,7 +372,7 @@ async def _handle__function_load_request(self, request):
             'Received WorkerLoadRequest, request ID %s, function_id: %s,'
             'function_name: %s,', self.request_id, function_id, function_name)
 
-        programming_model = "V1"
+        programming_model = "V2"
         try:
             if not self._functions.get_function(function_id):
                 script_file_name = get_app_setting(
@@ -396,10 +389,11 @@ async def _handle__function_load_request(self, request):
                     # indexing is enabled and load request is called without
                     # calling the metadata request. In this case we index the
                     # function and update the workers registry
-                    programming_model = "V2"
                     _ = self.index_functions(function_path)
                 else:
                     # legacy function
+                    programming_model = "V1"
+
                     func = loader.load_function(
                         func_request.metadata.name,
                         func_request.metadata.directory,

azure_functions_worker/loader.py

@@ -152,9 +152,11 @@ def process_indexed_function(functions_registry: functions.Registry,
 
 @attach_message_to_exception(
     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} ',
+    message='Cannot find module. Please check the requirements.txt '
+            'file for the missing module. For more info, '
+            'please refer the troubleshooting '
+            f'guide: {MODULE_NOT_FOUND_TS_URL}. '
+            f'Current sys.path: {sys.path}',
     debug_logs='Error in load_function. '
                f'Sys Path: {sys.path}, Sys Module: {sys.modules},'
                'python-packages Path exists: '
@@ -206,7 +208,11 @@ 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='Cannot find module. Please check the requirements.txt '
+            'file for the missing module. For more info, '
+            'please refer the troubleshooting '
+            f'guide: {MODULE_NOT_FOUND_TS_URL}. '
+            f'Current sys.path: {sys.path}',
     debug_logs='Error in index_function_app. '
                f'Sys Path: {sys.path}, Sys Module: {sys.modules},'
                'python-packages Path exists: '

azure_functions_worker/utils/wrappers.py

@@ -5,7 +5,7 @@
 
 from .common import is_envvar_true, is_envvar_false
 from .tracing import extend_exception_message
-from ..logging import logger
+from ..logging import error_logger, logger
 
 
 def enable_feature_by(flag: str,
@@ -45,6 +45,7 @@ def call(*args, **kwargs):
             except expt_type as e:
                 if debug_logs is not None:
                     logger.error(debug_logs)
+                error_logger.exception("Error: %s, %s", e, message)
                 raise extend_exception_message(e, message)
         return call
     return decorate

tests/unittests/test_http_functions.py

@@ -315,12 +315,19 @@ def check_log_user_event_loop_error(self, host_out: typing.List[str]):
 
     def check_log_import_module_troubleshooting_url(self,
                                                     host_out: typing.List[str]):
-        self.assertIn("Exception: ModuleNotFoundError: "
-                      "No module named 'does_not_exist'. "
-                      "Please check the requirements.txt file for the "
-                      "missing module. For more info, please refer the "
-                      "troubleshooting guide: "
-                      "https://aka.ms/functions-modulenotfound", host_out)
+        passed = False
+        exception_message = "Exception: ModuleNotFoundError: "\
+                            "No module named 'does_not_exist'. "\
+                            "Cannot find module. "\
+                            "Please check the requirements.txt file for the "\
+                            "missing module. For more info, please refer the "\
+                            "troubleshooting guide: "\
+                            "https://aka.ms/functions-modulenotfound. "\
+                            "Current sys.path: "
+        for log in host_out:
+            if exception_message in log:
+                passed = True
+        self.assertTrue(passed)
 
     def test_print_logging_no_flush(self):
         r = self.webhost.request('GET', 'print_logging?message=Secret42')

tests/unittests/test_loader.py

@@ -188,12 +188,19 @@ def test_loader_outside_main_package_should_be_loaded_from_package(self):
         self.assertEqual(r.text, 'OK')
 
     def check_log_loader_module_not_found(self, host_out):
-        self.assertIn("Exception: ModuleNotFoundError: "
-                      "No module named 'notfound'. "
-                      "Please check the requirements.txt file for the "
-                      "missing module. For more info, please refer the "
-                      "troubleshooting guide: "
-                      "https://aka.ms/functions-modulenotfound", host_out)
+        passed = False
+        exception_message = "Exception: ModuleNotFoundError: "\
+                            "No module named 'notfound'. "\
+                            "Cannot find module. "\
+                            "Please check the requirements.txt file for the "\
+                            "missing module. For more info, please refer the "\
+                            "troubleshooting guide: "\
+                            "https://aka.ms/functions-modulenotfound. "\
+                            "Current sys.path: "
+        for log in host_out:
+            if exception_message in log:
+                passed = True
+        self.assertTrue(passed)
 
 
 class TestPluginLoader(testutils.AsyncTestCase):