evlli/hass-core
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Fix flapping system log test (#75111)

Browse source
This commit is contained in:
J. Nick Koston 2022-07-14 11:05:52 +02:00 • committed by GitHub
parent a720b2989a
commit 08ff1b8986
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
5 changed files with 135 additions and 121 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

65
homeassistant/components/system_log/__init__.py
View file

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

12
homeassistant/components/zha/core/gateway.py
View file

@ -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,

6
tests/components/network/conftest.py
View file

@ -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."""

153
tests/components/system_log/test_init.py
View file

@ -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]

20
tests/conftest.py
View file

@ -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."""