Adding updates to the log messages (#805)

Author: vrdmr

azure_functions_worker/dispatcher.py

@@ -333,6 +333,7 @@ async def _handle__invocation_request(self, req):
                 'Received FunctionInvocationRequest',
                 f'request ID: {self.request_id}',
                 f'function ID: {function_id}',
+                f'function name: {fi.name}',
                 f'invocation ID: {invocation_id}',
                 f'function type: {"async" if fi.is_async else "sync"}'
             ]

azure_functions_worker/testutils.py

@@ -722,7 +722,8 @@ def start_webhost(*, script_dir=None, stdout=None):
             proc.wait(20)
         except subprocess.TimeoutExpired:
             proc.kill()
-        raise RuntimeError('could not start the webworker')
+        raise RuntimeError('could not start the webworker in time. Please'
+                           f' check the log file for details: {stdout.name} ')
 
     return _WebHostProxy(proc, addr)
 

tests/unittests/test_dispatcher.py

@@ -197,12 +197,15 @@ async def test_sync_invocation_request_log(self):
         with patch('azure_functions_worker.dispatcher.logger') as mock_logger:
             async with self._ctrl as host:
                 request_id: str = self._ctrl._worker._request_id
-                func_id, invoke_id = await self._check_if_function_is_ok(host)
+                func_id, invoke_id, func_name = (
+                    await self._check_if_function_is_ok(host)
+                )
 
                 mock_logger.info.assert_any_call(
                     'Received FunctionInvocationRequest, '
                     f'request ID: {request_id}, '
                     f'function ID: {func_id}, '
+                    f'function name: {func_name}, '
                     f'invocation ID: {invoke_id}, '
                     'function type: sync, '
                     f'sync threadpool max workers: {self._default_workers}'
@@ -212,14 +215,15 @@ async def test_async_invocation_request_log(self):
         with patch('azure_functions_worker.dispatcher.logger') as mock_logger:
             async with self._ctrl as host:
                 request_id: str = self._ctrl._worker._request_id
-                func_id, invoke_id = (
+                func_id, invoke_id, func_name = (
                     await self._check_if_async_function_is_ok(host)
                 )
 
                 mock_logger.info.assert_any_call(
                     'Received FunctionInvocationRequest, '
                     f'request ID: {request_id}, '
                     f'function ID: {func_id}, '
+                    f'function name: {func_name}, '
                     f'invocation ID: {invoke_id}, '
                     'function type: async'
                 )
@@ -230,12 +234,15 @@ async def test_sync_invocation_request_log_threads(self):
         with patch('azure_functions_worker.dispatcher.logger') as mock_logger:
             async with self._ctrl as host:
                 request_id: str = self._ctrl._worker._request_id
-                func_id, invoke_id = await self._check_if_function_is_ok(host)
+                func_id, invoke_id, func_name = (
+                    await self._check_if_function_is_ok(host)
+                )
 
                 mock_logger.info.assert_any_call(
                     'Received FunctionInvocationRequest, '
                     f'request ID: {request_id}, '
                     f'function ID: {func_id}, '
+                    f'function name: {func_name}, '
                     f'invocation ID: {invoke_id}, '
                     'function type: sync, '
                     'sync threadpool max workers: 5'
@@ -247,14 +254,15 @@ async def test_async_invocation_request_log_threads(self):
         with patch('azure_functions_worker.dispatcher.logger') as mock_logger:
             async with self._ctrl as host:
                 request_id: str = self._ctrl._worker._request_id
-                func_id, invoke_id = (
+                func_id, invoke_id, func_name = (
                     await self._check_if_async_function_is_ok(host)
                 )
 
                 mock_logger.info.assert_any_call(
                     'Received FunctionInvocationRequest, '
                     f'request ID: {request_id}, '
                     f'function ID: {func_id}, '
+                    f'function name: {func_name}, '
                     f'invocation ID: {invoke_id}, '
                     'function type: async'
                 )
@@ -267,12 +275,15 @@ async def test_sync_invocation_request_log_in_placeholder_threads(self):
                 })
 
                 request_id: str = self._ctrl._worker._request_id
-                func_id, invoke_id = await self._check_if_function_is_ok(host)
+                func_id, invoke_id, func_name = (
+                    await self._check_if_function_is_ok(host)
+                )
 
                 mock_logger.info.assert_any_call(
                     'Received FunctionInvocationRequest, '
                     f'request ID: {request_id}, '
                     f'function ID: {func_id}, '
+                    f'function name: {func_name}, '
                     f'invocation ID: {invoke_id}, '
                     'function type: sync, '
                     'sync threadpool max workers: 5'
@@ -286,14 +297,15 @@ async def test_async_invocation_request_log_in_placeholder_threads(self):
                 })
 
                 request_id: str = self._ctrl._worker._request_id
-                func_id, invoke_id = (
+                func_id, invoke_id, func_name = (
                     await self._check_if_async_function_is_ok(host)
                 )
 
                 mock_logger.info.assert_any_call(
                     'Received FunctionInvocationRequest, '
                     f'request ID: {request_id}, '
                     f'function ID: {func_id}, '
+                    f'function name: {func_name}, '
                     f'invocation ID: {invoke_id}, '
                     'function type: async'
                 )
@@ -308,7 +320,8 @@ async def _assert_workers_threadpool(self, ctrl, host,
 
     async def _check_if_function_is_ok(self, host) -> Tuple[str, str]:
         # Ensure the function can be properly loaded
-        func_id, load_r = await host.load_function('show_context')
+        function_name = "show_context"
+        func_id, load_r = await host.load_function(function_name)
         self.assertEqual(load_r.response.function_id, func_id)
         self.assertEqual(load_r.response.result.status,
                          protos.StatusResult.Success)
@@ -329,10 +342,11 @@ async def _check_if_function_is_ok(self, host) -> Tuple[str, str]:
         self.assertEqual(call_r.response.result.status,
                          protos.StatusResult.Success)
 
-        return func_id, invoke_id
+        return func_id, invoke_id, function_name
 
     async def _check_if_async_function_is_ok(self, host) -> Tuple[str, str]:
         # Ensure the function can be properly loaded
+        function_name = "show_context_async"
         func_id, load_r = await host.load_function('show_context_async')
         self.assertEqual(load_r.response.function_id, func_id)
         self.assertEqual(load_r.response.result.status,
@@ -354,7 +368,7 @@ async def _check_if_async_function_is_ok(self, host) -> Tuple[str, str]:
         self.assertEqual(call_r.response.result.status,
                          protos.StatusResult.Success)
 
-        return func_id, invoke_id
+        return func_id, invoke_id, function_name
 
 
 class TestThreadPoolSettingsPython38(TestThreadPoolSettingsPython37):