Enable logging in user created event_loop (#610)

* Inject _invocation_id with lowest priority

* Add unit tests

* Change back host version

* Add logging test facility in testutil

* Change file name

* Add tests on old logging

Author: Hazhzeng

azure_functions_worker/dispatcher.py

@@ -512,8 +512,10 @@ def get_current_invocation_id():
     if loop is not None:
         current_task = asyncio.Task.current_task(loop)
         if current_task is not None:
-            return getattr(
+            task_invocation_id = getattr(
                 current_task, ContextEnabledTask._AZURE_INVOCATION_ID, None)
+            if task_invocation_id is not None:
+                return task_invocation_id
 
     return getattr(_invocation_id_local, 'v', None)
 

azure_functions_worker/testutils.py

@@ -126,10 +126,25 @@ class WebHostTestCaseMeta(type(unittest.TestCase)):
     def __new__(mcls, name, bases, dct):
         for attrname, attr in dct.items():
             if attrname.startswith('test_') and callable(attr):
-
-                @functools.wraps(attr)
-                def wrapper(self, *args, __meth__=attr, **kwargs):
-                    return self._run_test(__meth__, *args, **kwargs)
+                test_case_name = attrname.lstrip('test_')
+                test_case = attr
+
+                check_log_case_name = f'check_log_{test_case_name}'
+                check_log_case = dct.get(check_log_case_name)
+
+                @functools.wraps(test_case)
+                def wrapper(self, *args, __meth__=test_case,
+                            __check_log__=check_log_case, **kwargs):
+                    if __check_log__ is not None and callable(__check_log__):
+                        # Check logging output for unit test scenarios
+                        result = self._run_test(__meth__, *args, **kwargs)
+                        output_lines = self.host_out.splitlines()
+                        host_out = list(map(lambda s: s.strip(), output_lines))
+                        self._run_test(__check_log__, host_out=host_out)
+                        return result
+                    else:
+                        # Check normal unit test
+                        return self._run_test(__meth__, *args, **kwargs)
 
                 dct[attrname] = wrapper
 
@@ -188,16 +203,20 @@ def _run_test(self, test, *args, **kwargs):
             self.host_stdout.read()
             last_pos = self.host_stdout.tell()
 
+            test_exception = None
             try:
                 test(self, *args, **kwargs)
-            except Exception:
-                try:
-                    self.host_stdout.seek(last_pos)
-                    host_out = self.host_stdout.read()
-                    self.host_stdout_logger.error(
-                        f'Captured WebHost stdout:\n{host_out}')
-                finally:
-                    raise
+            except Exception as e:
+                test_exception = e
+
+            try:
+                self.host_stdout.seek(last_pos)
+                self.host_out = self.host_stdout.read()
+                self.host_stdout_logger.error(
+                    f'Captured WebHost stdout:\n{self.host_out}')
+            finally:
+                if test_exception is not None:
+                    raise test_exception
 
 
 class _MockWebHostServicer(protos.FunctionRpcServicer):
@@ -725,7 +744,8 @@ def _setup_func_app(app_root):
         f.write(HOST_JSON_TEMPLATE)
 
     _symlink_dir(TESTS_ROOT / 'common' / 'ping', ping_func)
-    _symlink_dir(EXTENSIONS_PATH, extensions)
+    if EXTENSIONS_PATH.exists():
+        _symlink_dir(EXTENSIONS_PATH, extensions)
 
 
 def _teardown_func_app(app_root):

tests/unittests/http_functions/user_event_loop/function.json

@@ -0,0 +1,19 @@
+{
+  "scriptFile": "main.py",
+  "bindings": [
+    {
+      "authLevel": "anonymous",
+      "type": "httpTrigger",
+      "direction": "in",
+      "name": "req",
+      "methods": [
+        "get"
+      ]
+    },
+    {
+      "type": "http",
+      "direction": "out",
+      "name": "$return"
+    }
+  ]
+}

tests/unittests/http_functions/user_event_loop/main.py

@@ -0,0 +1,21 @@
+import logging
+import asyncio
+
+import azure.functions as func
+
+
+logger = logging.getLogger('my function')
+
+
+async def try_log():
+    logger.info("try_log")
+
+
+def main(req: func.HttpRequest) -> func.HttpResponse:
+    loop = asyncio.SelectorEventLoop()
+    asyncio.set_event_loop(loop)
+
+    # This line should throws an asyncio RuntimeError exception
+    loop.run_until_complete(try_log())
+    loop.close()
+    return 'OK-user-event-loop'

tests/unittests/test_http_functions.py

@@ -1,6 +1,7 @@
 import hashlib
 import pathlib
 import filecmp
+import typing
 import os
 
 from azure_functions_worker import testutils
@@ -88,12 +89,19 @@ def test_async_logging(self):
         self.assertEqual(r.status_code, 200)
         self.assertEqual(r.text, 'OK-async')
 
+    def check_log_async_logging(self, host_out: typing.List[str]):
+        self.assertIn('hello info', host_out)
+        self.assertIn('and another error', host_out)
+
     def test_sync_logging(self):
         # Test that logging doesn't *break* things.
         r = self.webhost.request('GET', 'sync_logging')
         self.assertEqual(r.status_code, 200)
         self.assertEqual(r.text, 'OK-sync')
 
+    def check_log_sync_logging(self, host_out: typing.List[str]):
+        self.assertIn('a gracefully handled error')
+
     def test_return_context(self):
         r = self.webhost.request('GET', 'return_context')
         self.assertEqual(r.status_code, 200)
@@ -263,3 +271,12 @@ def test_application_octet_stream_content_type(self):
         finally:
             if (os.path.exists(received_img_file)):
                 os.remove(received_img_file)
+
+    def test_user_event_loop_error(self):
+        # User event loop is not supported in HTTP trigger
+        r = self.webhost.request('GET', 'user_event_loop/')
+        self.assertEqual(r.status_code, 200)
+        self.assertEqual(r.text, 'OK-user-event-loop')
+
+    def check_log_user_event_loop_error(self, host_out: typing.List[str]):
+        self.assertIn('try_log', host_out)

tests/unittests/test_mock_timer_functions.py

@@ -38,3 +38,28 @@ async def call_and_check(due: bool):
 
             await call_and_check(True)
             await call_and_check(False)
+
+    async def test_mock_timer__user_event_loop(self):
+        async with testutils.start_mockhost(
+                script_root=self.timer_funcs_dir) as host:
+
+            func_id, r = await host.load_function('user_event_loop_timer')
+
+            self.assertEqual(r.response.function_id, func_id)
+            self.assertEqual(r.response.result.status,
+                             protos.StatusResult.Success)
+
+            async def call_and_check():
+                _, r = await host.invoke_function(
+                    'user_event_loop_timer', [
+                        protos.ParameterBinding(
+                            name='timer',
+                            data=protos.TypedData(
+                                json=json.dumps({
+                                    'IsPastDue': False
+                                })))
+                    ])
+                self.assertEqual(r.response.result.status,
+                                 protos.StatusResult.Success)
+
+            await call_and_check()

tests/unittests/timer_functions/user_event_loop_timer/function.json

@@ -0,0 +1,11 @@
+{
+  "scriptFile": "main.py",
+  "bindings": [
+    {
+      "type": "timerTrigger",
+      "direction": "in",
+      "name": "timer",
+      "schedule": "*/5 * * * * *"
+    }
+  ]
+}

tests/unittests/timer_functions/user_event_loop_timer/main.py

@@ -0,0 +1,18 @@
+import logging
+import asyncio
+
+import azure.functions as func
+
+
+logger = logging.getLogger('my function')
+
+
+async def try_log():
+    logger.info("try_log")
+
+
+def main(timer: func.TimerRequest):
+    loop = asyncio.SelectorEventLoop()
+    asyncio.set_event_loop(loop)
+    loop.run_until_complete(try_log())
+    loop.close()