From d86815c8a2e987cf62ad7d61d78984db5f702d18 Mon Sep 17 00:00:00 2001 From: Fergus Morrow Date: Sat, 14 Aug 2021 17:53:23 +0100 Subject: [PATCH] v2: include hooks functionality for logging/monitoring --- algorunner/hooks.py | 75 ++++++++++++++++ algorunner/monitoring.py | 22 +++++ test/scenarios/environment.py | 10 +++ test/scenarios/hooks.feature | 53 +++++++++++ test/scenarios/steps/hooks.py | 139 +++++++++++++++++++++++++++++ test/scenarios/steps/sync_agent.py | 1 - test/test_monitoring.py | 27 ++++++ 7 files changed, 326 insertions(+), 1 deletion(-) create mode 100644 algorunner/hooks.py create mode 100644 algorunner/monitoring.py create mode 100644 test/scenarios/environment.py create mode 100644 test/scenarios/hooks.feature create mode 100644 test/scenarios/steps/hooks.py create mode 100644 test/test_monitoring.py diff --git a/algorunner/hooks.py b/algorunner/hooks.py new file mode 100644 index 0000000..b165369 --- /dev/null +++ b/algorunner/hooks.py @@ -0,0 +1,75 @@ +from enum import Enum +from typing import Callable, Optional + +from loguru import logger + + +class Hook(Enum): + """Hook represents valid hooks for user-defined functions to listen + for.""" + PROCESS_DURATION = 1 + API_EXECUTE_DURATION = 2 + + +class InvalidHookHandler(Exception): + """Raised when `hook_handler` is unable to register a given hook.""" + pass + + +CALLBACK_TYPES = { + Hook.PROCESS_DURATION: Callable[[float], None], + Hook.API_EXECUTE_DURATION: Callable[[float], None], +} + +# @todo We have a few of these registry decorations now; place in one class? +_registered_hooks = {} + + +def hook_handler(hook: Hook): + """`hook_handler` is a decorator to go wrap around a hook handler.""" + def register(fn): + if not hook: + raise InvalidHookHandler(f"no hook specified for '{fn.__name}'") + + expected_callback = CALLBACK_TYPES.get(hook) + if not expected_callback: + raise InvalidHookHandler(f"unknown hook specified ('{hook}')") + + if not callable(fn): + raise InvalidHookHandler(f"invalid hook supplied for '{hook}") + + callbacks = _registered_hooks.get(hook, []) + callbacks.append(fn) + _registered_hooks[hook] = callbacks + + return register + + +def hook(hook: Hook, *args, **kwargs): + """`hook(...)` calls any handlers associated with a given Hook.""" + callbacks = _registered_hooks.get(hook, []) + for cb in callbacks: + try: + cb(*args, **kwargs) + except TypeError: + logger.error(f"invalid handler ({cb.__name__}) for hook ({hook})") + + +def clear_handlers(hook: Optional[Hook] = None): + """`clear_handlers` clears registered handlers; optionally for + a specific hook""" + if hook and _registered_hooks.get(hook): + _registered_hooks[hook] = [] + return + + _registered_hooks.clear() + + +@hook_handler(hook=Hook.API_EXECUTE_DURATION) +def handle_api_duration(duration: float): + logger.debug(f"api execution duration: {duration}ms") + + +@hook_handler(hook=Hook.PROCESS_DURATION) +def handle_process_duration(duration: float): + logger.debug(f"tick process duration: {duration}ms") diff --git a/algorunner/monitoring.py b/algorunner/monitoring.py new file mode 100644 index 0000000..7422141 --- /dev/null +++ b/algorunner/monitoring.py @@ -0,0 +1,22 @@ +from time import time + +from loguru import logger + + +class Timer: + """Simple timer based context manager, used for performance monitoring + in conjunction with hooks.""" + def __init__(self): + self.duration = None + + def __enter__(self): + self.start = time() + + def __exit__(self, exc_type, exc_val, traceback): + self.duration = (time() - self.start) + + if exc_type: + logger.error(f"detected exception during monitoring: {exc_type} ({exc_val})") + + def ms(self) -> float: + return self.duration * 1000 diff --git a/test/scenarios/environment.py b/test/scenarios/environment.py new file mode 100644 index 0000000..1a8f3ed --- /dev/null +++ b/test/scenarios/environment.py @@ -0,0 +1,10 @@ +from unittest.mock import patch + +def before_feature(context, feature): + if 'mock_logger' in feature.tags: + context._mock_logger = patch("algorunner.hooks.logger") + context.mock_logger = context._mock_logger.__enter__() + +def after_feature(context, feature): + if 'mock_logger' in feature.tags: + context._mock_logger.__exit__((None,)) diff --git a/test/scenarios/hooks.feature b/test/scenarios/hooks.feature new file mode 100644 index 0000000..4e4c957 --- /dev/null +++ b/test/scenarios/hooks.feature @@ -0,0 +1,53 @@ +@mock_logger +Feature: Hooks + Hooks allow user-defined handlers to internal events in the AlgoRunner. + + Scenario: An invalid handler should be rejected + Given no handlers are registered + and a handler that isn't callable + When that handler is registered + Then an InvalidHookHandler exception is raised + + Scenario: Hook type should be validated when registering handler + Given no handlers are registered + and a valid handler for an unknown hook + When that handler is registered + Then an InvalidHookHandler exception is raised + + @intercepts_error + Scenario: Invalid handler signactures trigger logging warning + Given no handlers are registered + Given an invalid handler with a different signature + and logging is enabled + When that handler is registered + and the process_duration hook is triggered + Then the logger recieves an error message + + Scenario: A valid hook should be registered and triggered + Given no handlers are registered + Given a valid handler for process_duration + When that handler is registered + and the process_duration hook is triggered + Then no exception should be raised + and the logger recieves no errors + and the handler should be called + and the handler should have the correct argument + + Scenario: Multiple hooks should all be called + Given no handlers are registered + and 5 valid handlers for process_duration + When those handlers are registered + and the process_duration hook is triggered + Then no exception should be raised + and the logger recieves no errors + and the handlers should all be called + and the handlers should have the correct argument + + Scenario: Handlers should be called per-hook trigger + Given no handlers are registered + and a valid handler for process_duration + When that handler is registered + and the process_duration hook is triggered 5 times + Then no exception should be raised + and the logger recieves no errors + and the handler should be called 5 times diff --git a/test/scenarios/steps/hooks.py b/test/scenarios/steps/hooks.py new file mode 100644 index 0000000..b4bb75f --- /dev/null +++ b/test/scenarios/steps/hooks.py @@ -0,0 +1,139 @@ +from behave import * + +from algorunner.hooks import ( + hook_handler, clear_handlers, hook, + Hook, InvalidHookHandler +) + + +class not_callable(): + pass + + +def has_wrong_signature(ex: str, am: int, ple: dict) -> int: + return 5 + + +class valid_handler: + def __init__(self): + self.was_called = False + self.arg = None + self.call_times = 0 + + def __call__(self, duration: float) -> None: + self.call_times += 1 + self.was_called = True + self.arg = duration + + +## GIVEN + + +@given(u'no handlers are registered') +def no_registered_handlers(context): + clear_handlers() + +@given(u'a handler that isn\'t callable') +def non_callable_handler(context): + context.handlers = [not_callable()] + +@given(u'{num:d} valid handlers for process_duration') +def multiple_valid_handlers(context, num): + context.handlers = [valid_handler() for _ in range(num)] + +@given(u'an invalid handler with a different signature') +def wrong_signature_handler(context): + context.handlers = [has_wrong_signature] + +@given(u'a valid handler for an unknown hook') +def valid_handler_unknown_hook(context): + context.hook = "ewfgheruihuier" + context.handlers = [valid_handler()] + +@given(u'a valid handler for process_duration') +def valid_process_duration_handler(context): + context.handlers = [valid_handler()] + + +## WHEN + + +@when(u'that handler is registered') +def handler_registered(context): + handlers_registered(context) + +@when(u'the process_duration hook is triggered') +def trigger_hook(context): + context.logger_has_error = False + context.hook_param = 3.242 + + context.mock_logger.error.call_count = 0 + hook(Hook.PROCESS_DURATION, context.hook_param) + context.logger_has_error = (context.mock_logger.error.call_count == 1) + +@when(u'those handlers are registered') +def handlers_registered(context): + context.have_exception = False + context.have_hook_exception = False + + try: + register_fn = hook_handler(getattr(context, "hook", Hook.PROCESS_DURATION)) + for handler in context.handlers: + register_fn(handler) + except InvalidHookHandler: + context.have_exception = True + context.have_hook_exception = True + except Exception: + context.have_exception = True + +@when(u'the process_duration hook is triggered {times:d} times') +def step_impl(context, times): + for _ in range(times): + trigger_hook(context) + +@given(u'logging is enabled') +def logging_enabled(context): + pass + + +## THEN + + +@then(u'an InvalidHookHandler exception is raised') +def hook_handler_exception_raised(context): + assert context.have_hook_exception + +@then(u'the handlers should have the correct argument') +def handlers_argument(context): + for handler in context.handlers: + assert handler.arg == context.hook_param + +@then(u'the handler should have the correct argument') +def handler_argument(context): + handlers_argument(context) + +@then(u'no exception should be raised') +def no_exception_raised(context): + assert not context.have_exception + +@then(u'the handlers should all be called') +def handlers_called(context): + for handler in context.handlers: + assert handler.was_called + +@then(u'the handler should be called') +def handler_called(context): + handlers_called(context) + +@then(u'the handler should be called {times:d} times') +def handler_called_multiple_times(context, times): + for handler in context.handlers: + assert handler.call_times == times + +@then(u'the logger recieves no errors') +def logger_has_no_errors(context): + assert context.logger_has_error == False + +@then(u'the logger recieves an error message') +def logger_has_errors(context): + assert context.logger_has_error \ No newline at end of file diff --git a/test/scenarios/steps/sync_agent.py b/test/scenarios/steps/sync_agent.py index 1c6e467..82265b9 100644 --- a/test/scenarios/steps/sync_agent.py +++ b/test/scenarios/steps/sync_agent.py @@ -2,7 +2,6 @@ from unittest import mock from time import sleep -from loguru import logger from behave import * from algorunner.abstract import ( diff --git a/test/test_monitoring.py b/test/test_monitoring.py new file mode 100644 index 0000000..3cf74ee --- /dev/null +++ b/test/test_monitoring.py @@ -0,0 +1,27 @@ +from unittest.mock import patch + +from algorunner.monitoring import Timer + +def test_timer_returns_duration_in_ms(): + with patch('algorunner.monitoring.time') as time_mock: + time_mock.side_effect = [2, 3] + + t = Timer() + with t: + pass + + assert t.ms() == 1000 + +def test_timer_bubbles_exceptions(): + have_exc = False + + with patch('algorunner.monitoring.logger') as logger_mock: + try: + t = Timer() + with t: + raise Exception() + except Exception: + have_exc = True + + assert logger_mock.error.call_count == 1 + assert have_exc