V2: include hooks functionality for logging/monitoring

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

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

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

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

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

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 (

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