Categorize SDK logs as system logs (#850)

* Add testing for cases

* Amend expected behavior

Author: Hazhzeng

azure_functions_worker/logging.py

@@ -9,6 +9,7 @@
 # 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)

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'

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"
+}

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'

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"
+}

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 @@
 
 
 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 @@ 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)
+        # 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 @@ 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)
+        # 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)

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(''))

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)