From a3c047bb0183f892aae9fef2c30178d5d68578bf Mon Sep 17 00:00:00 2001 From: Hanzhang Zeng <48038149+Hazhzeng@users.noreply.github.com> Date: Wed, 2 Jun 2021 10:22:27 -0700 Subject: [PATCH] Categorize SDK logs as system logs (#850) * Add testing for cases * Amend expected behavior --- azure_functions_worker/logging.py | 16 +++- .../sdk_logging/__init__.py | 16 ++++ .../sdk_logging/function.json | 16 ++++ .../sdk_submodule_logging/__init__.py | 16 ++++ .../sdk_submodule_logging/function.json | 16 ++++ .../unittests/test_log_filtering_functions.py | 47 +++++++++- tests/unittests/test_logging.py | 35 +++++++ .../test_mock_log_filtering_functions.py | 91 +++++++++++++++++++ 8 files changed, 249 insertions(+), 4 deletions(-) create mode 100644 tests/unittests/log_filtering_functions/sdk_logging/__init__.py create mode 100644 tests/unittests/log_filtering_functions/sdk_logging/function.json create mode 100644 tests/unittests/log_filtering_functions/sdk_submodule_logging/__init__.py create mode 100644 tests/unittests/log_filtering_functions/sdk_submodule_logging/function.json create mode 100644 tests/unittests/test_logging.py create mode 100644 tests/unittests/test_mock_log_filtering_functions.py diff --git a/azure_functions_worker/logging.py b/azure_functions_worker/logging.py index c37e3ae0..01a4373a 100644 --- a/azure_functions_worker/logging.py +++ b/azure_functions_worker/logging.py @@ -9,6 +9,7 @@ import sys # Logging Prefixes CONSOLE_LOG_PREFIX = "LanguageWorkerConsoleLog" SYSTEM_LOG_PREFIX = "azure_functions_worker" +SDK_LOG_PREFIX = "azure.functions" logger: logging.Logger = logging.getLogger('azure_functions_worker') @@ -76,6 +77,15 @@ def enable_console_logging() -> None: def is_system_log_category(ctg: str) -> bool: - # Category starts with 'azure_functions_worker' or - # 'azure_functions_worker_errors' will be treated as system logs - return ctg.lower().startswith(SYSTEM_LOG_PREFIX) + """Check if the logging namespace belongs to system logs. Category starts + with the following name will be treated as system logs. + 1. 'azure_functions_worker' (Worker Info) + 2. 'azure_functions_worker_errors' (Worker Error) + 3. 'azure.functions' (SDK) + + Expected behaviors for sytem logs and customer logs are listed below: + local_console customer_app_insight functions_kusto_table + system_log false false true + customer_log true true false + """ + return ctg.startswith(SYSTEM_LOG_PREFIX) or ctg.startswith(SDK_LOG_PREFIX) diff --git a/tests/unittests/log_filtering_functions/sdk_logging/__init__.py b/tests/unittests/log_filtering_functions/sdk_logging/__init__.py new file mode 100644 index 00000000..a30221e2 --- /dev/null +++ b/tests/unittests/log_filtering_functions/sdk_logging/__init__.py @@ -0,0 +1,16 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. +import logging + +import azure.functions as func + + +sdk_logger = logging.getLogger('azure.functions') + + +def main(req: func.HttpRequest): + sdk_logger.info('sdk_logger info') + sdk_logger.warning('sdk_logger warning') + sdk_logger.debug('sdk_logger debug') + sdk_logger.error('sdk_logger error', exc_info=True) + return 'OK-sdk-logger' diff --git a/tests/unittests/log_filtering_functions/sdk_logging/function.json b/tests/unittests/log_filtering_functions/sdk_logging/function.json new file mode 100644 index 00000000..9f7c2ae6 --- /dev/null +++ b/tests/unittests/log_filtering_functions/sdk_logging/function.json @@ -0,0 +1,16 @@ +{ + "scriptFile": "__init__.py", + "bindings": [ + { + "type": "httpTrigger", + "direction": "in", + "name": "req" + }, + { + "type": "http", + "direction": "out", + "name": "$return" + } + ], + "entryPoint": "main" +} diff --git a/tests/unittests/log_filtering_functions/sdk_submodule_logging/__init__.py b/tests/unittests/log_filtering_functions/sdk_submodule_logging/__init__.py new file mode 100644 index 00000000..acdef9e1 --- /dev/null +++ b/tests/unittests/log_filtering_functions/sdk_submodule_logging/__init__.py @@ -0,0 +1,16 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. +import logging + +import azure.functions as func + + +sdk_submodule_logger = logging.getLogger('azure.functions.submodule') + + +def main(req: func.HttpRequest): + sdk_submodule_logger.info('sdk_submodule_logger info') + sdk_submodule_logger.warning('sdk_submodule_logger warning') + sdk_submodule_logger.debug('sdk_submodule_logger debug') + sdk_submodule_logger.error('sdk_submodule_logger error', exc_info=True) + return 'OK-sdk-submodule-logging' diff --git a/tests/unittests/log_filtering_functions/sdk_submodule_logging/function.json b/tests/unittests/log_filtering_functions/sdk_submodule_logging/function.json new file mode 100644 index 00000000..9f7c2ae6 --- /dev/null +++ b/tests/unittests/log_filtering_functions/sdk_submodule_logging/function.json @@ -0,0 +1,16 @@ +{ + "scriptFile": "__init__.py", + "bindings": [ + { + "type": "httpTrigger", + "direction": "in", + "name": "req" + }, + { + "type": "http", + "direction": "out", + "name": "$return" + } + ], + "entryPoint": "main" +} diff --git a/tests/unittests/test_log_filtering_functions.py b/tests/unittests/test_log_filtering_functions.py index a416f57e..cd1ae561 100644 --- a/tests/unittests/test_log_filtering_functions.py +++ b/tests/unittests/test_log_filtering_functions.py @@ -1,6 +1,5 @@ # Copyright (c) Microsoft Corporation. All rights reserved. # Licensed under the MIT License. - import typing from azure_functions_worker import testutils @@ -20,6 +19,15 @@ HOST_JSON_TEMPLATE_WITH_LOGLEVEL_INFO = """\ class TestLogFilteringFunctions(testutils.WebHostTestCase): + """This class is for testing the logger behavior in Python Worker when + dealing with customer's log and system's log. Here's a list of expected + behaviors: + local_console customer_app_insight functions_kusto_table + system_log false false true + customer_log true true false + + Please ensure the following unit test cases align with the expectations + """ @classmethod def setUpClass(cls): @@ -50,6 +58,7 @@ class TestLogFilteringFunctions(testutils.WebHostTestCase): self.assertIn('logging info', host_out) self.assertIn('logging warning', host_out) self.assertIn('logging error', host_out) + # See HOST_JSON_TEMPLATE_WITH_LOGLEVEL_INFO, debug log is disabled self.assertNotIn('logging debug', host_out) def test_debug_with_user_logging(self): @@ -61,4 +70,40 @@ class TestLogFilteringFunctions(testutils.WebHostTestCase): self.assertIn('logging info', host_out) self.assertIn('logging warning', host_out) self.assertIn('logging error', host_out) + # See HOST_JSON_TEMPLATE_WITH_LOGLEVEL_INFO, debug log is disabled self.assertNotIn('logging debug', host_out) + + def test_info_with_sdk_logging(self): + """Invoke a HttpTrigger sdk_logging which contains logging invocation + via the azure.functions logger. This should be treated as system logs, + which means the log should not be displayed in local console. + """ + r = self.webhost.request('GET', 'sdk_logging') + self.assertEqual(r.status_code, 200) + self.assertEqual(r.text, 'OK-sdk-logger') + + def check_log_info_with_sdk_logging(self, host_out: typing.List[str]): + # See TestLogFilteringFunctions docstring + # System log should not be captured in console + self.assertNotIn('sdk_logger info', host_out) + self.assertNotIn('sdk_logger warning', host_out) + self.assertNotIn('sdk_logger error', host_out) + self.assertNotIn('sdk_logger debug', host_out) + + def test_info_with_sdk_submodule_logging(self): + """Invoke a HttpTrigger sdk_submodule_logging which contains logging + invocation via the azure.functions logger. This should be treated as + system logs. + """ + r = self.webhost.request('GET', 'sdk_submodule_logging') + self.assertEqual(r.status_code, 200) + self.assertEqual(r.text, 'OK-sdk-submodule-logging') + + def check_log_info_with_sdk_submodule_logging(self, + host_out: typing.List[str]): + # See TestLogFilteringFunctions docstring + # System log should not be captured in console + self.assertNotIn('sdk_submodule_logger info', host_out) + self.assertNotIn('sdk_submodule_logger warning', host_out) + self.assertNotIn('sdk_submodule_logger error', host_out) + self.assertNotIn('sdk_submodule_logger debug', host_out) diff --git a/tests/unittests/test_logging.py b/tests/unittests/test_logging.py new file mode 100644 index 00000000..3d3465c6 --- /dev/null +++ b/tests/unittests/test_logging.py @@ -0,0 +1,35 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. +import unittest + +from azure_functions_worker import logging as flog + + +class TestLogging(unittest.TestCase): + """This class is for testing the grpc logging behavior in Python Worker. + Here's a list of expected behaviors: + local_console customer_app_insight functions_kusto_table + system_log false false true + customer_log true true false + + Please ensure the following unit test cases align with the expectations + """ + + def test_system_log_namespace(self): + """Ensure the following list is part of the system's log + """ + self.assertTrue(flog.is_system_log_category('azure_functions_worker')) + self.assertTrue( + flog.is_system_log_category('azure_functions_worker_error') + ) + self.assertTrue(flog.is_system_log_category('azure.functions')) + self.assertTrue(flog.is_system_log_category('azure.functions.module')) + + def test_customer_log_namespace(self): + """Ensure the following list is part of the customer's log + """ + self.assertFalse(flog.is_system_log_category('customer_logger')) + self.assertFalse(flog.is_system_log_category('azure')) + self.assertFalse(flog.is_system_log_category('protobuf')) + self.assertFalse(flog.is_system_log_category('root')) + self.assertFalse(flog.is_system_log_category('')) diff --git a/tests/unittests/test_mock_log_filtering_functions.py b/tests/unittests/test_mock_log_filtering_functions.py new file mode 100644 index 00000000..800d4f70 --- /dev/null +++ b/tests/unittests/test_mock_log_filtering_functions.py @@ -0,0 +1,91 @@ +# Copyright (c) Microsoft Corporation. All rights reserved. +# Licensed under the MIT License. +from unittest.mock import patch, call + +from azure_functions_worker import testutils, protos +from azure_functions_worker.logging import is_system_log_category + + +class TestMockLogFilteringFunctions(testutils.AsyncTestCase): + dir = testutils.UNIT_TESTS_FOLDER / 'log_filtering_functions' + + async def test_root_logger_should_be_customer_log(self): + """When customer use the root logger to send logs, the 'root' namespace + should be treated as customer log, only sending to our customers. + """ + with patch( + 'azure_functions_worker.dispatcher.is_system_log_category' + ) as islc_mock: + async with testutils.start_mockhost(script_root=self.dir) as host: + await host.load_function('debug_logging') + await self._invoke_function(host, 'debug_logging') + + self.assertIn(call('root'), islc_mock.call_args_list) + self.assertFalse(is_system_log_category('root')) + + async def test_customer_logging_should_not_be_system_log(self): + """When sdk uses the 'azure' logger to send logs + (e.g. 'azure.servicebus'), the namespace should be treated as customer + log, only sends to our customers. + """ + with patch( + 'azure_functions_worker.dispatcher.is_system_log_category' + ) as islc_mock: + async with testutils.start_mockhost(script_root=self.dir) as host: + await host.load_function('debug_user_logging') + await self._invoke_function(host, 'debug_user_logging') + + self.assertIn(call('my function'), islc_mock.call_args_list) + self.assertFalse(is_system_log_category('my function')) + + async def test_sdk_logger_should_be_system_log(self): + """When sdk uses the 'azure.functions' logger to send logs, the + namespace should be treated as system log, sending to our customers and + our kusto table. + """ + with patch( + 'azure_functions_worker.dispatcher.is_system_log_category' + ) as islc_mock: + async with testutils.start_mockhost(script_root=self.dir) as host: + await host.load_function('sdk_logging') + await self._invoke_function(host, 'sdk_logging') + + self.assertIn( + call('azure.functions'), islc_mock.call_args_list + ) + self.assertTrue(is_system_log_category('azure.functions')) + + async def test_sdk_submodule_logger_should_be_system_log(self): + """When sdk uses the 'azure.functions.submodule' logger to send logs, + the namespace should be treated as system log, sending to our customers + and our kusto table. + """ + with patch( + 'azure_functions_worker.dispatcher.is_system_log_category' + ) as islc_mock: + async with testutils.start_mockhost(script_root=self.dir) as host: + await host.load_function('sdk_submodule_logging') + await self._invoke_function(host, 'sdk_submodule_logging') + + self.assertIn( + call('azure.functions.submodule'), islc_mock.call_args_list + ) + self.assertTrue( + is_system_log_category('azure.functions.submodule') + ) + + async def _invoke_function(self, + host: testutils._MockWebHost, + function_name: str): + _, r = await host.invoke_function( + function_name, [ + protos.ParameterBinding( + name='req', + data=protos.TypedData( + http=protos.RpcHttp(method='GET') + ) + ) + ] + ) + + self.assertEqual(r.response.result.status, protos.StatusResult.Success)