From bbef3f7f68b6b2e69ec72f2c854867db3a23864e Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Wed, 13 Mar 2024 00:58:34 -1000 Subject: [PATCH] Only extract traceback once in system_log (#113201) --- .../components/system_log/__init__.py | 36 +++++++++++++------ homeassistant/components/zha/core/gateway.py | 9 +++-- tests/components/system_log/test_init.py | 9 +++-- 3 files changed, 37 insertions(+), 17 deletions(-) diff --git a/homeassistant/components/system_log/__init__.py b/homeassistant/components/system_log/__init__.py index 8a8e8486f93..83a89a277cc 100644 --- a/homeassistant/components/system_log/__init__.py +++ b/homeassistant/components/system_log/__init__.py @@ -63,14 +63,19 @@ SERVICE_WRITE_SCHEMA = vol.Schema( def _figure_out_source( - record: logging.LogRecord, paths_re: re.Pattern[str] + record: logging.LogRecord, + paths_re: re.Pattern[str], + extracted_tb: traceback.StackSummary | None = None, ) -> tuple[str, int]: """Figure out where a log message came from.""" # 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 # exception). In that case, just use the file where the log was made from. if record.exc_info: - stack = [(x[0], x[1]) for x in traceback.extract_tb(record.exc_info[2])] + stack = [ + (x[0], x[1]) + for x in (extracted_tb or traceback.extract_tb(record.exc_info[2])) + ] for i, (filename, _) in enumerate(stack): # Slice the stack to the first frame that matches # the record pathname. @@ -161,13 +166,19 @@ class LogEntry: "level", "message", "exception", + "extracted_tb", "root_cause", "source", "count", "key", ) - def __init__(self, record: logging.LogRecord, source: tuple[str, int]) -> None: + def __init__( + self, + record: logging.LogRecord, + paths_re: re.Pattern, + figure_out_source: bool = False, + ) -> None: """Initialize a log entry.""" self.first_occurred = self.timestamp = record.created self.name = record.name @@ -176,16 +187,21 @@ class LogEntry: # This must be manually tested when changing the code. self.message = deque([_safe_get_message(record)], maxlen=5) self.exception = "" - self.root_cause = None + self.root_cause: str | None = None + extracted_tb: traceback.StackSummary | None = None if record.exc_info: self.exception = "".join(traceback.format_exception(*record.exc_info)) - _, _, tb = record.exc_info - # Last line of traceback contains the root cause of the exception - if extracted := traceback.extract_tb(tb): + if extracted := traceback.extract_tb(record.exc_info[2]): + # Last line of traceback contains the root cause of the exception + extracted_tb = extracted self.root_cause = str(extracted[-1]) - self.source = source + if figure_out_source: + self.source = _figure_out_source(record, paths_re, extracted_tb) + else: + self.source = (record.pathname, record.lineno) self.count = 1 - self.key = (self.name, source, self.root_cause) + self.extracted_tb = extracted_tb + self.key = (self.name, self.source, self.root_cause) def to_dict(self) -> dict[str, Any]: """Convert object into dict to maintain backward compatibility.""" @@ -259,7 +275,7 @@ class LogErrorHandler(logging.Handler): default upper limit is set to 50 (older entries are discarded) but can be changed if needed. """ - entry = LogEntry(record, _figure_out_source(record, self.paths_re)) + entry = LogEntry(record, self.paths_re, figure_out_source=True) self.records.add_entry(entry) if self.fire_event: self.hass.bus.fire(EVENT_SYSTEM_LOG, entry.to_dict()) diff --git a/homeassistant/components/zha/core/gateway.py b/homeassistant/components/zha/core/gateway.py index 62112f70584..9556631f45b 100644 --- a/homeassistant/components/zha/core/gateway.py +++ b/homeassistant/components/zha/core/gateway.py @@ -30,7 +30,7 @@ from zigpy.state import State 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.components.system_log import LogEntry from homeassistant.config_entries import ConfigEntry from homeassistant.core import HomeAssistant, callback from homeassistant.helpers import device_registry as dr, entity_registry as er @@ -871,10 +871,9 @@ class LogRelayHandler(logging.Handler): def emit(self, record: LogRecord) -> None: """Relay log message via dispatcher.""" - if record.levelno >= logging.WARN: - entry = LogEntry(record, _figure_out_source(record, self.paths_re)) - else: - entry = LogEntry(record, (record.pathname, record.lineno)) + entry = LogEntry( + record, self.paths_re, figure_out_source=record.levelno >= logging.WARN + ) async_dispatcher_send( self.hass, ZHA_GW_MSG, diff --git a/tests/components/system_log/test_init.py b/tests/components/system_log/test_init.py index 133b48ea745..22cef15b1ab 100644 --- a/tests/components/system_log/test_init.py +++ b/tests/components/system_log/test_init.py @@ -459,14 +459,19 @@ async def test__figure_out_source(hass: HomeAssistant) -> None: except ValueError as ex: exc_info = (type(ex), ex, ex.__traceback__) mock_record = MagicMock( - pathname="should not hit", + pathname="figure_out_source is False", lineno=5, exc_info=exc_info, ) regex_str = f"({__file__})" + paths_re = re.compile(regex_str) file, line_no = system_log._figure_out_source( mock_record, - re.compile(regex_str), + paths_re, + traceback.extract_tb(exc_info[2]), ) assert file == __file__ assert line_no != 5 + + entry = system_log.LogEntry(mock_record, paths_re, figure_out_source=False) + assert entry.source == ("figure_out_source is False", 5)