Repository: Azure/azure-functions-python-worker (language: python)

Issue:
[FeatureRequest] Add timestamp in the received invocation logs
**Describe the request: A clear and concise description.**
Adding a utcnow time stamp that is added to the ReceivedInvocationRequest


Discussion / hints:

Fix patch:
diff --git a/azure_functions_worker/dispatcher.py b/azure_functions_worker/dispatcher.py
index 625397f5..a0ac974d 100644
--- a/azure_functions_worker/dispatcher.py
+++ b/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(


Test patch:
diff --git a/tests/unittests/test_dispatcher.py b/tests/unittests/test_dispatcher.py
index 43df8819..0605a7dd 100644
--- a/tests/unittests/test_dispatcher.py
+++ b/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):