Enable debug logging using the PYTHON_ENABLE_DEBUG_LOGGING flag (#939)

peterstone2017 · wangbill1993 · web-flow · commit 191c9a0c2f97 · 2022-01-14T16:05:45.000-06:00
* Supporting customer enable debug logging flag from app settings

* Removing unused import

* Fixed flake8 styling issues

* Fix flaky enable debug log tests

* Fix enable debug logging test

* Address PR feedbacks(Add test case, Copyright, remove comments)

* Remove duplicate test app for enable debug logging testing

Co-authored-by: wangbill &lt;wangbill@microsoft.com&gt;
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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)
