From 2213006881b974b4dbc3287a9a754d7ff432eb73 Mon Sep 17 00:00:00 2001 From: Edward Hope-Morley Date: Thu, 2 May 2024 08:44:02 +0100 Subject: [PATCH] Group all event searches To avoid searching the same file more than once we now gather all searches from all events and executed all searches for a given file once. Related-to: #850 --- hotsos/client.py | 5 +- hotsos/core/plugintools.py | 2 + hotsos/core/ycheck/events.py | 229 +++++++++++++++++++++------- tests/unit/storage/test_ceph_mon.py | 4 + tests/unit/storage/test_ceph_osd.py | 4 + tests/unit/test_openstack.py | 10 ++ tests/unit/test_openvswitch.py | 42 ++++- tests/unit/test_ycheck_events.py | 5 + 8 files changed, 236 insertions(+), 65 deletions(-) diff --git a/hotsos/client.py b/hotsos/client.py index 8f058ebe4..0e6771dad 100755 --- a/hotsos/client.py +++ b/hotsos/client.py @@ -213,10 +213,7 @@ def __init__(self, plugins=None): all will be run. """ self._summary = OutputManager() - if plugins: - self.plugins = plugins - else: - self.plugins = plugintools.PLUGINS.keys() + self.plugins = plugins or plugintools.PLUGINS.keys() def setup_global_env(self): """ State saved here persists across all plugin runs. """ diff --git a/hotsos/core/plugintools.py b/hotsos/core/plugintools.py index d7aa964fb..b7e4b4d0b 100644 --- a/hotsos/core/plugintools.py +++ b/hotsos/core/plugintools.py @@ -7,6 +7,7 @@ from hotsos.core.issues import IssuesManager from hotsos.core.log import log from hotsos.core.ycheck.scenarios import YScenarioChecker +from hotsos.core.ycheck.events import EventDefsPreloader PLUGINS = {} PLUGIN_RUN_ORDER = [] @@ -393,6 +394,7 @@ def run(self): failed_parts = [] # The following are executed as part of each plugin run (but not last). ALWAYS_RUN = {'auto_scenario_check': YScenarioChecker} + ALWAYS_RUN['events_preload'] = EventDefsPreloader for name, always_parts in ALWAYS_RUN.items(): # update current env to reflect actual part being run HotSOSConfig.part_name = name diff --git a/hotsos/core/ycheck/events.py b/hotsos/core/ycheck/events.py index dc5fe23e8..5843a3d85 100644 --- a/hotsos/core/ycheck/events.py +++ b/hotsos/core/ycheck/events.py @@ -1,5 +1,6 @@ import abc from functools import cached_property +from collections import UserDict from hotsos.core.config import HotSOSConfig from hotsos.core.log import log @@ -13,6 +14,7 @@ YHandlerBase, YDefsSection, ) +from hotsos.core.ycheck.engine.properties import search from hotsos.core.ycheck.engine.properties.search import CommonTimestampMatcher @@ -225,7 +227,149 @@ def __call__(self): """ Callback method. """ -class EventHandlerBase(YHandlerBase, EventProcessingUtils): +class EventRegistryError(Exception): + def __init__(self, key, all_keys): + self.key = key + self.all_keys = all_keys + + def __str__(self): + return ("Key '{}' not found in event registry. Available keys are:" + "\n - {}". + format(self.key, '\n - '.join(self.all_keys))) + + +class EventsRegistry(UserDict): + + def __getitem__(self, key): + try: + return super().__getitem__(key) + except KeyError: + raise EventRegistryError(key, list(self.data)) from KeyError + + def reset(self): + self.data = {} + + +class EventsBase(object): + _global_searcher = None + _events_registry = EventsRegistry() + + @property + def registry(self): + return self._events_registry + + def get_global_searcher(self, reset=False): + cls = EventsBase + if not reset and cls._global_searcher: + log.error("USING GLOBAL SEARCHER %s", cls._global_searcher) + return cls._global_searcher + + constraint = SearchConstraintSearchSince( + ts_matcher_cls=CommonTimestampMatcher) + searcher = FileSearcher(constraint=constraint) + cls._global_searcher = searcher + log.error("CREATING GLOBAL SEARCHER %s", cls._global_searcher) + return searcher + + def meets_requirements(self, event): + if HotSOSConfig.force_mode: + return True + + if event.requires and not event.requires.result: + log.error("event '%s' pre-requisites not met - " + "skipping", event.name) + return False + + return True + + def skip_filtered_event(self, event_path): + if not HotSOSConfig.event_filter: + return False + + if event_path == HotSOSConfig.event_filter: + return False + + log.info("skipping event %s (filter=%s)", event_path, + HotSOSConfig.event_filter) + return True + + def get_defs(self, group=None): + plugin_defs = YDefsLoader('events').plugin_defs + if not plugin_defs: + return {} + + log.error("loading event defs (group=%s)", group) + group_defs = plugin_defs + if not group: + return group_defs + + group_defs = {group: group_defs[group]} + + # ensure we only include the events we want + for entry in group.split('.'): + group_defs[entry] = group_defs[entry] + + log.error("loaded %s", group_defs) + return group_defs + + def load_searches(self): + self.registry.reset() + global_searcher = self.get_global_searcher(reset=True) + search_props = set() + events = YDefsSection(HotSOSConfig.plugin_name, self.get_defs() or {}) + for prop in events.manager.properties.values(): + for item in prop: + if not issubclass(item['cls'], search.YPropertySearch): + break + + search_props.add(item['path']) + + for proppath in search_props: + if self.skip_filtered_event(proppath): + continue + + s = None + proppath = proppath.partition('.')[2] + event = None + for prop in proppath.split('.'): + if s is None: + s = getattr(events, prop) + else: + s = getattr(s, prop) + + if not s: + continue + + if not isinstance(s, search.YPropertySearch): + event = s + else: + break + + if event.input.command: + # don't apply constraints to command outputs + allow_constraints = False + else: + allow_constraints = True + + for path in event.input.paths: + log.debug("loading search for event %s path %s (tag=%s)", + proppath, + path, event.search.unique_search_tag) + # remove the .search + rkey = proppath.rpartition('.')[0] + # these may be needed later e.g. for sequence lookups + self.registry[rkey] = {'search': event.search} + event.search.load_searcher(global_searcher, path, + allow_constraints=allow_constraints) + + +class EventDefsPreloader(EventsBase): + + def load_and_run(self): + self.load_searches() + + +class EventHandlerBase(EventsBase, YHandlerBase, EventProcessingUtils): """ Root name used to identify a group of event definitions. Once all the yaml definitions are loaded this defines the level below which events @@ -241,10 +385,9 @@ def __init__(self, *args, searcher=None, **kwargs): done at once. """ super().__init__(*args, **kwargs) - if not searcher: - log.debug("creating searcher for event checker") - searcher = FileSearcher(constraint=SearchConstraintSearchSince( - ts_matcher_cls=CommonTimestampMatcher)) + if searcher is None: + log.debug("using global searcher for event checker") + searcher = self.get_global_searcher() self._searcher = searcher self._event_results = None @@ -254,41 +397,20 @@ def searcher(self): return self._searcher @cached_property - def event_definitions(self): + def events(self): """ Load event definitions from yaml. """ - _event_defs = {} - - plugin = YDefsLoader('events').plugin_defs - if not plugin: - return _event_defs - - log.debug("loading defs for subgroup=%s", self.event_group) - ytree = plugin - ypath = self.event_group.split('.') - for i, g in enumerate(ypath): - if i >= len(ypath) - 1: - group_defs = ytree.get(g) - else: - ytree = ytree.get(g) - - group = YDefsSection(self.event_group, group_defs) + group = YDefsSection(HotSOSConfig.plugin_name, + self.get_defs(self.event_group) or {}) log.debug("sections=%s, events=%s", len(list(group.branch_sections)), len(list(group.leaf_sections))) + _events = {} for event in group.leaf_sections: - fullname = "{}.{}.{}".format(HotSOSConfig.plugin_name, - event.parent.name, event.name) - if (HotSOSConfig.event_filter and - fullname != HotSOSConfig.event_filter): - log.info("skipping event %s (filter=%s)", fullname, - HotSOSConfig.event_filter) + if self.skip_filtered_event(event.resolve_path): continue - if (not HotSOSConfig.force_mode and event.requires and not - event.requires.result): - log.error("event '%s' pre-requisites not met - " - "skipping", event.name) + if not self.meets_requirements(event): return {} log.debug("event: %s", event.name) @@ -296,30 +418,16 @@ def event_definitions(self): event.input.command is not None) section_name = event.parent.name - if section_name not in _event_defs: - _event_defs[section_name] = {} - - for path in event.input.paths: - if event.input.command: - # don't apply constraints to command outputs - allow_constraints = False - else: - allow_constraints = True - - event.search.load_searcher(self.searcher, path, - allow_constraints=allow_constraints) + if section_name not in _events: + _events[section_name] = {} - passthrough = bool(event.search.passthrough_results) - emeta = {'passthrough': passthrough, - 'sequence': event.search.sequence_search, - 'tag': event.search.unique_search_tag} - _event_defs[section_name][event.name] = emeta + _events[section_name][event.name] = \ + event.resolve_path.partition('.')[2] - return _event_defs + return _events def load(self): - """ Pre-load event definitions. """ - self.event_definitions + pass @property def final_event_results(self): @@ -340,18 +448,20 @@ def run(self, results): raise Exception("need to register at least one callback for " "event handler.") - log.debug("registered callbacks:\n%s", '\n'.join(CALLBACKS.keys())) + log.debug("registered event callbacks:\n%s", '\n'. + join(CALLBACKS.keys())) info = {} - for section_name, section in self.event_definitions.items(): - for event, event_meta in section.items(): - search_tag = event_meta['tag'] + for section_name, section in self.events.items(): + for event, fullname in section.items(): + event_search = self.registry[fullname]['search'] + search_tag = event_search.unique_search_tag seq_def = None - if event_meta['passthrough']: + if bool(event_search.passthrough_results): # this is for implementations that have their own means of # retrieving results. search_results = results else: - seq_def = event_meta['sequence'] + seq_def = event_search.sequence_search if seq_def: search_results = results.find_sequence_sections( seq_def) @@ -361,7 +471,8 @@ def run(self, results): search_results = results.find_by_tag(search_tag) if not search_results: - log.debug("event %s did not yield any results", event) + log.debug("event %s did not yield any results (tag=%s)", + event, search_tag) continue # We want this to throw an exception if the callback is not diff --git a/tests/unit/storage/test_ceph_mon.py b/tests/unit/storage/test_ceph_mon.py index 0be0a0d8b..a4662dd12 100644 --- a/tests/unit/storage/test_ceph_mon.py +++ b/tests/unit/storage/test_ceph_mon.py @@ -6,6 +6,7 @@ from hotsos.core.plugins.storage import ( ceph as ceph_core, ) +from hotsos.core.ycheck.events import EventDefsPreloader from hotsos.plugin_extensions.storage import ceph_summary, ceph_event_checks from .. import utils @@ -401,6 +402,9 @@ def test_ceph_daemon_log_checker(self, mock_cli): mock_cli.return_value = mock.MagicMock() # ensure log file contents are within allowed timeframe ("since") mock_cli.return_value.date.return_value = "2022-02-10 00:00:00" + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() result = {'osd-reported-failed': {'osd.41': {'2022-02-08': 23}, 'osd.85': {'2022-02-08': 4}}, 'long-heartbeat-pings': {'2022-02-09': 4}, diff --git a/tests/unit/storage/test_ceph_osd.py b/tests/unit/storage/test_ceph_osd.py index dd66842ad..aad748e67 100644 --- a/tests/unit/storage/test_ceph_osd.py +++ b/tests/unit/storage/test_ceph_osd.py @@ -5,6 +5,7 @@ from hotsos.core.plugins.storage import ( ceph as ceph_core, ) +from hotsos.core.ycheck.events import EventDefsPreloader from hotsos.plugin_extensions.storage import ( ceph_summary, ceph_event_checks, @@ -210,6 +211,9 @@ def test_ceph_daemon_log_checker(self, mock_cli): mock_cli.return_value = mock.MagicMock() # ensure log file contents are within allowed timeframe ("since") mock_cli.return_value.date.return_value = "2021-01-01 00:00:00" + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() result = {'crc-err-bluestore': {'2021-02-12': 5, '2021-02-13': 1}, 'crc-err-rocksdb': {'2021-02-12': 7}} inst = ceph_event_checks.CephEventHandler() diff --git a/tests/unit/test_openstack.py b/tests/unit/test_openstack.py index f237a1087..1086aca49 100644 --- a/tests/unit/test_openstack.py +++ b/tests/unit/test_openstack.py @@ -7,6 +7,7 @@ import hotsos.core.plugins.openstack as openstack_core import hotsos.core.plugins.openstack.nova as nova_core import hotsos.core.plugins.openstack.neutron as neutron_core +from hotsos.core.ycheck.events import EventDefsPreloader from hotsos.plugin_extensions.openstack import ( vm_info, nova_external_events, @@ -678,6 +679,9 @@ def test_get_vm_checks(self): "used": 1, "overcommit-factor": 0.5}} } + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = vm_info.OpenstackInstanceChecks() actual = self.part_output_to_actual(inst.output) self.assertEqual(actual, expected) @@ -694,6 +698,9 @@ def test_vm_migration_analysis(self): 'disk': 0}, 'iterations': 1}] }}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = vm_info.NovaServerMigrationAnalysis() actual = self.part_output_to_actual(inst.output) self.assertEqual(actual, expected) @@ -702,6 +709,9 @@ def test_vm_migration_analysis(self): class TestOpenstackNovaExternalEvents(TestOpenstackBase): def test_get_events(self): + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = nova_external_events.NovaExternalEventChecks() events = {'network-changed': {"succeeded": diff --git a/tests/unit/test_openvswitch.py b/tests/unit/test_openvswitch.py index 620c32d29..4120397da 100644 --- a/tests/unit/test_openvswitch.py +++ b/tests/unit/test_openvswitch.py @@ -7,6 +7,7 @@ from hotsos.core.issues.utils import IssuesStore from hotsos.core.plugins.openvswitch import OpenvSwitchBase, OVSDB from hotsos.core.ycheck.scenarios import YScenarioChecker +from hotsos.core.ycheck.events import EventDefsPreloader from hotsos.plugin_extensions.openvswitch import ( event_checks, summary, @@ -269,6 +270,9 @@ def test_ovs_vswitchd_checks(self): {'2022-02-10': 3}, 'bridge-no-such-device': { '2022-02-10': {'tap6a0486f9-82': 1}}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVSEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -284,6 +288,9 @@ def test_ovs_vswitchd_assertion_failures(self): 'ovs-vswitchd': { 'assertion-failures': {'2023-06-08': 2}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVSEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -303,6 +310,9 @@ def test_ovs_common_log_checks(self): '2022-02-04': 6, '2022-02-09': 2, '2022-02-10': 4}}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVSEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -319,6 +329,9 @@ def test_ovs_emer_log_checks(self): 'ovs-vswitchd': { 'EMER': { '2023-06-08': 2}}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVSEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -336,6 +349,9 @@ def test_ovs_dp_checks(self): 'RX': { 'dropped': 1394875, 'packets': 309}}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVSEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -363,7 +379,9 @@ def test_ovn_central_checks(self): '2022-02-16': 2, '2022-02-17': 1} }} - + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVNEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -382,6 +400,9 @@ def test_ovn_controller_checks(self): '2022-02-16': {'provnet-aa3a4fec-a788-42e6-a773-bf3a0cdb52c2': 1}}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVNEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -402,7 +423,9 @@ def test_ovn_common_log_checks(self): 'ovsdb-server-sb': { 'ERR': {'2022-02-16': 2, '2022-02-17': 2}, 'WARN': {'2022-02-16': 23, '2022-02-17': 23}}}} - + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVNEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -422,6 +445,9 @@ def test_ovs_bfd_state_changes(self): '2022-07-27': {'ovn-abc-xb-0': 1, 'ovn-abc-xa-2': 1, 'ovn-abc-xa-15': 3}}}}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVSEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -438,6 +464,9 @@ def test_ovn_ovsdb_leadership_changes(self): '2022-07-27': 2}}, 'ovsdb-server-sb': {'leadership-transfers': { '2022-07-27': 2}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVNEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -450,6 +479,9 @@ def test_ovn_ovsdb_leadership_changes(self): def test_ovn_northd_leadership_changes(self): expected = {'ovn-northd': {'leadership-acquired': { '2023-12-13': 2}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVNEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -466,6 +498,9 @@ def test_ovn_ovsdb_compactions(self): '2022-07-13': 3}}, 'ovsdb-server-sb': {'compactions': { '2022-07-14': 3}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVNEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) @@ -479,6 +514,9 @@ def test_ovs_defferred_action_limit_reached(self): 'deferred-action-limit-reached': { 'ovs-system': {'Mar 3': 7}}}} + # NOTE: this has to be done AFTER the data root is set hence why we do + # it here. + EventDefsPreloader().load_searches() inst = event_checks.OVSEventChecks() self.assertEqual(self.part_output_to_actual(inst.output), expected) diff --git a/tests/unit/test_ycheck_events.py b/tests/unit/test_ycheck_events.py index 20a2037e8..5ebb0348c 100644 --- a/tests/unit/test_ycheck_events.py +++ b/tests/unit/test_ycheck_events.py @@ -4,6 +4,7 @@ from hotsos.core.config import HotSOSConfig from hotsos.core.ycheck.engine import YDefsSection from hotsos.core.ycheck.events import ( + EventDefsPreloader, EventHandlerBase, EventCallbackBase, EventCallbackNotFound, @@ -263,3 +264,7 @@ def event_group(self): defs = {} self.assertEqual(MyEventHandler().event_definitions, defs) + + def test_events_preloader(self): + HotSOSConfig.plugin_name = 'openvswitch' + self.assertEqual(EventDefsPreloader().load_searches(), {})