diff --git a/CODEOWNERS b/CODEOWNERS index e1ccc731b..fe8c2faeb 100644 --- a/CODEOWNERS +++ b/CODEOWNERS @@ -10,4 +10,4 @@ # For all file changes, github would automatically # include the following people in the PRs. -* @vrdmr @gavin-aguiar +* @vrdmr @gavin-aguiar @YunchuWang diff --git a/azure_functions_worker/constants.py b/azure_functions_worker/constants.py index e1147492a..53e4a7805 100644 --- a/azure_functions_worker/constants.py +++ b/azure_functions_worker/constants.py @@ -28,6 +28,7 @@ PYTHON_THREADPOOL_THREAD_COUNT = "PYTHON_THREADPOOL_THREAD_COUNT" PYTHON_ISOLATE_WORKER_DEPENDENCIES = "PYTHON_ISOLATE_WORKER_DEPENDENCIES" PYTHON_ENABLE_WORKER_EXTENSIONS = "PYTHON_ENABLE_WORKER_EXTENSIONS" +PYTHON_ENABLE_DEBUG_LOGGING = "PYTHON_ENABLE_DEBUG_LOGGING" FUNCTIONS_WORKER_SHARED_MEMORY_DATA_TRANSFER_ENABLED = \ "FUNCTIONS_WORKER_SHARED_MEMORY_DATA_TRANSFER_ENABLED" """ diff --git a/azure_functions_worker/dispatcher.py b/azure_functions_worker/dispatcher.py index 322abc60f..e230a289d 100644 --- a/azure_functions_worker/dispatcher.py +++ b/azure_functions_worker/dispatcher.py @@ -27,12 +27,13 @@ from .constants import (PYTHON_THREADPOOL_THREAD_COUNT, PYTHON_THREADPOOL_THREAD_COUNT_DEFAULT, PYTHON_THREADPOOL_THREAD_COUNT_MAX_37, - PYTHON_THREADPOOL_THREAD_COUNT_MIN) + PYTHON_THREADPOOL_THREAD_COUNT_MIN, + PYTHON_ENABLE_DEBUG_LOGGING) from .logging import disable_console_logging, enable_console_logging from .logging import (logger, error_logger, is_system_log_category, CONSOLE_LOG_PREFIX) from .extension import ExtensionManager -from .utils.common import get_app_setting +from .utils.common import get_app_setting, is_envvar_true from .utils.tracing import marshall_exception_trace from .utils.dependency import DependencyManager from .utils.wrappers import disable_feature_by @@ -145,8 +146,9 @@ async def dispatch_forever(self): logging_handler = AsyncLoggingHandler() root_logger = logging.getLogger() - # Don't change this unless you read #780 and #745 - root_logger.setLevel(logging.INFO) + log_level = logging.INFO if not is_envvar_true( + PYTHON_ENABLE_DEBUG_LOGGING) else logging.DEBUG + root_logger.setLevel(log_level) root_logger.addHandler(logging_handler) logger.info('Switched to gRPC logging.') logging_handler.flush() @@ -484,6 +486,10 @@ async def _handle__function_environment_reload_request(self, req): self._create_sync_call_tp(self._get_sync_tp_max_workers()) ) + if is_envvar_true(PYTHON_ENABLE_DEBUG_LOGGING): + root_logger = logging.getLogger() + root_logger.setLevel(logging.DEBUG) + # Reload azure google namespaces DependencyManager.reload_customer_libraries( func_env_reload_request.function_app_directory diff --git a/azure_functions_worker/main.py b/azure_functions_worker/main.py index 78f8b7f58..3a7e44417 100644 --- a/azure_functions_worker/main.py +++ b/azure_functions_worker/main.py @@ -12,12 +12,11 @@ def parse_args(): parser.add_argument('--host', help="host address") parser.add_argument('--port', type=int, - help='id for the requests') + help='port number') 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') + help='id of the request') parser.add_argument('--log-level', type=str, default='INFO', choices=['TRACE', 'INFO', 'WARNING', 'ERROR'], help="log level: 'TRACE', 'INFO', 'WARNING', " diff --git a/tests/endtoend/test_linux_consumption.py b/tests/endtoend/test_linux_consumption.py index f7202400a..df55ad0ac 100644 --- a/tests/endtoend/test_linux_consumption.py +++ b/tests/endtoend/test_linux_consumption.py @@ -1,4 +1,6 @@ -from unittest import TestCase, skip +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. +from unittest import TestCase import os import sys @@ -9,7 +11,6 @@ ) -@skip('Flaky test and needs stabilization') class TestLinuxConsumption(TestCase): """Test worker behaviors on specific scenarios. @@ -134,6 +135,59 @@ def test_old_protobuf(self): self.assertIn('grpc', content) self.assertEqual(resp.status_code, 200) + def test_debug_logging_disabled(self): + """An HttpTrigger function app with 'azure-functions' library + should return 200 and by default customer debug logging should be + disabled. + """ + with LinuxConsumptionWebHostController("3", self._py_version) as ctrl: + ctrl.assign_container(env={ + "AzureWebJobsStorage": self._storage, + "SCM_RUN_FROM_PACKAGE": self._get_blob_url("EnableDebugLogging") + }) + req = Request('GET', f'{ctrl.url}/api/HttpTrigger1') + resp = ctrl.send_request(req) + + self.assertEqual(resp.status_code, 200) + container_log = ctrl.get_container_logs() + func_start_idx = container_log.find( + "Executing 'Functions.HttpTrigger1'") + self.assertTrue(func_start_idx > -1, + "HttpTrigger function is not executed.") + func_log = container_log[func_start_idx:] + + self.assertIn('logging info', func_log) + self.assertIn('logging warning', func_log) + self.assertIn('logging error', func_log) + self.assertNotIn('logging debug', func_log) + + def test_debug_logging_enabled(self): + """An HttpTrigger function app with 'azure-functions' library + should return 200 and with customer debug logging enabled, debug logs + should be written to container logs. + """ + with LinuxConsumptionWebHostController("3", self._py_version) as ctrl: + ctrl.assign_container(env={ + "AzureWebJobsStorage": self._storage, + "SCM_RUN_FROM_PACKAGE": self._get_blob_url( + "EnableDebugLogging"), + "PYTHON_ENABLE_DEBUG_LOGGING": "1" + }) + req = Request('GET', f'{ctrl.url}/api/HttpTrigger1') + resp = ctrl.send_request(req) + + self.assertEqual(resp.status_code, 200) + container_log = ctrl.get_container_logs() + func_start_idx = container_log.find( + "Executing 'Functions.HttpTrigger1'") + self.assertTrue(func_start_idx > -1) + func_log = container_log[func_start_idx:] + + self.assertIn('logging info', func_log) + self.assertIn('logging warning', func_log) + self.assertIn('logging error', func_log) + self.assertIn('logging debug', func_log) + def _get_blob_url(self, scenario_name: str) -> str: return ( f'https://pythonworker{self._py_shortform}sa.blob.core.windows.net/' diff --git a/tests/unittests/http_functions/debug_user_logging/main.py b/tests/unittests/http_functions/debug_user_logging/main.py index fc0b6d342..38d99d8cc 100644 --- a/tests/unittests/http_functions/debug_user_logging/main.py +++ b/tests/unittests/http_functions/debug_user_logging/main.py @@ -4,8 +4,8 @@ import azure.functions - logger = logging.getLogger('my function') +logger.setLevel(logging.DEBUG) def main(req: azure.functions.HttpRequest): diff --git a/tests/unittests/test_enable_debug_logging_functions.py b/tests/unittests/test_enable_debug_logging_functions.py new file mode 100644 index 000000000..6dedde52b --- /dev/null +++ b/tests/unittests/test_enable_debug_logging_functions.py @@ -0,0 +1,119 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. +import typing +import os +from unittest.mock import patch + +from azure_functions_worker import testutils +from azure_functions_worker.constants import PYTHON_ENABLE_DEBUG_LOGGING +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 TestDebugLoggingEnabledFunctions(testutils.WebHostTestCase): + @classmethod + def setUpClass(cls): + os_environ = os.environ.copy() + os_environ[PYTHON_ENABLE_DEBUG_LOGGING] = '1' + cls._patch_environ = patch.dict('os.environ', os_environ) + cls._patch_environ.start() + super().setUpClass() + + @classmethod + def tearDownClass(self): + super().tearDownClass() + self._patch_environ.stop() + + @classmethod + def get_script_dir(cls): + return testutils.UNIT_TESTS_FOLDER / 'log_filtering_functions' + + def test_debug_logging_enabled(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_enabled(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) + + +class TestDebugLoggingDisabledFunctions(testutils.WebHostTestCase): + @classmethod + def setUpClass(cls): + os_environ = os.environ.copy() + os_environ[PYTHON_ENABLE_DEBUG_LOGGING] = '0' + cls._patch_environ = patch.dict('os.environ', os_environ) + cls._patch_environ.start() + super().setUpClass() + + @classmethod + def tearDownClass(self): + super().tearDownClass() + self._patch_environ.stop() + + @classmethod + def get_script_dir(cls): + return testutils.UNIT_TESTS_FOLDER / 'log_filtering_functions' + + def test_debug_logging_disabled(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_disabled(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) + + +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) + + os_environ = os.environ.copy() + os_environ[PYTHON_ENABLE_DEBUG_LOGGING] = '1' + cls._patch_environ = patch.dict('os.environ', os_environ) + cls._patch_environ.start() + super().setUpClass() + + @classmethod + def tearDownClass(self): + host_json = TESTS_ROOT / self.get_script_dir() / 'host.json' + remove_path(host_json) + + super().tearDownClass() + self._patch_environ.stop() + + @classmethod + def get_script_dir(cls): + return testutils.UNIT_TESTS_FOLDER / 'log_filtering_functions' + + def test_debug_logging_filtered(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_filtered(self, host_out: typing.List[str]): + self.assertIn('logging info', host_out) + self.assertIn('logging warning', host_out) + self.assertNotIn('logging debug', host_out) + self.assertIn('logging error', host_out) diff --git a/tests/unittests/test_http_functions.py b/tests/unittests/test_http_functions.py index 9edb12a3e..2e65a3108 100644 --- a/tests/unittests/test_http_functions.py +++ b/tests/unittests/test_http_functions.py @@ -5,7 +5,6 @@ import filecmp import typing import os -import unittest import pytest from azure_functions_worker import testutils @@ -98,34 +97,22 @@ def check_log_async_logging(self, host_out: typing.List[str]): self.assertIn('hello info', host_out) self.assertIn('and another error', host_out) - @unittest.skip("Reverting the debug logs PR as host currently cannot handle" - "apps with lot of debug statements. Reverting PR: " - "azure-functions-python-worker/pull/745") def test_debug_logging(self): r = self.webhost.request('GET', 'debug_logging') self.assertEqual(r.status_code, 200) self.assertEqual(r.text, 'OK-debug') - @unittest.skip("Reverting the debug logs PR as host currently cannot handle" - "apps with lot of debug statements. Reverting PR: " - "azure-functions-python-worker/pull/745") 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) + self.assertNotIn('logging debug', host_out) - @unittest.skip("Reverting the debug logs PR as host currently cannot handle" - "apps with lot of debug statements. Reverting PR: " - "azure-functions-python-worker/pull/745") 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') - @unittest.skip("Reverting the debug logs PR as host currently cannot handle" - "apps with lot of debug statements. Reverting PR: " - "azure-functions-python-worker/pull/745") 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)