Repository: Azure/azure-functions-python-worker

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:
codecov[bot]: ## [Codecov](https://app.codecov.io/gh/Azure/azure-functions-python-worker/pull/1378?src=pr&el=h1&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) Report
All modified and coverable lines are covered by tests :white_check_mark:
> Comparison is base [(`f269c09`)](https://app.codecov.io/gh/Azure/azure-functions-python-worker/commit/f269c09764da25e70cad4c6f4bd785cd86221c12?el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) 85.81% compared to head [(`512a37e`)](https://app.codecov.io/gh/Azure/azure-functions-python-worker/pull/1378?src=pr&el=desc&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) 85.11%.


<details><summary>Additional details and impacted files</summary>


```diff
@@            Coverage Diff             @@
##              dev    #1378      +/-   ##
==========================================
- Coverage   85.81%   85.11%   -0.71%     
==========================================
  Files          35       35              
  Lines        1953     1955       +2     
  Branches      370      370              
==========================================
- Hits         1676     1664      -12     
- Misses        208      217       +9     
- Partials       69       74       +5     
```

| [Flag](https://app.codecov.io/gh/Azure/azure-functions-python-worker/pull/1378/flags?src=pr&el=flags&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) | Coverage Δ | |
|---|---|---|
| [unittests](https://app.codecov.io/gh/Azure/azure-functions-python-worker/pull/1378/flags?src=pr&el=flag&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure) | `85.06% <100.00%> (-0.71%)` | :arrow_down: |

Flags with carried forward coverage won't be shown. [Click here](https://docs.codecov.io/docs/carryforward-flags?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure#carryforward-flags-in-the-pull-request-comment) to find out more.


</details>

[:umbrella: View full report in Codecov by Sentry](https://app.codecov.io/gh/Azure/azure-functions-python-worker/pull/1378?src=pr&el=continue&utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure).   
:loudspeaker: Have feedback on the report? [Share it here](https://about.codecov.io/codecov-pr-comment-feedback/?utm_medium=referral&utm_source=github&utm_content=comment&utm_campaign=pr+comments&utm_term=Azure).


Patch:
diff --git a/azure_functions_worker/dispatcher.py b/azure_functions_worker/dispatcher.py
index 625397f..a0ac974 100644
--- a/azure_functions_worker/dispatcher.py
+++ b/azure_functions_worker/dispatcher.py
@@ -16,6 +16,7 @@ import threading
 from asyncio import BaseEventLoop
 from logging import LogRecord
 from typing import List, Optional
+from datetime import datetime
 
 import grpc
 
@@ -431,6 +432,7 @@ class Dispatcher(metaclass=DispatcherMeta):
                         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 @@ class Dispatcher(metaclass=DispatcherMeta):
                 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 43df881..0605a7d 100644
--- a/tests/unittests/test_dispatcher.py
+++ b/tests/unittests/test_dispatcher.py
@@ -304,15 +304,20 @@ class TestThreadPoolSettingsPython37(testutils.AsyncTestCase):
                     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 @@ class TestThreadPoolSettingsPython37(testutils.AsyncTestCase):
                     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 @@ class TestThreadPoolSettingsPython37(testutils.AsyncTestCase):
                     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 @@ class TestThreadPoolSettingsPython37(testutils.AsyncTestCase):
                     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 @@ class TestThreadPoolSettingsPython37(testutils.AsyncTestCase):
                     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 @@ class TestThreadPoolSettingsPython37(testutils.AsyncTestCase):
                     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):