From 08ff1b89862594077c68e16e3010b908c7880ad7 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 14 Jul 2022 11:05:52 +0200 Subject: [PATCH] Fix flapping system log test (#75111) --- .../components/system_log/__init__.py | 65 +++----- homeassistant/components/zha/core/gateway.py | 12 +- tests/components/network/conftest.py | 6 +- tests/components/system_log/test_init.py | 153 +++++++++--------- tests/conftest.py | 20 +++ 5 files changed, 135 insertions(+), 121 deletions(-) diff --git a/homeassistant/components/system_log/__init__.py b/homeassistant/components/system_log/__init__.py index 343830fe690..b0d538a4ff8 100644 --- a/homeassistant/components/system_log/__init__.py +++ b/homeassistant/components/system_log/__init__.py @@ -1,7 +1,6 @@ """Support for system log.""" from collections import OrderedDict, deque import logging -import queue import re import traceback @@ -9,7 +8,7 @@ import voluptuous as vol from homeassistant import __path__ as HOMEASSISTANT_PATH from homeassistant.components import websocket_api -from homeassistant.const import EVENT_HOMEASSISTANT_CLOSE, EVENT_HOMEASSISTANT_STOP +from homeassistant.const import EVENT_HOMEASSISTANT_CLOSE from homeassistant.core import HomeAssistant, ServiceCall, callback import homeassistant.helpers.config_validation as cv from homeassistant.helpers.typing import ConfigType @@ -56,8 +55,7 @@ SERVICE_WRITE_SCHEMA = vol.Schema( ) -def _figure_out_source(record, call_stack, hass): - paths = [HOMEASSISTANT_PATH[0], hass.config.config_dir] +def _figure_out_source(record, call_stack, paths_re): # If a stack trace exists, extract file names from the entire call stack. # The other case is when a regular "log" is made (without an attached @@ -78,11 +76,10 @@ def _figure_out_source(record, call_stack, hass): # Iterate through the stack call (in reverse) and find the last call from # a file in Home Assistant. Try to figure out where error happened. - paths_re = r"(?:{})/(.*)".format("|".join([re.escape(x) for x in paths])) for pathname in reversed(stack): # Try to match with a file within Home Assistant - if match := re.match(paths_re, pathname[0]): + if match := paths_re.match(pathname[0]): return [match.group(1), pathname[1]] # Ok, we don't know what this is return (record.pathname, record.lineno) @@ -157,26 +154,16 @@ class DedupStore(OrderedDict): return [value.to_dict() for value in reversed(self.values())] -class LogErrorQueueHandler(logging.handlers.QueueHandler): - """Process the log in another thread.""" - - def emit(self, record): - """Emit a log record.""" - try: - self.enqueue(record) - except Exception: # pylint: disable=broad-except - self.handleError(record) - - class LogErrorHandler(logging.Handler): """Log handler for error messages.""" - def __init__(self, hass, maxlen, fire_event): + def __init__(self, hass, maxlen, fire_event, paths_re): """Initialize a new LogErrorHandler.""" super().__init__() self.hass = hass self.records = DedupStore(maxlen=maxlen) self.fire_event = fire_event + self.paths_re = paths_re def emit(self, record): """Save error and warning logs. @@ -189,7 +176,9 @@ class LogErrorHandler(logging.Handler): if not record.exc_info: stack = [(f[0], f[1]) for f in traceback.extract_stack()] - entry = LogEntry(record, stack, _figure_out_source(record, stack, self.hass)) + entry = LogEntry( + record, stack, _figure_out_source(record, stack, self.paths_re) + ) self.records.add_entry(entry) if self.fire_event: self.hass.bus.fire(EVENT_SYSTEM_LOG, entry.to_dict()) @@ -200,29 +189,28 @@ async def async_setup(hass: HomeAssistant, config: ConfigType) -> bool: if (conf := config.get(DOMAIN)) is None: conf = CONFIG_SCHEMA({DOMAIN: {}})[DOMAIN] - simple_queue: queue.SimpleQueue = queue.SimpleQueue() - queue_handler = LogErrorQueueHandler(simple_queue) - queue_handler.setLevel(logging.WARN) - logging.root.addHandler(queue_handler) - - handler = LogErrorHandler(hass, conf[CONF_MAX_ENTRIES], conf[CONF_FIRE_EVENT]) + hass_path: str = HOMEASSISTANT_PATH[0] + config_dir = hass.config.config_dir + assert config_dir is not None + paths_re = re.compile( + r"(?:{})/(.*)".format("|".join([re.escape(x) for x in (hass_path, config_dir)])) + ) + handler = LogErrorHandler( + hass, conf[CONF_MAX_ENTRIES], conf[CONF_FIRE_EVENT], paths_re + ) + handler.setLevel(logging.WARN) hass.data[DOMAIN] = handler - listener = logging.handlers.QueueListener( - simple_queue, handler, respect_handler_level=True - ) - - listener.start() - @callback - def _async_stop_queue_handler(_) -> None: + def _async_stop_handler(_) -> None: """Cleanup handler.""" - logging.root.removeHandler(queue_handler) - listener.stop() + logging.root.removeHandler(handler) del hass.data[DOMAIN] - hass.bus.async_listen_once(EVENT_HOMEASSISTANT_CLOSE, _async_stop_queue_handler) + hass.bus.async_listen_once(EVENT_HOMEASSISTANT_CLOSE, _async_stop_handler) + + logging.root.addHandler(handler) websocket_api.async_register_command(hass, list_errors) @@ -238,13 +226,6 @@ async def async_setup(hass: HomeAssistant, config: ConfigType) -> bool: level = service.data[CONF_LEVEL] getattr(logger, level)(service.data[CONF_MESSAGE]) - async def async_shutdown_handler(event): - """Remove logging handler when Home Assistant is shutdown.""" - # This is needed as older logger instances will remain - logging.getLogger().removeHandler(handler) - - hass.bus.async_listen_once(EVENT_HOMEASSISTANT_STOP, async_shutdown_handler) - hass.services.async_register( DOMAIN, SERVICE_CLEAR, async_service_handler, schema=SERVICE_CLEAR_SCHEMA ) diff --git a/homeassistant/components/zha/core/gateway.py b/homeassistant/components/zha/core/gateway.py index 9efb6e99550..f2fd226249b 100644 --- a/homeassistant/components/zha/core/gateway.py +++ b/homeassistant/components/zha/core/gateway.py @@ -8,6 +8,7 @@ from datetime import timedelta from enum import Enum import itertools import logging +import re import time import traceback from typing import TYPE_CHECKING, Any, NamedTuple, Union @@ -20,6 +21,7 @@ import zigpy.endpoint import zigpy.group from zigpy.types.named import EUI64 +from homeassistant import __path__ as HOMEASSISTANT_PATH from homeassistant.components.system_log import LogEntry, _figure_out_source from homeassistant.config_entries import ConfigEntry from homeassistant.core import HomeAssistant, callback @@ -732,7 +734,15 @@ class LogRelayHandler(logging.Handler): if record.levelno >= logging.WARN and not record.exc_info: stack = [f for f, _, _, _ in traceback.extract_stack()] - entry = LogEntry(record, stack, _figure_out_source(record, stack, self.hass)) + hass_path: str = HOMEASSISTANT_PATH[0] + config_dir = self.hass.config.config_dir + assert config_dir is not None + paths_re = re.compile( + r"(?:{})/(.*)".format( + "|".join([re.escape(x) for x in (hass_path, config_dir)]) + ) + ) + entry = LogEntry(record, stack, _figure_out_source(record, stack, paths_re)) async_dispatcher_send( self.hass, ZHA_GW_MSG, diff --git a/tests/components/network/conftest.py b/tests/components/network/conftest.py index 9c1bf232d7b..8b1b383ae42 100644 --- a/tests/components/network/conftest.py +++ b/tests/components/network/conftest.py @@ -6,4 +6,8 @@ import pytest @pytest.fixture(autouse=True) def mock_get_source_ip(): """Override mock of network util's async_get_source_ip.""" - return + + +@pytest.fixture(autouse=True) +def mock_network(): + """Override mock of network util's async_get_adapters.""" diff --git a/tests/components/system_log/test_init.py b/tests/components/system_log/test_init.py index d558d690536..6304e0ea7cf 100644 --- a/tests/components/system_log/test_init.py +++ b/tests/components/system_log/test_init.py @@ -1,10 +1,11 @@ """Test system log component.""" -import asyncio -import logging -import queue -from unittest.mock import MagicMock, patch +from __future__ import annotations -import pytest +import asyncio +from collections.abc import Awaitable +import logging +from typing import Any +from unittest.mock import MagicMock, patch from homeassistant.bootstrap import async_setup_component from homeassistant.components import system_log @@ -16,28 +17,6 @@ _LOGGER = logging.getLogger("test_logger") BASIC_CONFIG = {"system_log": {"max_entries": 2}} -@pytest.fixture -def simple_queue(): - """Fixture that get the queue.""" - simple_queue_fixed = queue.SimpleQueue() - with patch( - "homeassistant.components.system_log.queue.SimpleQueue", - return_value=simple_queue_fixed, - ): - yield simple_queue_fixed - - -async def _async_block_until_queue_empty(hass, sq): - # Unfortunately we are stuck with polling - await hass.async_block_till_done() - while not sq.empty(): - await asyncio.sleep(0.01) - hass.data[system_log.DOMAIN].acquire() - hass.data[system_log.DOMAIN].release() - await hass.async_block_till_done() - await hass.async_block_till_done() - - async def get_error_log(hass_ws_client): """Fetch all entries from system_log via the API.""" client = await hass_ws_client() @@ -81,66 +60,97 @@ def assert_log(log, exception, message, level): assert "timestamp" in log +class WatchLogErrorHandler(system_log.LogErrorHandler): + """WatchLogErrorHandler that watches for a message.""" + + instances: list[WatchLogErrorHandler] = [] + + def __init__(self, *args: Any, **kwargs: Any) -> None: + """Initialize HASSQueueListener.""" + super().__init__(*args, **kwargs) + self.watch_message: str | None = None + self.watch_event: asyncio.Event | None = asyncio.Event() + WatchLogErrorHandler.instances.append(self) + + def add_watcher(self, match: str) -> Awaitable: + """Add a watcher.""" + self.watch_event = asyncio.Event() + self.watch_message = match + return self.watch_event.wait() + + def handle(self, record: logging.LogRecord) -> None: + """Handle a logging record.""" + super().handle(record) + if record.message in self.watch_message: + self.watch_event.set() + + def get_frame(name): """Get log stack frame.""" return (name, 5, None, None) -async def test_normal_logs(hass, simple_queue, hass_ws_client): +async def async_setup_system_log(hass, config) -> WatchLogErrorHandler: + """Set up the system_log component.""" + WatchLogErrorHandler.instances = [] + with patch( + "homeassistant.components.system_log.LogErrorHandler", WatchLogErrorHandler + ): + await async_setup_component(hass, system_log.DOMAIN, config) + await hass.async_block_till_done() + + assert len(WatchLogErrorHandler.instances) == 1 + return WatchLogErrorHandler.instances.pop() + + +async def test_normal_logs(hass, hass_ws_client): """Test that debug and info are not logged.""" await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) await hass.async_block_till_done() - _LOGGER.debug("debug") _LOGGER.info("info") - await _async_block_until_queue_empty(hass, simple_queue) # Assert done by get_error_log logs = await get_error_log(hass_ws_client) assert len([msg for msg in logs if msg["level"] in ("DEBUG", "INFO")]) == 0 -async def test_exception(hass, simple_queue, hass_ws_client): +async def test_exception(hass, hass_ws_client): """Test that exceptions are logged and retrieved correctly.""" await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) await hass.async_block_till_done() _generate_and_log_exception("exception message", "log message") - await _async_block_until_queue_empty(hass, simple_queue) log = find_log(await get_error_log(hass_ws_client), "ERROR") assert log is not None assert_log(log, "exception message", "log message", "ERROR") -async def test_warning(hass, simple_queue, hass_ws_client): +async def test_warning(hass, hass_ws_client): """Test that warning are logged and retrieved correctly.""" await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) await hass.async_block_till_done() - _LOGGER.warning("warning message") - await _async_block_until_queue_empty(hass, simple_queue) log = find_log(await get_error_log(hass_ws_client), "WARNING") assert_log(log, "", "warning message", "WARNING") -async def test_error(hass, simple_queue, hass_ws_client): +async def test_error(hass, hass_ws_client): """Test that errors are logged and retrieved correctly.""" await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) await hass.async_block_till_done() _LOGGER.error("error message") - await _async_block_until_queue_empty(hass, simple_queue) log = find_log(await get_error_log(hass_ws_client), "ERROR") assert_log(log, "", "error message", "ERROR") -async def test_config_not_fire_event(hass, simple_queue): +async def test_config_not_fire_event(hass): """Test that errors are not posted as events with default config.""" await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) await hass.async_block_till_done() - events = [] @callback @@ -150,50 +160,49 @@ async def test_config_not_fire_event(hass, simple_queue): hass.bus.async_listen(system_log.EVENT_SYSTEM_LOG, event_listener) - _LOGGER.error("error message") - await _async_block_until_queue_empty(hass, simple_queue) + await hass.async_block_till_done() + await hass.async_block_till_done() assert len(events) == 0 -async def test_error_posted_as_event(hass, simple_queue): +async def test_error_posted_as_event(hass): """Test that error are posted as events.""" - await async_setup_component( - hass, system_log.DOMAIN, {"system_log": {"max_entries": 2, "fire_event": True}} + watcher = await async_setup_system_log( + hass, {"system_log": {"max_entries": 2, "fire_event": True}} ) - await hass.async_block_till_done() + wait_empty = watcher.add_watcher("error message") events = async_capture_events(hass, system_log.EVENT_SYSTEM_LOG) _LOGGER.error("error message") - await _async_block_until_queue_empty(hass, simple_queue) + await wait_empty + await hass.async_block_till_done() + await hass.async_block_till_done() assert len(events) == 1 assert_log(events[0].data, "", "error message", "ERROR") -async def test_critical(hass, simple_queue, hass_ws_client): +async def test_critical(hass, hass_ws_client): """Test that critical are logged and retrieved correctly.""" await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) await hass.async_block_till_done() _LOGGER.critical("critical message") - await _async_block_until_queue_empty(hass, simple_queue) log = find_log(await get_error_log(hass_ws_client), "CRITICAL") assert_log(log, "", "critical message", "CRITICAL") -async def test_remove_older_logs(hass, simple_queue, hass_ws_client): +async def test_remove_older_logs(hass, hass_ws_client): """Test that older logs are rotated out.""" await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) await hass.async_block_till_done() - _LOGGER.error("error message 1") _LOGGER.error("error message 2") _LOGGER.error("error message 3") - await _async_block_until_queue_empty(hass, simple_queue) - + await hass.async_block_till_done() log = await get_error_log(hass_ws_client) assert_log(log[0], "", "error message 3", "ERROR") assert_log(log[1], "", "error message 2", "ERROR") @@ -204,16 +213,14 @@ def log_msg(nr=2): _LOGGER.error("error message %s", nr) -async def test_dedupe_logs(hass, simple_queue, hass_ws_client): +async def test_dedupe_logs(hass, hass_ws_client): """Test that duplicate log entries are dedupe.""" - await async_setup_component(hass, system_log.DOMAIN, {}) + await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) await hass.async_block_till_done() - _LOGGER.error("error message 1") log_msg() log_msg("2-2") _LOGGER.error("error message 3") - await _async_block_until_queue_empty(hass, simple_queue) log = await get_error_log(hass_ws_client) assert_log(log[0], "", "error message 3", "ERROR") @@ -221,8 +228,6 @@ async def test_dedupe_logs(hass, simple_queue, hass_ws_client): assert_log(log[1], "", ["error message 2", "error message 2-2"], "ERROR") log_msg() - await _async_block_until_queue_empty(hass, simple_queue) - log = await get_error_log(hass_ws_client) assert_log(log[0], "", ["error message 2", "error message 2-2"], "ERROR") assert log[0]["timestamp"] > log[0]["first_occurred"] @@ -231,7 +236,6 @@ async def test_dedupe_logs(hass, simple_queue, hass_ws_client): log_msg("2-4") log_msg("2-5") log_msg("2-6") - await _async_block_until_queue_empty(hass, simple_queue) log = await get_error_log(hass_ws_client) assert_log( @@ -248,17 +252,14 @@ async def test_dedupe_logs(hass, simple_queue, hass_ws_client): ) -async def test_clear_logs(hass, simple_queue, hass_ws_client): +async def test_clear_logs(hass, hass_ws_client): """Test that the log can be cleared via a service call.""" await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) await hass.async_block_till_done() - _LOGGER.error("error message") - await _async_block_until_queue_empty(hass, simple_queue) await hass.services.async_call(system_log.DOMAIN, system_log.SERVICE_CLEAR, {}) - await _async_block_until_queue_empty(hass, simple_queue) - + await hass.async_block_till_done() # Assert done by get_error_log await get_error_log(hass_ws_client) @@ -309,19 +310,17 @@ async def test_write_choose_level(hass): assert logger.method_calls[0] == ("debug", ("test_message",)) -async def test_unknown_path(hass, simple_queue, hass_ws_client): +async def test_unknown_path(hass, hass_ws_client): """Test error logged from unknown path.""" await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) await hass.async_block_till_done() - _LOGGER.findCaller = MagicMock(return_value=("unknown_path", 0, None, None)) _LOGGER.error("error message") - await _async_block_until_queue_empty(hass, simple_queue) log = (await get_error_log(hass_ws_client))[0] assert log["source"] == ["unknown_path", 0] -async def async_log_error_from_test_path(hass, path, sq): +async def async_log_error_from_test_path(hass, path, watcher): """Log error while mocking the path.""" call_path = "internal_path.py" with patch.object( @@ -337,34 +336,34 @@ async def async_log_error_from_test_path(hass, path, sq): ] ), ): + wait_empty = watcher.add_watcher("error message") _LOGGER.error("error message") - await _async_block_until_queue_empty(hass, sq) + await wait_empty -async def test_homeassistant_path(hass, simple_queue, hass_ws_client): +async def test_homeassistant_path(hass, hass_ws_client): """Test error logged from Home Assistant path.""" - await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) - await hass.async_block_till_done() with patch( "homeassistant.components.system_log.HOMEASSISTANT_PATH", new=["venv_path/homeassistant"], ): + watcher = await async_setup_system_log(hass, BASIC_CONFIG) await async_log_error_from_test_path( - hass, "venv_path/homeassistant/component/component.py", simple_queue + hass, "venv_path/homeassistant/component/component.py", watcher ) log = (await get_error_log(hass_ws_client))[0] assert log["source"] == ["component/component.py", 5] -async def test_config_path(hass, simple_queue, hass_ws_client): +async def test_config_path(hass, hass_ws_client): """Test error logged from config path.""" - await async_setup_component(hass, system_log.DOMAIN, BASIC_CONFIG) - await hass.async_block_till_done() with patch.object(hass.config, "config_dir", new="config"): + watcher = await async_setup_system_log(hass, BASIC_CONFIG) + await async_log_error_from_test_path( - hass, "config/custom_component/test.py", simple_queue + hass, "config/custom_component/test.py", watcher ) log = (await get_error_log(hass_ws_client))[0] assert log["source"] == ["custom_component/test.py", 5] diff --git a/tests/conftest.py b/tests/conftest.py index 97b1a959d2c..4b2852e94fc 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -22,6 +22,7 @@ from homeassistant.auth.const import GROUP_ID_ADMIN, GROUP_ID_READ_ONLY from homeassistant.auth.models import Credentials from homeassistant.auth.providers import homeassistant, legacy_api_password from homeassistant.components import mqtt, recorder +from homeassistant.components.network.models import Adapter, IPv4ConfiguredAddress from homeassistant.components.websocket_api.auth import ( TYPE_AUTH, TYPE_AUTH_OK, @@ -644,6 +645,25 @@ async def mqtt_mock_entry_with_yaml_config(hass, mqtt_client_mock, mqtt_config): yield _setup_mqtt_entry +@pytest.fixture(autouse=True) +def mock_network(): + """Mock network.""" + mock_adapter = Adapter( + name="eth0", + index=0, + enabled=True, + auto=True, + default=True, + ipv4=[IPv4ConfiguredAddress(address="10.10.10.10", network_prefix=24)], + ipv6=[], + ) + with patch( + "homeassistant.components.network.network.async_load_adapters", + return_value=[mock_adapter], + ): + yield + + @pytest.fixture(autouse=True) def mock_get_source_ip(): """Mock network util's async_get_source_ip."""