Adding support for debug logs in executed functions. (#745)

* Adding support for debug logs in executed functions.
* Adding tests to see make sure host prevents debug logs

.gitignore

@@ -84,7 +84,7 @@ celerybeat-schedule
 
 # virtualenv (.venv/.venv36/.venv37/.venv38)
 .venv*
-venv/
+venv*/
 ENV/
 py3env/
 

azure_functions_worker/dispatcher.py

@@ -126,7 +126,7 @@ async def dispatch_forever(self):
             # established, should use it for system and user logs
             logging_handler = AsyncLoggingHandler()
             root_logger = logging.getLogger()
-            root_logger.setLevel(logging.INFO)
+            root_logger.setLevel(logging.DEBUG)
             root_logger.addHandler(logging_handler)
             logger.info('Switched to gRPC logging.')
             logging_handler.flush()

azure_functions_worker/main.py

@@ -5,21 +5,28 @@
 
 import argparse
 
-from ._thirdparty import aio_compat
 from . import dispatcher
 from . import logging
+from ._thirdparty import aio_compat
 from .logging import error_logger, logger
 
 
 def parse_args():
     parser = argparse.ArgumentParser(
         description='Python Azure Functions Worker')
-    parser.add_argument('--host')
-    parser.add_argument('--port', type=int)
-    parser.add_argument('--workerId', dest='worker_id')
-    parser.add_argument('--requestId', dest='request_id')
+    parser.add_argument('--host',
+                        help="host address")
+    parser.add_argument('--port', type=int,
+                        help='id for the requests')
+    parser.add_argument('--workerId', dest='worker_id',
+                        help='id for the worker')
+    parser.add_argument('--requestId', dest='request_id',
+                        help='log destination: stdout, stderr, '
+                             'syslog, or a file path')
     parser.add_argument('--log-level', type=str, default='INFO',
-                        choices=['TRACE', 'INFO', 'WARNING', 'ERROR'],)
+                        choices=['TRACE', 'INFO', 'WARNING', 'ERROR'],
+                        help="log level: 'TRACE', 'INFO', 'WARNING', "
+                             "or 'ERROR'")
     parser.add_argument('--log-to', type=str, default=None,
                         help='log destination: stdout, stderr, '
                              'syslog, or a file path')
@@ -45,8 +52,9 @@ def main():
 
 
 async def start_async(host, port, worker_id, request_id):
-    disp = await dispatcher.Dispatcher.connect(
-        host, port, worker_id, request_id,
-        connect_timeout=5.0)
+    disp = await dispatcher.Dispatcher.connect(host=host, port=port,
+                                               worker_id=worker_id,
+                                               request_id=request_id,
+                                               connect_timeout=5.0)
 
     await disp.dispatch_forever()

azure_functions_worker/testutils.py

