From 4d84483a62f63f0323e2b1684a1d25af47fcf0c4 Mon Sep 17 00:00:00 2001 From: "Varad Meru [gmail]" Date: Wed, 23 Sep 2020 23:40:31 -0700 Subject: [PATCH 1/3] Adding support for debug logs in executed functions. --- .gitignore | 2 +- azure_functions_worker/dispatcher.py | 2 +- azure_functions_worker/main.py | 26 ++++++++++++------- azure_functions_worker/testutils.py | 7 ++++- .../debug_logging/function.json | 15 +++++++++++ .../http_functions/debug_logging/main.py | 13 ++++++++++ .../debug_user_logging/function.json | 15 +++++++++++ .../http_functions/debug_user_logging/main.py | 16 ++++++++++++ tests/unittests/test_http_functions.py | 22 ++++++++++++++++ 9 files changed, 106 insertions(+), 12 deletions(-) create mode 100644 tests/unittests/http_functions/debug_logging/function.json create mode 100644 tests/unittests/http_functions/debug_logging/main.py create mode 100644 tests/unittests/http_functions/debug_user_logging/function.json create mode 100644 tests/unittests/http_functions/debug_user_logging/main.py diff --git a/.gitignore b/.gitignore index a89043847..b999acb65 100644 --- a/.gitignore +++ b/.gitignore @@ -84,7 +84,7 @@ celerybeat-schedule # virtualenv (.venv/.venv36/.venv37/.venv38) .venv* -venv/ +venv*/ ENV/ py3env/ diff --git a/azure_functions_worker/dispatcher.py b/azure_functions_worker/dispatcher.py index b72c11db0..36f32c224 100644 --- a/azure_functions_worker/dispatcher.py +++ b/azure_functions_worker/dispatcher.py @@ -122,7 +122,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() diff --git a/azure_functions_worker/main.py b/azure_functions_worker/main.py index 2d5ad2f14..c7db801e5 100644 --- a/azure_functions_worker/main.py +++ b/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() diff --git a/azure_functions_worker/testutils.py b/azure_functions_worker/testutils.py index 536203767..9d3f549e3 100644 --- a/azure_functions_worker/testutils.py +++ b/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') diff --git a/tests/unittests/http_functions/debug_logging/function.json b/tests/unittests/http_functions/debug_logging/function.json new file mode 100644 index 000000000..5d4d8285f --- /dev/null +++ b/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" + } + ] +} diff --git a/tests/unittests/http_functions/debug_logging/main.py b/tests/unittests/http_functions/debug_logging/main.py new file mode 100644 index 000000000..be3e2d506 --- /dev/null +++ b/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' diff --git a/tests/unittests/http_functions/debug_user_logging/function.json b/tests/unittests/http_functions/debug_user_logging/function.json new file mode 100644 index 000000000..5d4d8285f --- /dev/null +++ b/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" + } + ] +} diff --git a/tests/unittests/http_functions/debug_user_logging/main.py b/tests/unittests/http_functions/debug_user_logging/main.py new file mode 100644 index 000000000..6cf0465af --- /dev/null +++ b/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' diff --git a/tests/unittests/test_http_functions.py b/tests/unittests/test_http_functions.py index 6b9a38905..733e3f8ae 100644 --- a/tests/unittests/test_http_functions.py +++ b/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') From a0f66c5945c4f0826f9c3596414a58ed621cd12f Mon Sep 17 00:00:00 2001 From: "Varad Meru [gmail]" Date: Thu, 24 Sep 2020 18:47:29 -0700 Subject: [PATCH 2/3] Adding tests to see make sure host prevents debug logs --- azure_functions_worker/testutils.py | 5 +- .../debug_logging/function.json | 15 +++++ .../debug_logging/main.py | 13 ++++ .../debug_user_logging/function.json | 15 +++++ .../debug_user_logging/main.py | 16 +++++ .../unittests/test_log_filtering_functions.py | 67 +++++++++++++++++++ 6 files changed, 129 insertions(+), 2 deletions(-) create mode 100644 tests/unittests/log_filtering_functions/debug_logging/function.json create mode 100644 tests/unittests/log_filtering_functions/debug_logging/main.py create mode 100644 tests/unittests/log_filtering_functions/debug_user_logging/function.json create mode 100644 tests/unittests/log_filtering_functions/debug_user_logging/main.py create mode 100644 tests/unittests/test_log_filtering_functions.py diff --git a/azure_functions_worker/testutils.py b/azure_functions_worker/testutils.py index 9d3f549e3..59c452a00 100644 --- a/azure_functions_worker/testutils.py +++ b/azure_functions_worker/testutils.py @@ -756,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) diff --git a/tests/unittests/log_filtering_functions/debug_logging/function.json b/tests/unittests/log_filtering_functions/debug_logging/function.json new file mode 100644 index 000000000..5d4d8285f --- /dev/null +++ b/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" + } + ] +} diff --git a/tests/unittests/log_filtering_functions/debug_logging/main.py b/tests/unittests/log_filtering_functions/debug_logging/main.py new file mode 100644 index 000000000..be3e2d506 --- /dev/null +++ b/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' diff --git a/tests/unittests/log_filtering_functions/debug_user_logging/function.json b/tests/unittests/log_filtering_functions/debug_user_logging/function.json new file mode 100644 index 000000000..5d4d8285f --- /dev/null +++ b/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" + } + ] +} diff --git a/tests/unittests/log_filtering_functions/debug_user_logging/main.py b/tests/unittests/log_filtering_functions/debug_user_logging/main.py new file mode 100644 index 000000000..6cf0465af --- /dev/null +++ b/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' diff --git a/tests/unittests/test_log_filtering_functions.py b/tests/unittests/test_log_filtering_functions.py new file mode 100644 index 000000000..a26b70440 --- /dev/null +++ b/tests/unittests/test_log_filtering_functions.py @@ -0,0 +1,67 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. +import hashlib +import pathlib +import filecmp +import typing +import os + +from azure_functions_worker import testutils +from azure_functions_worker.testutils import TESTS_ROOT, _remove_path + +HOST_JSON_TEMPLATE = """\ +{ + "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) + + 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) From 02185f18202f594bd962b6b1bcceb7890ab60848 Mon Sep 17 00:00:00 2001 From: "Varad Meru [gmail]" Date: Thu, 24 Sep 2020 23:17:38 -0700 Subject: [PATCH 3/3] minor; organizing imports and making a protected member as public --- azure_functions_worker/testutils.py | 6 +++--- tests/unittests/test_log_filtering_functions.py | 13 +++++-------- 2 files changed, 8 insertions(+), 11 deletions(-) diff --git a/azure_functions_worker/testutils.py b/azure_functions_worker/testutils.py index 59c452a00..870b3e0e4 100644 --- a/azure_functions_worker/testutils.py +++ b/azure_functions_worker/testutils.py @@ -733,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(): @@ -743,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)) @@ -770,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(): diff --git a/tests/unittests/test_log_filtering_functions.py b/tests/unittests/test_log_filtering_functions.py index a26b70440..a416f57e0 100644 --- a/tests/unittests/test_log_filtering_functions.py +++ b/tests/unittests/test_log_filtering_functions.py @@ -1,15 +1,12 @@ # Copyright (c) Microsoft Corporation. All rights reserved. # Licensed under the MIT License. -import hashlib -import pathlib -import filecmp + import typing -import os from azure_functions_worker import testutils -from azure_functions_worker.testutils import TESTS_ROOT, _remove_path +from azure_functions_worker.testutils import TESTS_ROOT, remove_path -HOST_JSON_TEMPLATE = """\ +HOST_JSON_TEMPLATE_WITH_LOGLEVEL_INFO = """\ { "version": "2.0", "logging": { @@ -29,14 +26,14 @@ 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) + 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) + remove_path(host_json) super(TestLogFilteringFunctions, cls).tearDownClass()