From 3618db4fac71c9e9ed3aba1492a9203b75a4781a 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 | 274 ++++++++++++++---- .../events/openstack/neutron/ml2-routers.yaml | 2 +- .../openstack/agent/events.py | 9 +- tests/unit/test_openstack.py | 12 +- tests/unit/test_ycheck_events.py | 66 +++-- tests/unit/utils.py | 4 + 8 files changed, 269 insertions(+), 105 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..c67ff1319 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 @@ -27,6 +29,17 @@ class EventCallbackNotFound(Exception): pass +class EventsSearchRegistryKeyNotFound(Exception): + def __init__(self, key, all_keys): + self.key = key + self.all_keys = all_keys + + def __str__(self): + return ("'{}' not found in event registry. Available keys are:" + "\n - {}". + format(self.key, '\n - '.join(self.all_keys))) + + class EventCallbackMeta(type): def __init__(cls, _name, _mro, members): @@ -225,7 +238,167 @@ def __call__(self): """ Callback method. """ -class EventHandlerBase(YHandlerBase, EventProcessingUtils): +class EventsSearchRegistry(UserDict): + _global_searcher = None + _custom_searcher = None + + def __getitem__(self, key): + try: + return super().__getitem__(key) + except KeyError: + raise EventsSearchRegistryKeyNotFound( + key, + list(self.data)) from KeyError + + @classmethod + def set_custom_searcher(cls, searcher): + cls._custom_searcher = searcher + + @classmethod + def reset_searchers(cls): + cls._global_searcher = None + cls._custom_searcher = None + + def reset(self): + log.debug("resetting events registry") + self.reset_searchers() + self.data = {} + + +class EventsBase(object): + _events_registry = EventsSearchRegistry() + + @property + def registry(self): + return self._events_registry + + @classmethod + def reset_global_searcher(cls): + log.info("resetting events global searcher") + cls._events_registry.reset() + + def get_global_searcher(self, allow_create=True): + if self.registry._global_searcher is None and not allow_create: + return + + if self.registry._global_searcher: + log.debug("using existing global searcher (%s)", + self.registry._global_searcher) + return self.registry._global_searcher + + constraint = SearchConstraintSearchSince( + ts_matcher_cls=CommonTimestampMatcher) + searcher = FileSearcher(constraint=constraint) + EventsSearchRegistry._global_searcher = searcher + log.debug("creating new global searcher (%s)", searcher) + return searcher + + def meets_requirements(self, event): + if HotSOSConfig.force_mode: + return True + + if event.requires and not event.requires.result: + log.debug("event '%s' pre-requisites not met - " + "skipping", event.name) + return False + + return True + + def skip_filtered_event(self, event_path): + e_filter = HotSOSConfig.event_filter + if e_filter and event_path != e_filter: + log.info("skipping event %s (filter=%s)", event_path, e_filter) + return True + + return False + + def get_defs(self, group=None): + plugin_defs = YDefsLoader('events').plugin_defs + if not plugin_defs: + return {} + + log.debug("loading event defs (group=%s)", group) + group_defs = plugin_defs + if not group: + return group_defs + + # ensure we only include the events we want + groups = group.split('.') + for i, _group in enumerate(groups): + if i == 0: + group_defs = {_group: group_defs[_group]} + else: + prev = groups[i - 1] + group_defs[prev] = {_group: group_defs[prev][_group]} + + return group_defs + + def load_searches(self, group=None, searcher=None): + if searcher is None: + self.registry.reset() + searcher = self.get_global_searcher() + + log.debug("started loading event (group=%s) searches into searcher " + "(%s)", group, searcher) + + search_props = set() + events = YDefsSection(HotSOSConfig.plugin_name, + self.get_defs(group) 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']) + + if len(search_props) > 0: + log.debug("loading searches for %s events", len(search_props)) + for event_search_prop_path in search_props: + branch = None + event = None + # skip plugin name at start and skip ".search" at the end. + for node in event_search_prop_path.split('.')[1:-1]: + if branch is None: + branch = getattr(events, node) + else: + branch = getattr(branch, node) + + # the last one will be the one we want + event = branch + + if self.skip_filtered_event(event.resolve_path): + log.debug("skipping event %s", event.resolve_path) + continue + + allow_constraints = True + if event.input.command: + # don't apply constraints to command outputs + allow_constraints = False + + for path in event.input.paths: + log.debug("loading search for event %s (path=%s, tag=%s)", + event.resolve_path, + path, event.search.unique_search_tag) + # these may be needed later e.g. for sequence lookups + self.registry[event.resolve_path] = {'search': + event.search} + event.search.load_searcher( + searcher, path, + allow_constraints=allow_constraints) + else: + log.debug("no events found - no searches to load") + + log.debug("finished loading event searches into searcher " + "(registry has %s items)", len(self.registry)) + + +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 +414,26 @@ 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("no searcher provided - using global searcher") + searcher = self.get_global_searcher() + if len(searcher.catalog) == 0: + # This is mainly intended to be useful for unit tests so that + # they don't have to call it in every single test. + log.debug("global searcher catalog is empty so launching " + "pre-load of all event searches") + # NOTE: this is not re-entrant safe + self.load_searches(group=self.event_group) + searcher = self.get_global_searcher() + else: + # If a searcher is provided we clear the global searcher and + # registry. + if (self.get_global_searcher(allow_create=False) or + self.registry._custom_searcher != searcher): + self.registry.reset() + self.registry.set_custom_searcher(searcher) + + self.load_searches(group=self.event_group, searcher=searcher) self._searcher = searcher self._event_results = None @@ -254,41 +443,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 +464,15 @@ 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 - return _event_defs + return _events def load(self): - """ Pre-load event definitions. """ - self.event_definitions + pass @property def final_event_results(self): @@ -340,18 +493,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 +516,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/hotsos/defs/events/openstack/neutron/ml2-routers.yaml b/hotsos/defs/events/openstack/neutron/ml2-routers.yaml index f21a87c1d..499e51403 100644 --- a/hotsos/defs/events/openstack/neutron/ml2-routers.yaml +++ b/hotsos/defs/events/openstack/neutron/ml2-routers.yaml @@ -4,6 +4,6 @@ l3ha: input: command: journalctl options: - args-callback: hotsos.plugin_extensions.openstack.agent.events.NeutronL3HAEventChecks.journalctl_args + args-callback: hotsos.plugin_extensions.openstack.agent.events.NeutronL3HAEventCheckJournalCtl.args # timestamp at start of line will be in journalctl -oshort-iso format expr: '([\d-]+)T([\d:]+)\S+ \S+ Keepalived_vrrp\[\d+\]: (?:VRRP_Instance)?\(VR_(\d+)\) .+ (\S+) STATE' diff --git a/hotsos/plugin_extensions/openstack/agent/events.py b/hotsos/plugin_extensions/openstack/agent/events.py index 33c9e4736..fb734fc06 100644 --- a/hotsos/plugin_extensions/openstack/agent/events.py +++ b/hotsos/plugin_extensions/openstack/agent/events.py @@ -347,10 +347,9 @@ def __call__(self, event): return {'transitions': transitions}, 'keepalived' -class NeutronL3HAEventChecks(OpenstackEventHandlerBase): - event_group = 'neutron.ml2-routers' +class NeutronL3HAEventCheckJournalCtl(object): - def journalctl_args(self): + def args(self): """ Args callback for event cli command """ args = [] kwargs = {'unit': 'neutron-l3-agent'} @@ -359,6 +358,10 @@ def journalctl_args(self): return args, kwargs + +class NeutronL3HAEventChecks(OpenstackEventHandlerBase): + event_group = 'neutron.ml2-routers' + def __109_summary_neutron_l3ha(self): return self.final_event_results diff --git a/tests/unit/test_openstack.py b/tests/unit/test_openstack.py index f237a1087..21b5beec8 100644 --- a/tests/unit/test_openstack.py +++ b/tests/unit/test_openstack.py @@ -978,10 +978,10 @@ def test_run_octavia_checks(self): '2022-03-09': 1}} } } + inst = agent.events.OctaviaAgentEventChecks() + inst.load_and_run() + actual = self.part_output_to_actual(inst.output) for section_key in ['amp-missed-heartbeats', 'lb-failovers']: - inst = agent.events.OctaviaAgentEventChecks() - inst.load_and_run() - actual = self.part_output_to_actual(inst.output) self.assertEqual(actual["octavia"][section_key], expected[section_key]) @@ -990,10 +990,10 @@ def test_run_octavia_checks(self): def test_run_apache_checks(self): expected = {'connection-refused': { '2021-10-26': {'127.0.0.1:8981': 3}}} + inst = agent.events.ApacheEventChecks() + inst.load_and_run() + actual = self.part_output_to_actual(inst.output) for section_key in ['connection-refused']: - inst = agent.events.ApacheEventChecks() - inst.load_and_run() - actual = self.part_output_to_actual(inst.output) self.assertEqual(actual['apache'][section_key], expected[section_key]) diff --git a/tests/unit/test_ycheck_events.py b/tests/unit/test_ycheck_events.py index 20a2037e8..8591deb95 100644 --- a/tests/unit/test_ycheck_events.py +++ b/tests/unit/test_ycheck_events.py @@ -51,15 +51,14 @@ """ EVENT_DEF_SIMPLE = r""" -myplugin: - myeventgroup: - input: - path: a/path - myeventsubgroup: - event1: - expr: 'event1' - event2: - expr: 'event2' +myeventgroup: + input: + path: a/path + myeventsubgroup: + event1: + expr: 'event1' + event2: + expr: 'event2' """ # noqa EVENT_DEF_MULTI_SEARCH = r""" @@ -206,7 +205,8 @@ def event_group(self): with self.assertRaises(EventCallbackNotFound): MyEventHandler().load_and_run() - @utils.create_data_root({'events/myplugin/mygroup.yaml': EVENT_DEF_SIMPLE}) + @utils.create_data_root({'events/myplugin/mygroup.yaml': EVENT_DEF_SIMPLE, + 'a/path': 'content'}) def test_events_filter_none(self): HotSOSConfig.plugin_yaml_defs = HotSOSConfig.data_root HotSOSConfig.plugin_name = 'myplugin' @@ -217,22 +217,22 @@ class MyEventHandler(EventHandlerBase): def event_group(self): return 'mygroup' - prefix = 'mygroup.myplugin.myeventgroup.myeventsubgroup' defs = {'myeventsubgroup': { - 'event1': { - 'passthrough': False, - 'sequence': None, - 'tag': prefix + '.event1.search'}, - 'event2': { - 'passthrough': False, - 'sequence': None, - 'tag': prefix + '.event2.search'}}} - self.assertEqual(MyEventHandler().event_definitions, defs) - - @utils.create_data_root({'events/myplugin/mygroup.yaml': EVENT_DEF_SIMPLE}) + 'event1': ('myplugin.mygroup.myeventgroup.myeventsubgroup.' + 'event1'), + 'event2': ('myplugin.mygroup.myeventgroup.myeventsubgroup.' + 'event2')}} + + handler = MyEventHandler() + self.assertEqual(handler.events, defs) + self.assertEqual(len(handler.searcher.catalog), 1) + + @utils.create_data_root({'events/myplugin/mygroup.yaml': EVENT_DEF_SIMPLE, + 'a/path': 'content'}) def test_events_filter_event2(self): HotSOSConfig.plugin_yaml_defs = HotSOSConfig.data_root - HotSOSConfig.event_filter = 'myplugin.myeventsubgroup.event2' + HotSOSConfig.event_filter = ('myplugin.mygroup.myeventgroup.' + 'myeventsubgroup.event2') HotSOSConfig.plugin_name = 'myplugin' class MyEventHandler(EventHandlerBase): @@ -241,15 +241,15 @@ class MyEventHandler(EventHandlerBase): def event_group(self): return 'mygroup' - prefix = 'mygroup.myplugin.myeventgroup.myeventsubgroup' defs = {'myeventsubgroup': { - 'event2': { - 'passthrough': False, - 'sequence': None, - 'tag': prefix + '.event2.search'}}} - self.assertEqual(MyEventHandler().event_definitions, defs) - - @utils.create_data_root({'events/myplugin/mygroup.yaml': EVENT_DEF_SIMPLE}) + 'event2': ('myplugin.mygroup.myeventgroup.myeventsubgroup.' + 'event2')}} + handler = MyEventHandler() + self.assertEqual(handler.events, defs) + self.assertEqual(len(handler.searcher.catalog), 1) + + @utils.create_data_root({'events/myplugin/mygroup.yaml': EVENT_DEF_SIMPLE, + 'a/path': 'content'}) def test_events_filter_nonexistent(self): HotSOSConfig.plugin_yaml_defs = HotSOSConfig.data_root HotSOSConfig.event_filter = 'blahblah' @@ -262,4 +262,6 @@ def event_group(self): return 'mygroup' defs = {} - self.assertEqual(MyEventHandler().event_definitions, defs) + handler = MyEventHandler() + self.assertEqual(handler.events, defs) + self.assertEqual(len(handler.searcher.catalog), 0) diff --git a/tests/unit/utils.py b/tests/unit/utils.py index 1d3efab74..855a1f5d3 100644 --- a/tests/unit/utils.py +++ b/tests/unit/utils.py @@ -12,6 +12,7 @@ from hotsos.core.issues import IssuesManager # disable for stestr otherwise output is much too verbose from hotsos.core.log import log, logging, LoggingManager +from hotsos.core.ycheck.events import EventsBase from hotsos.core.ycheck.scenarios import YScenarioChecker # Must be set prior to other imports @@ -451,6 +452,9 @@ def setUp(self): HotSOSConfig.debug_log_levels['searchkit'] = 'WARNING' LoggingManager().start(level=logging.WARNING) + # Always do this to avoid cross-pollution between tests. + EventsBase.reset_global_searcher() + def _addDuration(self, *args, **kwargs): # For Python >= 3.12 """ Python 3.12 needs subclasses of unittest.TestCase to implement this in order to record times and execute any cleanup actions once