Simplify logger integration (#37780)

Co-authored-by: J. Nick Koston <nick@koston.org>
This commit is contained in:
Paulus Schoutsen 2020-07-13 10:20:18 -07:00 committed by GitHub
parent 8ed1a29c82
commit 9ac1475251
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
8 changed files with 233 additions and 245 deletions

View file

@ -127,9 +127,6 @@ async def async_setup(hass, config):
netdisco = NetworkDiscovery()
already_discovered = set()
# Disable zeroconf logging, it spams
logging.getLogger("zeroconf").setLevel(logging.CRITICAL)
if DOMAIN in config:
# Platforms ignore by config
ignored_platforms = config[DOMAIN][CONF_IGNORE]

View file

@ -17,10 +17,6 @@ import homeassistant.helpers.config_validation as cv
_LOGGER = logging.getLogger(__name__)
_GNTP_LOGGER = logging.getLogger("gntp")
_GNTP_LOGGER.setLevel(logging.ERROR)
CONF_APP_NAME = "app_name"
CONF_APP_ICON = "app_icon"
CONF_HOSTNAME = "hostname"
@ -42,6 +38,8 @@ PLATFORM_SCHEMA = PLATFORM_SCHEMA.extend(
def get_service(hass, config, discovery_info=None):
"""Get the GNTP notification service."""
logging.getLogger("gntp").setLevel(logging.ERROR)
if config.get(CONF_APP_ICON) is None:
icon_file = os.path.join(
os.path.dirname(__file__),

View file

@ -82,10 +82,6 @@ from .const import (
_LOGGER = logging.getLogger(__name__)
# dicttoxml (used by huawei-lte-api) has uselessly verbose INFO level.
# https://github.com/quandyfactory/dicttoxml/issues/60
logging.getLogger("dicttoxml").setLevel(logging.WARNING)
SCAN_INTERVAL = timedelta(seconds=10)
NOTIFY_SCHEMA = vol.Any(
@ -460,6 +456,10 @@ async def async_unload_entry(
async def async_setup(hass: HomeAssistantType, config) -> bool:
"""Set up Huawei LTE component."""
# dicttoxml (used by huawei-lte-api) has uselessly verbose INFO level.
# https://github.com/quandyfactory/dicttoxml/issues/60
logging.getLogger("dicttoxml").setLevel(logging.WARNING)
# Arrange our YAML config to dict with normalized URLs as keys
domain_config = {}
if DOMAIN not in hass.data:

View file

@ -291,18 +291,13 @@ def async_register_services(hass):
def print_aldb_to_log(aldb):
"""Print the All-Link Database to the log file."""
# This service is useless if the log level is not INFO for the
# insteon component. Setting the log level to INFO and resetting it
# back when we are done
orig_log_level = _LOGGER.level
if orig_log_level > logging.INFO:
_LOGGER.setLevel(logging.INFO)
_LOGGER.info("%s ALDB load status is %s", aldb.address, aldb.status.name)
logger = logging.getLogger(f"{__name__}.links")
logger.info("%s ALDB load status is %s", aldb.address, aldb.status.name)
if aldb.status not in [ALDBStatus.LOADED, ALDBStatus.PARTIAL]:
_LOGGER.warning("All-Link database not loaded")
_LOGGER.info("RecID In Use Mode HWM Group Address Data 1 Data 2 Data 3")
_LOGGER.info("----- ------ ---- --- ----- -------- ------ ------ ------")
logger.info("RecID In Use Mode HWM Group Address Data 1 Data 2 Data 3")
logger.info("----- ------ ---- --- ----- -------- ------ ------ ------")
for mem_addr in aldb:
rec = aldb[mem_addr]
# For now we write this to the log
@ -315,8 +310,7 @@ def print_aldb_to_log(aldb):
f"{rec.group:3d} {str(rec.target):s} {rec.data1:3d} "
f"{rec.data2:3d} {rec.data3:3d}"
)
_LOGGER.info(log_msg)
_LOGGER.setLevel(orig_log_level)
logger.info(log_msg)
@callback

View file

@ -1,20 +1,16 @@
"""Support for setting the level of logging for components."""
import logging
import re
import voluptuous as vol
from homeassistant.core import callback
import homeassistant.helpers.config_validation as cv
DOMAIN = "logger"
DATA_LOGGER = "logger"
SERVICE_SET_DEFAULT_LEVEL = "set_default_level"
SERVICE_SET_LEVEL = "set_level"
HIGHEST_LOG_LEVEL = logging.CRITICAL
LOGSEVERITY = {
"CRITICAL": 50,
"FATAL": 50,
@ -26,6 +22,8 @@ LOGSEVERITY = {
"NOTSET": 0,
}
DEFAULT_LOGSEVERITY = "DEBUG"
LOGGER_DEFAULT = "default"
LOGGER_LOGS = "logs"
@ -49,114 +47,36 @@ CONFIG_SCHEMA = vol.Schema(
)
class HomeAssistantLogFilter(logging.Filter):
"""A log filter."""
def __init__(self):
"""Initialize the filter."""
super().__init__()
self._default = None
self._logs = {}
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 set_logger_level(self):
"""Find the lowest log level set to allow logger to pre-filter log messages."""
#
# We set the root logger level to lowest log level
# specified in default or for in the log filter so
# logger.isEnabledFor function will work as designed
# to avoid making logger records that will always be
# discarded.
#
# This can make the logger performance significantly
# faster if no integrations are requesting debug logs
# because we can avoid the record creation and filtering
# overhead.
#
logger = logging.getLogger("")
logger.setLevel(min(HIGHEST_LOG_LEVEL, self._default, *self._logs.values()))
def filter(self, record):
"""Filter the log entries."""
# Log with filtered severity
if self._log_rx:
match = self._log_rx.match(record.name)
if match:
return record.levelno >= self._logs[match.group(0)]
# Log with default severity
return record.levelno >= self._default
async def async_setup(hass, config):
"""Set up the logger component."""
logfilter = {}
hass_filter = HomeAssistantLogFilter()
hass.data[DOMAIN] = {}
logging.setLoggerClass(_get_logger_class(hass.data[DOMAIN]))
@callback
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])
_set_log_level(logging.getLogger(""), level)
@callback
def set_log_levels(logpoints):
"""Set the specified log levels."""
logs = {}
# Preserve existing logs
if LOGGER_LOGS in logfilter:
logs.update(logfilter[LOGGER_LOGS])
# Add new logpoints mapped to correct severity
hass.data[DOMAIN].update(logpoints)
for key, value in logpoints.items():
logs[key] = LOGSEVERITY[value]
logfilter[LOGGER_LOGS] = logs
hass_filter.update_log_filter(logs)
_set_log_level(logging.getLogger(key), value)
# Set default log severity
if LOGGER_DEFAULT in config.get(DOMAIN):
set_default_log_level(config.get(DOMAIN)[LOGGER_DEFAULT])
else:
set_default_log_level("DEBUG")
set_default_log_level(config[DOMAIN].get(LOGGER_DEFAULT, DEFAULT_LOGSEVERITY))
# Set log filter for all log handler
for handler in logging.root.handlers:
handler.setLevel(logging.NOTSET)
handler.addFilter(hass_filter)
if LOGGER_LOGS in config[DOMAIN]:
set_log_levels(config[DOMAIN][LOGGER_LOGS])
if LOGGER_LOGS in config.get(DOMAIN):
set_log_levels(config.get(DOMAIN)[LOGGER_LOGS])
hass_filter.set_logger_level()
async def async_service_handler(service):
@callback
def async_service_handler(service):
"""Handle logger services."""
if service.service == SERVICE_SET_DEFAULT_LEVEL:
set_default_log_level(service.data.get(ATTR_LEVEL))
else:
set_log_levels(service.data)
hass_filter.set_logger_level()
hass.services.async_register(
DOMAIN,
@ -173,3 +93,36 @@ async def async_setup(hass, config):
)
return True
def _set_log_level(logger, level):
"""Set the log level.
Any logger fetched before this integration is loaded will use old class.
"""
getattr(logger, "orig_setLevel", logger.setLevel)(LOGSEVERITY[level])
def _get_logger_class(hass_overrides):
"""Create a logger subclass.
logging.setLoggerClass checks if it is a subclass of Logger and
so we cannot use partial to inject hass_overrides.
"""
class HassLogger(logging.Logger):
"""Home Assistant aware logger class."""
def setLevel(self, level) -> None:
"""Set the log level unless overridden."""
if self.name in hass_overrides:
return
super().setLevel(level)
# pylint: disable=invalid-name
def orig_setLevel(self, level) -> None:
"""Set the log level."""
super().setLevel(level)
return HassLogger

View file

@ -36,8 +36,6 @@ SERVICE_RECORD_SCHEMA = STREAM_SERVICE_SCHEMA.extend(
vol.Optional(CONF_LOOKBACK, default=0): int,
}
)
# Set log level to error for libav
logging.getLogger("libav").setLevel(logging.ERROR)
@bind_hass
@ -80,6 +78,9 @@ def request_stream(hass, stream_source, *, fmt="hls", keepalive=False, options=N
async def async_setup(hass, config):
"""Set up stream."""
# Set log level to error for libav
logging.getLogger("libav").setLevel(logging.ERROR)
# Keep import here so that we can import stream integration without installing reqs
# pylint: disable=import-outside-toplevel
from .recorder import async_setup_recorder

View file

@ -14,7 +14,6 @@ from zeroconf import (
ServiceInfo,
ServiceStateChange,
Zeroconf,
log as zeroconf_log,
)
from homeassistant import util
@ -71,6 +70,7 @@ async def async_get_instance(hass):
def _get_instance(hass, default_interface=False):
"""Create an instance."""
logging.getLogger("zeroconf").setLevel(logging.NOTSET)
args = [InterfaceChoice.Default] if default_interface else []
zeroconf = HaZeroconf(*args)
@ -115,8 +115,6 @@ class HaZeroconf(Zeroconf):
def setup(hass, config):
"""Set up Zeroconf and make Home Assistant discoverable."""
# Zeroconf sets its log level to WARNING, reset it to allow filtering by the logger component.
zeroconf_log.setLevel(logging.NOTSET)
zeroconf = hass.data[DOMAIN] = _get_instance(
hass, config.get(DOMAIN, {}).get(CONF_DEFAULT_INTERFACE)
)

View file

@ -1,143 +1,190 @@
"""The tests for the Logger component."""
from collections import namedtuple
from collections import defaultdict
import logging
import pytest
from homeassistant.components import logger
from homeassistant.components.logger import LOGSEVERITY
from homeassistant.setup import async_setup_component
RECORD = namedtuple("record", ("name", "levelno"))
from tests.async_mock import Mock, patch
NO_DEFAULT_CONFIG = {"logger": {}}
NO_LOGS_CONFIG = {"logger": {"default": "info"}}
TEST_CONFIG = {
"logger": {
"default": "warning",
"logs": {"test": "info", "test.child": "debug", "test.child.child": "warning"},
}
}
HASS_NS = "unused.homeassistant"
COMPONENTS_NS = f"{HASS_NS}.components"
ZONE_NS = f"{COMPONENTS_NS}.zone"
GROUP_NS = f"{COMPONENTS_NS}.group"
CONFIGED_NS = "otherlibx"
UNCONFIG_NS = "unconfigurednamespace"
async def async_setup_logger(hass, config):
"""Set up logger and save log filter."""
await async_setup_component(hass, logger.DOMAIN, config)
return logging.root.handlers[-1].filters[0]
@pytest.fixture(autouse=True)
def restore_logging_class():
"""Restore logging class."""
klass = logging.getLoggerClass()
yield
logging.setLoggerClass(klass)
async def test_logger_setup(hass):
"""Use logger to create a logging filter."""
await async_setup_logger(hass, TEST_CONFIG)
async def test_setting_level(hass):
"""Test we set log levels."""
mocks = defaultdict(Mock)
assert len(logging.root.handlers) > 0
handler = logging.root.handlers[-1]
with patch("logging.getLogger", mocks.__getitem__):
assert await async_setup_component(
hass,
"logger",
{
"logger": {
"default": "warning",
"logs": {
"test": "info",
"test.child": "debug",
"test.child.child": "warning",
},
}
},
)
await hass.async_block_till_done()
assert len(handler.filters) == 1
assert len(mocks) == 4
assert len(mocks[""].orig_setLevel.mock_calls) == 1
assert mocks[""].orig_setLevel.mock_calls[0][1][0] == LOGSEVERITY["WARNING"]
assert len(mocks["test"].orig_setLevel.mock_calls) == 1
assert mocks["test"].orig_setLevel.mock_calls[0][1][0] == LOGSEVERITY["INFO"]
assert len(mocks["test.child"].orig_setLevel.mock_calls) == 1
assert mocks["test.child"].orig_setLevel.mock_calls[0][1][0] == LOGSEVERITY["DEBUG"]
assert len(mocks["test.child.child"].orig_setLevel.mock_calls) == 1
assert (
mocks["test.child.child"].orig_setLevel.mock_calls[0][1][0]
== LOGSEVERITY["WARNING"]
)
# Test set default level
with patch("logging.getLogger", mocks.__getitem__):
await hass.services.async_call(
"logger", "set_default_level", {"level": "fatal"}, blocking=True
)
assert len(mocks[""].orig_setLevel.mock_calls) == 2
assert mocks[""].orig_setLevel.mock_calls[1][1][0] == LOGSEVERITY["FATAL"]
# Test update other loggers
with patch("logging.getLogger", mocks.__getitem__):
await hass.services.async_call(
"logger",
"set_level",
{"test.child": "info", "new_logger": "notset"},
blocking=True,
)
assert len(mocks) == 5
assert len(mocks["test.child"].orig_setLevel.mock_calls) == 2
assert mocks["test.child"].orig_setLevel.mock_calls[1][1][0] == LOGSEVERITY["INFO"]
assert len(mocks["new_logger"].orig_setLevel.mock_calls) == 1
assert (
mocks["new_logger"].orig_setLevel.mock_calls[0][1][0] == LOGSEVERITY["NOTSET"]
)
async def test_logger_test_filters(hass):
"""Test resulting filter operation."""
log_filter = await async_setup_logger(hass, TEST_CONFIG)
async def test_can_set_level(hass):
"""Test logger propagation."""
assert await async_setup_component(
hass,
"logger",
{
"logger": {
"logs": {
CONFIGED_NS: "warning",
f"{CONFIGED_NS}.info": "info",
f"{CONFIGED_NS}.debug": "debug",
HASS_NS: "warning",
COMPONENTS_NS: "info",
ZONE_NS: "debug",
GROUP_NS: "info",
},
}
},
)
assert logging.getLogger(UNCONFIG_NS).level == logging.NOTSET
assert logging.getLogger(UNCONFIG_NS).isEnabledFor(logging.CRITICAL) is True
assert (
logging.getLogger(f"{UNCONFIG_NS}.any").isEnabledFor(logging.CRITICAL) is True
)
assert (
logging.getLogger(f"{UNCONFIG_NS}.any.any").isEnabledFor(logging.CRITICAL)
is True
)
assert logging.getLogger(CONFIGED_NS).isEnabledFor(logging.DEBUG) is False
assert logging.getLogger(CONFIGED_NS).isEnabledFor(logging.WARNING) is True
assert logging.getLogger(f"{CONFIGED_NS}.any").isEnabledFor(logging.WARNING) is True
assert (
logging.getLogger(f"{CONFIGED_NS}.any.any").isEnabledFor(logging.WARNING)
is True
)
assert logging.getLogger(f"{CONFIGED_NS}.info").isEnabledFor(logging.DEBUG) is False
assert logging.getLogger(f"{CONFIGED_NS}.info").isEnabledFor(logging.INFO) is True
assert (
logging.getLogger(f"{CONFIGED_NS}.info.any").isEnabledFor(logging.DEBUG)
is False
)
assert (
logging.getLogger(f"{CONFIGED_NS}.info.any").isEnabledFor(logging.INFO) is True
)
assert logging.getLogger(f"{CONFIGED_NS}.debug").isEnabledFor(logging.DEBUG) is True
assert (
logging.getLogger(f"{CONFIGED_NS}.debug.any").isEnabledFor(logging.DEBUG)
is True
)
assert logging.getLogger(HASS_NS).isEnabledFor(logging.DEBUG) is False
assert logging.getLogger(HASS_NS).isEnabledFor(logging.WARNING) is True
assert logging.getLogger(COMPONENTS_NS).isEnabledFor(logging.DEBUG) is False
assert logging.getLogger(COMPONENTS_NS).isEnabledFor(logging.WARNING) is True
assert logging.getLogger(COMPONENTS_NS).isEnabledFor(logging.INFO) is True
assert logging.getLogger(GROUP_NS).isEnabledFor(logging.DEBUG) is False
assert logging.getLogger(GROUP_NS).isEnabledFor(logging.WARNING) is True
assert logging.getLogger(GROUP_NS).isEnabledFor(logging.INFO) is True
assert logging.getLogger(f"{GROUP_NS}.any").isEnabledFor(logging.DEBUG) is False
assert logging.getLogger(f"{GROUP_NS}.any").isEnabledFor(logging.WARNING) is True
assert logging.getLogger(f"{GROUP_NS}.any").isEnabledFor(logging.INFO) is True
assert logging.getLogger(ZONE_NS).isEnabledFor(logging.DEBUG) is True
assert logging.getLogger(f"{ZONE_NS}.any").isEnabledFor(logging.DEBUG) is True
await hass.services.async_call(
logger.DOMAIN, "set_level", {f"{UNCONFIG_NS}.any": "debug"}, blocking=True
)
logging.getLogger(UNCONFIG_NS).level == logging.NOTSET
logging.getLogger(f"{UNCONFIG_NS}.any").level == logging.DEBUG
logging.getLogger(UNCONFIG_NS).level == logging.NOTSET
await hass.services.async_call(
logger.DOMAIN, "set_default_level", {"level": "debug"}, blocking=True
)
assert logging.getLogger(UNCONFIG_NS).isEnabledFor(logging.DEBUG) is True
assert logging.getLogger(f"{UNCONFIG_NS}.any").isEnabledFor(logging.DEBUG) is True
assert (
logging.getLogger(f"{UNCONFIG_NS}.any.any").isEnabledFor(logging.DEBUG) is True
)
assert logging.getLogger("").isEnabledFor(logging.DEBUG) is True
# Blocked default record
assert not log_filter.filter(RECORD("asdf", logging.DEBUG))
assert logging.getLogger(COMPONENTS_NS).isEnabledFor(logging.DEBUG) is False
assert logging.getLogger(GROUP_NS).isEnabledFor(logging.DEBUG) is False
# Allowed default record
assert log_filter.filter(RECORD("asdf", logging.WARNING))
logging.getLogger(CONFIGED_NS).setLevel(logging.INFO)
assert logging.getLogger(CONFIGED_NS).level == logging.WARNING
# Blocked named record
assert not log_filter.filter(RECORD("test", logging.DEBUG))
# Allowed named record
assert log_filter.filter(RECORD("test", logging.INFO))
# Allowed named record child
assert log_filter.filter(RECORD("test.child", logging.INFO))
# Allowed named record child
assert log_filter.filter(RECORD("test.child", logging.DEBUG))
# Blocked named record child of child
assert not log_filter.filter(RECORD("test.child.child", logging.DEBUG))
# Allowed named record child of child
assert log_filter.filter(RECORD("test.child.child", logging.WARNING))
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)
assert logging.getLogger("").isEnabledFor(logging.DEBUG) is False
assert not log_filter.filter(RECORD("test", logging.DEBUG))
await hass.services.async_call(
logger.DOMAIN, "set_default_level", {"level": "warning"}
)
await hass.async_block_till_done()
assert not log_filter.filter(RECORD("test", logging.DEBUG))
assert logging.getLogger("").isEnabledFor(logging.DEBUG) is False
assert logging.getLogger("").isEnabledFor(logging.WARNING) is True
await hass.services.async_call(logger.DOMAIN, "set_level", {"test": "debug"})
await hass.async_block_till_done()
assert log_filter.filter(RECORD("test", logging.DEBUG))
assert logging.getLogger("").isEnabledFor(logging.DEBUG) is True
async def test_set_filter(hass):
"""Test change log level of existing filter."""
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_level", {"asdf": "debug", "dummy": "info"}
)
await hass.async_block_till_done()
assert log_filter.filter(RECORD("asdf", logging.DEBUG))
assert log_filter.filter(RECORD("dummy", logging.WARNING))
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)
assert logging.getLogger("").isEnabledFor(logging.DEBUG) is True
assert logging.getLogger("").isEnabledFor(logging.WARNING) is True
assert log_filter.filter(RECORD("test", logging.DEBUG))
await hass.services.async_call(
logger.DOMAIN, "set_default_level", {"level": "warning"}
)
await hass.async_block_till_done()
assert not log_filter.filter(RECORD("test", logging.DEBUG))
assert logging.getLogger("").isEnabledFor(logging.DEBUG) is False
assert logging.getLogger("").isEnabledFor(logging.INFO) is False
assert logging.getLogger("").isEnabledFor(logging.WARNING) is True
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))
logging.getLogger("").setLevel(logging.NOTSET)