@@ -148,7 +148,7 @@ def wrapper(self, *args, __meth__=test_case,
                         # Trim off host output timestamps
                         host_output = getattr(self, 'host_out', '')
                         output_lines = host_output.splitlines()
-                        ts_re = r"^\[\d+\/\d+\/\d+ \d+\:\d+\:\d+ (A|P)M\]"
+                        ts_re = r"^\[\d+\/\d+\/\d+ \d+\:\d+\:\d+.*(A|P)*M*\]"
                         output = list(map(
                             lambda s: re.sub(ts_re, '', s).strip(),
                             output_lines))
@@ -171,6 +171,11 @@ class WebHostTestCase(unittest.TestCase, metaclass=WebHostTestCaseMeta):
     In addition to automatically starting up a WebHost instance,
     this test case class logs WebHost stdout/stderr in case
     a unit test fails.
+
+    You can write two sets of test - test_* and check_log_* tests.
+
+    test_ABC - Unittest
+    check_log_ABC - Check logs generated during the execution of test_ABC.
     """
     host_stdout_logger = logging.getLogger('webhosttests')
 
@@ -728,7 +733,7 @@ def call(*args, **kwargs):
     return decorate
 
 
-def _remove_path(path):
+def remove_path(path):
     if path.is_symlink():
         path.unlink()
     elif path.is_dir():
@@ -738,7 +743,7 @@ def _remove_path(path):
 
 
 def _symlink_dir(src, dst):
-    _remove_path(dst)
+    remove_path(dst)
 
     if ON_WINDOWS:
         shutil.copytree(str(src), str(dst))
@@ -751,8 +756,9 @@ def _setup_func_app(app_root):
     ping_func = app_root / 'ping'
     host_json = app_root / 'host.json'
 
-    with open(host_json, 'w') as f:
-        f.write(HOST_JSON_TEMPLATE)
+    if not os.path.isfile(host_json):
+        with open(host_json, 'w') as f:
+            f.write(HOST_JSON_TEMPLATE)
 
     _symlink_dir(TESTS_ROOT / 'common' / 'ping', ping_func)
     _symlink_dir(EXTENSIONS_PATH, extensions)
@@ -764,7 +770,7 @@ def _teardown_func_app(app_root):
     host_json = app_root / 'host.json'
 
     for path in (extensions, ping_func, host_json):
-        _remove_path(path)
+        remove_path(path)
 
 
 def _main():

tests/unittests/http_functions/debug_logging/function.json

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

tests/unittests/http_functions/debug_logging/main.py

@@ -0,0 +1,13 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License.
+import logging
+
+import azure.functions
+
+
+def main(req: azure.functions.HttpRequest):
+    logging.info('logging info', exc_info=True)
+    logging.warning('logging warning', exc_info=True)
+    logging.debug('logging debug', exc_info=True)
+    logging.error('logging error', exc_info=True)
+    return 'OK-debug'

tests/unittests/http_functions/debug_user_logging/function.json

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

tests/unittests/http_functions/debug_user_logging/main.py

@@ -0,0 +1,16 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License.
+import logging
+
+import azure.functions
+
+
+logger = logging.getLogger('my function')
+
+
+def main(req: azure.functions.HttpRequest):
+    logger.info('logging info', exc_info=True)
+    logger.warning('logging warning', exc_info=True)
+    logger.debug('logging debug', exc_info=True)
+    logger.error('logging error', exc_info=True)
+    return 'OK-user-debug'

tests/unittests/log_filtering_functions/debug_logging/function.json

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

tests/unittests/log_filtering_functions/debug_logging/main.py

@@ -0,0 +1,13 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License.
+import logging
+
+import azure.functions
+
+
+def main(req: azure.functions.HttpRequest):
+    logging.info('logging info', exc_info=True)
+    logging.warning('logging warning', exc_info=True)
+    logging.debug('logging debug', exc_info=True)
+    logging.error('logging error', exc_info=True)
+    return 'OK-debug'

tests/unittests/log_filtering_functions/debug_user_logging/function.json

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

tests/unittests/log_filtering_functions/debug_user_logging/main.py

@@ -0,0 +1,16 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License.
+import logging
+
+import azure.functions
+
+
+logger = logging.getLogger('my function')
+
+
+def main(req: azure.functions.HttpRequest):
+    logger.info('logging info', exc_info=True)
+    logger.warning('logging warning', exc_info=True)
+    logger.debug('logging debug', exc_info=True)
+    logger.error('logging error', exc_info=True)
+    return 'OK-user-debug'

tests/unittests/test_http_functions.py

@@ -96,6 +96,28 @@ 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_debug_logging(self):
+        r = self.webhost.request('GET', 'debug_logging')
+        self.assertEqual(r.status_code, 200)
+        self.assertEqual(r.text, 'OK-debug')
+
+    def check_log_debug_logging(self, host_out: typing.List[str]):
+        self.assertIn('logging info', host_out)
+        self.assertIn('logging warning', host_out)
+        self.assertIn('logging debug', host_out)
+        self.assertIn('logging error', host_out)
+
+    def test_debug_with_user_logging(self):
+        r = self.webhost.request('GET', 'debug_user_logging')
+        self.assertEqual(r.status_code, 200)
+        self.assertEqual(r.text, 'OK-user-debug')
+
+    def check_log_debug_with_user_logging(self, host_out: typing.List[str]):
+        self.assertIn('logging info', host_out)
+        self.assertIn('logging warning', host_out)
+        self.assertIn('logging debug', host_out)
+        self.assertIn('logging error', host_out)
+
     def test_sync_logging(self):
         # Test that logging doesn't *break* things.
         r = self.webhost.request('GET', 'sync_logging')

tests/unittests/test_log_filtering_functions.py

@@ -0,0 +1,64 @@
+# Copyright (c) Microsoft Corporation. All rights reserved.
+# Licensed under the MIT License.
+
+import typing
+
+from azure_functions_worker import testutils
+from azure_functions_worker.testutils import TESTS_ROOT, remove_path
+
+HOST_JSON_TEMPLATE_WITH_LOGLEVEL_INFO = """\
+{
+    "version": "2.0",
+    "logging": {
+        "logLevel": {
+           "default": "Information"
+        }
+    },
+    "functionTimeout": "00:05:00"
+}
+"""
+
+
+class TestLogFilteringFunctions(testutils.WebHostTestCase):
+
+    @classmethod
+    def setUpClass(cls):
+        host_json = TESTS_ROOT / cls.get_script_dir() / 'host.json'
+
+        with open(host_json, 'w+') as f:
+            f.write(HOST_JSON_TEMPLATE_WITH_LOGLEVEL_INFO)
+
+        super(TestLogFilteringFunctions, cls).setUpClass()
+
+    @classmethod
+    def tearDownClass(cls):
+        host_json = TESTS_ROOT / cls.get_script_dir() / 'host.json'
+        remove_path(host_json)
+
+        super(TestLogFilteringFunctions, cls).tearDownClass()
+
+    @classmethod
+    def get_script_dir(cls):
+        return testutils.UNIT_TESTS_FOLDER / 'log_filtering_functions'
+
+    def test_debug_logging(self):
+        r = self.webhost.request('GET', 'debug_logging')
+        self.assertEqual(r.status_code, 200)
+        self.assertEqual(r.text, 'OK-debug')
+
+    def check_log_debug_logging(self, host_out: typing.List[str]):
+        self.assertIn('logging info', host_out)
+        self.assertIn('logging warning', host_out)
+        self.assertIn('logging error', host_out)
+        self.assertNotIn('logging debug', host_out)
+
+    def test_debug_with_user_logging(self):
+        r = self.webhost.request('GET', 'debug_user_logging')
+        self.assertEqual(r.status_code, 200)
+        self.assertEqual(r.text, 'OK-user-debug')
+
+    def check_log_debug_with_user_logging(self, host_out: typing.List[str]):
+        self.assertIn('logging info', host_out)
+        self.assertIn('logging warning', host_out)
+        self.assertIn('logging error', host_out)
+        self.assertNotIn('logging debug', host_out)