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 5dc5b3e30..f646c43c9 100644 --- a/azure_functions_worker/dispatcher.py +++ b/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() 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..870b3e0e4 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') @@ -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(): 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/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_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') diff --git a/tests/unittests/test_log_filtering_functions.py b/tests/unittests/test_log_filtering_functions.py new file mode 100644 index 000000000..a416f57e0 --- /dev/null +++ b/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)