diff --git a/src/ibex_bluesky_core/run_engine/_msg_handlers.py b/src/ibex_bluesky_core/run_engine/_msg_handlers.py index d16bcbb..8c82178 100644 --- a/src/ibex_bluesky_core/run_engine/_msg_handlers.py +++ b/src/ibex_bluesky_core/run_engine/_msg_handlers.py @@ -4,12 +4,15 @@ """ import ctypes +import logging import threading from asyncio import CancelledError, Event, get_running_loop from typing import Any from bluesky.utils import Msg +logger = logging.getLogger(__name__) + class _ExternalFunctionInterrupted(BaseException): """An external sync function running in a worker thread is being interrupted.""" @@ -25,23 +28,36 @@ async def call_sync_handler(msg: Msg) -> Any: # noqa: ANN401 def _wrapper() -> Any: # noqa: ANN401 nonlocal ret, exc + logger.info("Running '{func.__name__}' with args=({msg.args}), kwargs=({msg.kwargs})") try: ret = func(*msg.args, **msg.kwargs) + logger.debug("Running '%s' successful", func.__name__) except _ExternalFunctionInterrupted: - pass # Suppress stack traces from our special interruption exception. + # Suppress stack traces from our special interruption exception. + logger.debug("Running '%s' was interrupted by user", func.__name__) except BaseException as e: + logger.error("Running '%s' failed with %s: %s", func.__name__, e.__class__.__name__, e) exc = e finally: loop.call_soon_threadsafe(done_event.set) + logger.info( + "Spawning thread to run '%s' with args=(%s), kwargs=(%s)", + func.__name__, + msg.args, + msg.kwargs, + ) worker_thread = threading.Thread(target=_wrapper, name="external_function_worker", daemon=True) worker_thread.start() try: # Wait until done event is set. # Ensure we're not blocking the whole event loop while waiting. + logger.debug("Waiting for event to be set") await done_event.wait() + logger.debug("event set") except (KeyboardInterrupt, CancelledError): + logger.info("Interrupted during execution of %s", func.__name__) # We got interrupted while the external function thread was running. # # A few options: @@ -75,5 +91,6 @@ def _wrapper() -> Any: # noqa: ANN401 assert n_threads <= 1, f"Raised async exception in multiple ({n_threads}) threads!" raise if exc is not None: + logger.debug("Re-raising %s thrown by %s", exc.__class__.__name__, func.__name__) raise exc return ret