Ensure configured logger severity is respected (#35749)

homeassistant/components/logger/__init__.py

@@ -1,6 +1,6 @@
 """Support for setting the level of logging for components."""
-from collections import OrderedDict
 import logging
+import re
 
 import voluptuous as vol
 
@@ -50,33 +50,54 @@ CONFIG_SCHEMA = vol.Schema(
 class HomeAssistantLogFilter(logging.Filter):
     """A log filter."""
 
-    def __init__(self, logfilter):
+    def __init__(self):
         """Initialize the filter."""
         super().__init__()
 
-        self.logfilter = logfilter
+        self._default = None
+        self._logs = None
+        self._log_rx = None
+
+    def update_default_level(self, default_level):
+        """Update the default logger level."""
+        self._default = default_level
+
+    def update_log_filter(self, logs):
+        """Rebuild the internal filter from new config."""
+        #
+        # A precompiled regex is used to avoid
+        # the overhead of a list transversal
+        #
+        # Sort to make sure the longer
+        # names are always matched first
+        # so they take precedence of the shorter names
+        # to allow for more granular settings.
+        #
+        names_by_len = sorted(list(logs), key=len, reverse=True)
+        self._log_rx = re.compile("".join(["^(?:", "|".join(names_by_len), ")"]))
+        self._logs = logs
 
     def filter(self, record):
         """Filter the log entries."""
         # Log with filtered severity
-        if LOGGER_LOGS in self.logfilter:
+        if self._log_rx:
-            for filtername in self.logfilter[LOGGER_LOGS]:
+            match = self._log_rx.match(record.name)
-                logseverity = self.logfilter[LOGGER_LOGS][filtername]
+            if match:
-                if record.name.startswith(filtername):
+                return record.levelno >= self._logs[match.group(0)]
-                    return record.levelno >= logseverity
 
         # Log with default severity
-        default = self.logfilter[LOGGER_DEFAULT]
+        return record.levelno >= self._default
-        return record.levelno >= default
 
 
 async def async_setup(hass, config):
     """Set up the logger component."""
     logfilter = {}
+    hass_filter = HomeAssistantLogFilter()
 
     def set_default_log_level(level):
         """Set the default log level for components."""
         logfilter[LOGGER_DEFAULT] = LOGSEVERITY[level]
+        hass_filter.update_default_level(LOGSEVERITY[level])
 
     def set_log_levels(logpoints):
         """Set the specified log levels."""
@@ -90,9 +111,9 @@ async def async_setup(hass, config):
         for key, value in logpoints.items():
             logs[key] = LOGSEVERITY[value]
 
-        logfilter[LOGGER_LOGS] = OrderedDict(
+        logfilter[LOGGER_LOGS] = logs
-            sorted(logs.items(), key=lambda t: len(t[0]), reverse=True)
+
-        )
+        hass_filter.update_log_filter(logs)
 
     # Set default log severity
     if LOGGER_DEFAULT in config.get(DOMAIN):
@@ -106,7 +127,7 @@ async def async_setup(hass, config):
     # Set log filter for all log handler
     for handler in logging.root.handlers:
         handler.setLevel(logging.NOTSET)
-        handler.addFilter(HomeAssistantLogFilter(logfilter))
+        handler.addFilter(hass_filter)
 
     if LOGGER_LOGS in config.get(DOMAIN):
         set_log_levels(config.get(DOMAIN)[LOGGER_LOGS])

tests/components/logger/test_init.py

@@ -1,123 +1,120 @@
 """The tests for the Logger component."""
 from collections import namedtuple
 import logging
-import unittest
 
 from homeassistant.components import logger
-from homeassistant.setup import setup_component
+from homeassistant.setup import async_setup_component
-
-from tests.common import get_test_home_assistant
 
 RECORD = namedtuple("record", ("name", "levelno"))
 
 NO_DEFAULT_CONFIG = {"logger": {}}
 NO_LOGS_CONFIG = {"logger": {"default": "info"}}
-TEST_CONFIG = {"logger": {"default": "warning", "logs": {"test": "info"}}}
+TEST_CONFIG = {
+    "logger": {
+        "default": "warning",
+        "logs": {"test": "info", "test.child": "debug", "test.child.child": "warning"},
+    }
+}
 
 
-class TestUpdater(unittest.TestCase):
+async def async_setup_logger(hass, config):
-    """Test logger component."""
+    """Set up logger and save log filter."""
+    await async_setup_component(hass, logger.DOMAIN, config)
+    return logging.root.handlers[-1].filters[0]
 
-    def setUp(self):
-        """Set up things to be run when tests are started."""
-        self.hass = get_test_home_assistant()
-        self.log_filter = None
 
-    def tearDown(self):
+async def test_logger_setup(hass):
-        """Stop everything that was started."""
+    """Use logger to create a logging filter."""
-        del logging.root.handlers[-1]
+    await async_setup_logger(hass, TEST_CONFIG)
-        self.hass.stop()
 
-    def setup_logger(self, config):
+    assert len(logging.root.handlers) > 0
-        """Set up logger and save log filter."""
+    handler = logging.root.handlers[-1]
-        setup_component(self.hass, logger.DOMAIN, config)
-        self.log_filter = logging.root.handlers[-1].filters[0]
 
-    def assert_logged(self, name, level):
+    assert len(handler.filters) == 1
-        """Assert that a certain record was logged."""
-        assert self.log_filter.filter(RECORD(name, level))
 
-    def assert_not_logged(self, name, level):
-        """Assert that a certain record was not logged."""
-        assert not self.log_filter.filter(RECORD(name, level))
 
-    def test_logger_setup(self):
+async def test_logger_test_filters(hass):
-        """Use logger to create a logging filter."""
+    """Test resulting filter operation."""
-        self.setup_logger(TEST_CONFIG)
+    log_filter = await async_setup_logger(hass, TEST_CONFIG)
 
-        assert len(logging.root.handlers) > 0
+    # Blocked default record
-        handler = logging.root.handlers[-1]
+    assert not log_filter.filter(RECORD("asdf", logging.DEBUG))
 
-        assert len(handler.filters) == 1
+    # Allowed default record
-        log_filter = handler.filters[0].logfilter
+    assert log_filter.filter(RECORD("asdf", logging.WARNING))
 
-        assert log_filter["default"] == logging.WARNING
+    # Blocked named record
-        assert log_filter["logs"]["test"] == logging.INFO
+    assert not log_filter.filter(RECORD("test", logging.DEBUG))
 
-    def test_logger_test_filters(self):
+    # Allowed named record
-        """Test resulting filter operation."""
+    assert log_filter.filter(RECORD("test", logging.INFO))
-        self.setup_logger(TEST_CONFIG)
 
-        # Blocked default record
+    # Allowed named record child
-        self.assert_not_logged("asdf", logging.DEBUG)
+    assert log_filter.filter(RECORD("test.child", logging.INFO))
 
-        # Allowed default record
+    # Allowed named record child
-        self.assert_logged("asdf", logging.WARNING)
+    assert log_filter.filter(RECORD("test.child", logging.DEBUG))
 
-        # Blocked named record
+    # Blocked named record child of child
-        self.assert_not_logged("test", logging.DEBUG)
+    assert not log_filter.filter(RECORD("test.child.child", logging.DEBUG))
 
-        # Allowed named record
+    # Allowed named record child of child
-        self.assert_logged("test", logging.INFO)
+    assert log_filter.filter(RECORD("test.child.child", logging.WARNING))
 
-    def test_set_filter_empty_config(self):
-        """Test change log level from empty configuration."""
-        self.setup_logger(NO_LOGS_CONFIG)
 
-        self.assert_not_logged("test", logging.DEBUG)
+async def test_set_filter_empty_config(hass):
+    """Test change log level from empty configuration."""
+    log_filter = await async_setup_logger(hass, NO_LOGS_CONFIG)
 
-        self.hass.services.call(logger.DOMAIN, "set_level", {"test": "debug"})
+    assert not log_filter.filter(RECORD("test", logging.DEBUG))
-        self.hass.block_till_done()
 
-        self.assert_logged("test", logging.DEBUG)
+    await hass.services.async_call(logger.DOMAIN, "set_level", {"test": "debug"})
+    await hass.async_block_till_done()
 
-    def test_set_filter(self):
+    assert log_filter.filter(RECORD("test", logging.DEBUG))
-        """Test change log level of existing filter."""
-        self.setup_logger(TEST_CONFIG)
 
-        self.assert_not_logged("asdf", logging.DEBUG)
-        self.assert_logged("dummy", logging.WARNING)
 
-        self.hass.services.call(
+async def test_set_filter(hass):
-            logger.DOMAIN, "set_level", {"asdf": "debug", "dummy": "info"}
+    """Test change log level of existing filter."""
-        )
+    log_filter = await async_setup_logger(hass, TEST_CONFIG)
-        self.hass.block_till_done()
 
-        self.assert_logged("asdf", logging.DEBUG)
+    assert not log_filter.filter(RECORD("asdf", logging.DEBUG))
-        self.assert_logged("dummy", logging.WARNING)
+    assert log_filter.filter(RECORD("dummy", logging.WARNING))
 
-    def test_set_default_filter_empty_config(self):
+    await hass.services.async_call(
-        """Test change default log level from empty configuration."""
+        logger.DOMAIN, "set_level", {"asdf": "debug", "dummy": "info"}
-        self.setup_logger(NO_DEFAULT_CONFIG)
+    )
+    await hass.async_block_till_done()
 
-        self.assert_logged("test", logging.DEBUG)
+    assert log_filter.filter(RECORD("asdf", logging.DEBUG))
+    assert log_filter.filter(RECORD("dummy", logging.WARNING))
 
-        self.hass.services.call(
-            logger.DOMAIN, "set_default_level", {"level": "warning"}
-        )
-        self.hass.block_till_done()
 
-        self.assert_not_logged("test", logging.DEBUG)
+async def test_set_default_filter_empty_config(hass):
+    """Test change default log level from empty configuration."""
+    log_filter = await async_setup_logger(hass, NO_DEFAULT_CONFIG)
 
-    def test_set_default_filter(self):
+    assert log_filter.filter(RECORD("test", logging.DEBUG))
-        """Test change default log level with existing default."""
-        self.setup_logger(TEST_CONFIG)
 
-        self.assert_not_logged("asdf", logging.DEBUG)
+    await hass.services.async_call(
-        self.assert_logged("dummy", logging.WARNING)
+        logger.DOMAIN, "set_default_level", {"level": "warning"}
+    )
+    await hass.async_block_till_done()
 
-        self.hass.services.call(logger.DOMAIN, "set_default_level", {"level": "debug"})
+    assert not log_filter.filter(RECORD("test", logging.DEBUG))
-        self.hass.block_till_done()
 
-        self.assert_logged("asdf", logging.DEBUG)
+
-        self.assert_logged("dummy", logging.WARNING)
+async def test_set_default_filter(hass):
+    """Test change default log level with existing default."""
+    log_filter = await async_setup_logger(hass, TEST_CONFIG)
+
+    assert not log_filter.filter(RECORD("asdf", logging.DEBUG))
+    assert log_filter.filter(RECORD("dummy", logging.WARNING))
+
+    await hass.services.async_call(
+        logger.DOMAIN, "set_default_level", {"level": "debug"}
+    )
+    await hass.async_block_till_done()
+
+    assert log_filter.filter(RECORD("asdf", logging.DEBUG))
+    assert log_filter.filter(RECORD("dummy", logging.WARNING))