Add timestamp in the received invocation logs (Azure#1378)

* adding timestamp to invocation req logs * fixing / adding tests * fixing tests for 3.7 * consolidate tests

Author: hallvictoria

azure_functions_worker/dispatcher.py

@@ -16,6 +16,7 @@
 from asyncio import BaseEventLoop
 from logging import LogRecord
 from typing import List, Optional
+from datetime import datetime
 
 import grpc
 
@@ -431,6 +432,7 @@ async def _handle__function_load_request(self, request):
  exception=self._serialize_exception(ex))))
 
  async def _handle__invocation_request(self, request):
+ invocation_time = datetime.utcnow()
  invoc_request = request.invocation_request
  invocation_id = invoc_request.invocation_id
  function_id = invoc_request.function_id
@@ -452,7 +454,8 @@ async def _handle__invocation_request(self, request):
  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"}'
+ f'function type: {"async" if fi.is_async else "sync"}',
+ f'timestamp (UTC): {invocation_time}'
  ]
  if not fi.is_async:
  function_invocation_logs.append(

tests/unittests/test_dispatcher.py

@@ -304,15 +304,20 @@ async def test_sync_invocation_request_log(self):
  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}'
- )
+ logs, _ = mock_logger.info.call_args
+ self.assertRegex(logs[0],
+ '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, '
+ r'timestamp \(UTC\): '
+ r'(\d{4}-\d{2}-\d{2} '
+ r'\d{2}:\d{2}:\d{2}.\d{6}), '
+ 'sync threadpool max workers: '
+ f'{self._default_workers}'
+ )
 
  async def test_async_invocation_request_log(self):
  with patch('azure_functions_worker.dispatcher.logger') as mock_logger:
@@ -323,14 +328,18 @@ async def test_async_invocation_request_log(self):
  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'
- )
+ logs, _ = mock_logger.info.call_args
+ self.assertRegex(logs[0],
+ '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, '
+ r'timestamp \(UTC\): '
+ r'(\d{4}-\d{2}-\d{2} '
+ r'\d{2}:\d{2}:\d{2}.\d{6})'
+ )
 
  async def test_sync_invocation_request_log_threads(self):
  os.environ.update({PYTHON_THREADPOOL_THREAD_COUNT: '5'})
@@ -342,15 +351,19 @@ async def test_sync_invocation_request_log_threads(self):
  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'
- )
+ logs, _ = mock_logger.info.call_args
+ self.assertRegex(logs[0],
+ '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, '
+ r'timestamp \(UTC\): '
+ r'(\d{4}-\d{2}-\d{2} '
+ r'\d{2}:\d{2}:\d{2}.\d{6}), '
+ 'sync threadpool max workers: 5'
+ )
 
  async def test_async_invocation_request_log_threads(self):
  os.environ.update({PYTHON_THREADPOOL_THREAD_COUNT: '4'})
@@ -362,14 +375,18 @@ async def test_async_invocation_request_log_threads(self):
  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'
- )
+ logs, _ = mock_logger.info.call_args
+ self.assertRegex(logs[0],
+ '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, '
+ r'timestamp \(UTC\): '
+ r'(\d{4}-\d{2}-\d{2} '
+ r'\d{2}:\d{2}:\d{2}.\d{6})'
+ )
 
  async def test_sync_invocation_request_log_in_placeholder_threads(self):
  with patch('azure_functions_worker.dispatcher.logger') as mock_logger:
@@ -383,15 +400,19 @@ async def test_sync_invocation_request_log_in_placeholder_threads(self):
  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'
- )
+ logs, _ = mock_logger.info.call_args
+ self.assertRegex(logs[0],
+ '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, '
+ r'timestamp \(UTC\): '
+ r'(\d{4}-\d{2}-\d{2} '
+ r'\d{2}:\d{2}:\d{2}.\d{6}), '
+ 'sync threadpool max workers: 5'
+ )
 
  async def test_async_invocation_request_log_in_placeholder_threads(self):
  with patch('azure_functions_worker.dispatcher.logger') as mock_logger:
@@ -405,14 +426,18 @@ async def test_async_invocation_request_log_in_placeholder_threads(self):
  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'
- )
+ logs, _ = mock_logger.info.call_args
+ self.assertRegex(logs[0],
+ '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, '
+ r'timestamp \(UTC\): '
+ r'(\d{4}-\d{2}-\d{2} '
+ r'\d{2}:\d{2}:\d{2}.\d{6})'
+ )
 
  async def _assert_workers_threadpool(self, ctrl, host,
  expected_worker_count):