Added console logging to show errors during function load & indexing (Azure#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):