diff --git a/run_hyperion.sh b/run_hyperion.sh index 8e49d13d9..b44d48886 100755 --- a/run_hyperion.sh +++ b/run_hyperion.sh @@ -135,9 +135,9 @@ if [[ $START == 1 ]]; then ["VERBOSE_EVENT_LOGGING"]="--verbose-event-logging" ["EXTERNAL_CALLBACK_SERVICE"]="--external-callbacks") - declare -A h_and_cb_args( ["IN_DEV"]="$IN_DEV" + declare -A h_and_cb_args=( ["IN_DEV"]="$IN_DEV" ["LOGGING_LEVEL"]="$LOGGING_LEVEL" ) - declare -A h_and_cb_arg_strings( ["IN_DEV"]="--dev" + declare -A h_and_cb_arg_strings=( ["IN_DEV"]="--dev" ["LOGGING_LEVEL"]="--logging-level=$LOGGING_LEVEL" ) h_commands=() diff --git a/setup.cfg b/setup.cfg index 31a43e646..aa07251c1 100644 --- a/setup.cfg +++ b/setup.cfg @@ -38,7 +38,7 @@ install_requires = dls-dodal @ git+https://github.com/DiamondLightSource/dodal.git@0aabdb389f65a30e629cec60a36c3b5298b7647f pydantic<2.0 # See https://github.com/DiamondLightSource/hyperion/issues/774 scipy - pyzmq + pyzmq<25 # See https://github.com/DiamondLightSource/hyperion/issues/1103 [options.entry_points] console_scripts = diff --git a/src/hyperion/__main__.py b/src/hyperion/__main__.py index 9fdcdfeac..235834b74 100755 --- a/src/hyperion/__main__.py +++ b/src/hyperion/__main__.py @@ -14,6 +14,9 @@ from hyperion.exceptions import WarningException from hyperion.experiment_plans.experiment_registry import PLAN_REGISTRY, PlanNotFound +from hyperion.external_interaction.callbacks.__main__ import ( + setup_logging as setup_callback_logging, +) from hyperion.external_interaction.callbacks.abstract_plan_callback_collection import ( AbstractPlanCallbackCollection, ) @@ -24,7 +27,7 @@ VerbosePlanExecutionLoggingCallback, ) from hyperion.log import LOGGER, set_up_logging_handlers -from hyperion.parameters.cli import parse_cli_args +from hyperion.parameters.cli import parse_callback_cli_args, parse_cli_args from hyperion.parameters.constants import CALLBACK_0MQ_PROXY_PORTS, Actions, Status from hyperion.parameters.internal_parameters import InternalParameters from hyperion.tracing import TRACER @@ -155,6 +158,9 @@ def wait_on_queue(self): and command.callbacks and (cbs := list(command.callbacks.setup())) ): + LOGGER.info( + f"Using callbacks for this plan: {not self.use_external_callbacks} - {cbs}" + ) self.subscribed_per_plan_callbacks += [ self.RE.subscribe(cb) for cb in cbs ] @@ -295,9 +301,9 @@ def create_app( def create_targets(): hyperion_port = 5005 args = parse_cli_args() - set_up_logging_handlers( - logger=LOGGER, logging_level=args.logging_level, dev_mode=args.dev_mode - ) + set_up_logging_handlers(logging_level=args.logging_level, dev_mode=args.dev_mode) + if not args.use_external_callbacks: + setup_callback_logging(parse_callback_cli_args()) app, runner = create_app( skip_startup_connection=args.skip_startup_connection, use_external_callbacks=args.use_external_callbacks, diff --git a/src/hyperion/device_setup_plans/check_topup.py b/src/hyperion/device_setup_plans/check_topup.py index 496832443..aa75f76c5 100644 --- a/src/hyperion/device_setup_plans/check_topup.py +++ b/src/hyperion/device_setup_plans/check_topup.py @@ -41,6 +41,7 @@ def _delay_to_avoid_topup(total_run_time, time_to_topup): def wait_for_topup_complete(synchrotron): + LOGGER.info("Waiting for topup to complete") start = yield from bps.rd(synchrotron.top_up.start_countdown) while start == COUNTDOWN_DURING_TOPUP: yield from bps.sleep(0.1) diff --git a/src/hyperion/experiment_plans/experiment_registry.py b/src/hyperion/experiment_plans/experiment_registry.py index f8dbaf09d..112257097 100644 --- a/src/hyperion/experiment_plans/experiment_registry.py +++ b/src/hyperion/experiment_plans/experiment_registry.py @@ -95,7 +95,7 @@ class ExperimentRegistryEntry(TypedDict): "setup": grid_detect_then_xray_centre_plan.create_devices, "internal_param_type": GridScanWithEdgeDetectInternalParameters, "experiment_param_type": GridScanWithEdgeDetectParams, - "callback_collection_type": NullPlanCallbackCollection, + "callback_collection_type": XrayCentreCallbackCollection, }, "rotation_scan": { "setup": rotation_scan_plan.create_devices, @@ -107,7 +107,7 @@ class ExperimentRegistryEntry(TypedDict): "setup": pin_centre_then_xray_centre_plan.create_devices, "internal_param_type": PinCentreThenXrayCentreInternalParameters, "experiment_param_type": PinCentreThenXrayCentreParams, - "callback_collection_type": NullPlanCallbackCollection, + "callback_collection_type": XrayCentreCallbackCollection, }, "stepped_grid_scan": { "setup": stepped_grid_scan_plan.create_devices, @@ -119,7 +119,7 @@ class ExperimentRegistryEntry(TypedDict): "setup": wait_for_robot_load_then_centre_plan.create_devices, "internal_param_type": WaitForRobotLoadThenCentreInternalParameters, "experiment_param_type": WaitForRobotLoadThenCentreParams, - "callback_collection_type": NullPlanCallbackCollection, + "callback_collection_type": XrayCentreCallbackCollection, }, } EXPERIMENT_NAMES = list(PLAN_REGISTRY.keys()) diff --git a/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py b/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py index 4d1fdc5a5..0e9e832a9 100755 --- a/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py +++ b/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py @@ -208,15 +208,19 @@ def do_fgs(): total_exposure = ( parameters.experiment_params.get_num_images() * dwell_time_in_s ) # Expected exposure time for full scan + LOGGER.info("waiting for topup if necessary...") yield from check_topup_and_wait_if_necessary( fgs_composite.synchrotron, total_exposure, 30.0, ) + LOGGER.info("kicking off FGS") yield from bps.kickoff(fgs_motors) + LOGGER.info("Waiting for Zocalo device queue to have been cleared...") yield from bps.wait( ZOCALO_STAGE_GROUP ) # Make sure ZocaloResults queue is clear and ready to accept our new data + LOGGER.info("completing FGS") yield from bps.complete(fgs_motors, wait=True) LOGGER.info("Waiting for arming to finish") @@ -225,7 +229,6 @@ def do_fgs(): with TRACER.start_span("do_fgs"): yield from do_fgs() - yield from bps.abs_set(fgs_motors.z_steps, 0, wait=False) diff --git a/src/hyperion/external_interaction/callbacks/__main__.py b/src/hyperion/external_interaction/callbacks/__main__.py index dfd265393..ef4f1d9f5 100644 --- a/src/hyperion/external_interaction/callbacks/__main__.py +++ b/src/hyperion/external_interaction/callbacks/__main__.py @@ -24,7 +24,7 @@ XrayCentreZocaloCallback, ) from hyperion.log import ISPYB_LOGGER, NEXUS_LOGGER, set_up_logging_handlers -from hyperion.parameters.cli import parse_callback_cli_args +from hyperion.parameters.cli import CallbackArgs, parse_callback_cli_args from hyperion.parameters.constants import CALLBACK_0MQ_PROXY_PORTS LIVENESS_POLL_SECONDS = 1 @@ -43,20 +43,16 @@ def setup_callbacks(): ] -def setup_logging(logging_args): - ( - logging_level, - dev_mode, - ) = logging_args +def setup_logging(logging_args: CallbackArgs): set_up_logging_handlers( - logging_level=logging_level, - dev_mode=dev_mode, + logging_level=logging_args.logging_level, + dev_mode=logging_args.dev_mode, filename="hyperion_ispyb_callback.txt", logger=ISPYB_LOGGER, ) set_up_logging_handlers( - logging_level=logging_level, - dev_mode=dev_mode, + logging_level=logging_args.logging_level, + dev_mode=logging_args.dev_mode, filename="hyperion_nexus_callback.txt", logger=NEXUS_LOGGER, ) @@ -130,6 +126,7 @@ def start(self): def main(logging_args=None) -> None: logging_args = logging_args or parse_callback_cli_args() + print(f"using logging args {logging_args}") runner = HyperionCallbackRunner(logging_args) runner.start() diff --git a/src/hyperion/external_interaction/callbacks/abstract_plan_callback_collection.py b/src/hyperion/external_interaction/callbacks/abstract_plan_callback_collection.py index eb4a763e0..a65034ba2 100644 --- a/src/hyperion/external_interaction/callbacks/abstract_plan_callback_collection.py +++ b/src/hyperion/external_interaction/callbacks/abstract_plan_callback_collection.py @@ -28,3 +28,6 @@ class NullPlanCallbackCollection(AbstractPlanCallbackCollection): @classmethod def setup(cls): return cls() + + def __iter__(self): + yield from () diff --git a/src/hyperion/log.py b/src/hyperion/log.py index ced0a6340..a71c1618f 100755 --- a/src/hyperion/log.py +++ b/src/hyperion/log.py @@ -50,10 +50,13 @@ def set_up_logging_handlers( logger.handlers.clear() logger.filters.clear() dodal_logger.filters.clear() + print( + f"setting up handler with level {logging_level} dev mode {dev_mode} path {filename}" + ) handlers = setup_dodal_logging( - logging_level, - dev_mode, - _get_logging_file_path(filename), + logging_level=logging_level, + dev_mode=dev_mode, + logging_path=_get_logging_file_path(filename), file_handler_logging_level="DEBUG", logger=logger, ) diff --git a/src/hyperion/parameters/cli.py b/src/hyperion/parameters/cli.py index 81c3fd5d7..a2cb4b2d3 100644 --- a/src/hyperion/parameters/cli.py +++ b/src/hyperion/parameters/cli.py @@ -5,17 +5,17 @@ @dataclass class CallbackArgs: - logging_level: str - dev_mode: bool + logging_level: str = "INFO" + dev_mode: bool = False @dataclass class HyperionArgs: - logging_level: str - dev_mode: bool - use_external_callbacks: bool - verbose_event_logging: bool - skip_startup_connection: bool + logging_level: str = "INFO" + dev_mode: bool = False + use_external_callbacks: bool = False + verbose_event_logging: bool = False + skip_startup_connection: bool = False def add_callback_relevant_args(parser: argparse.ArgumentParser) -> None: @@ -37,7 +37,9 @@ def parse_callback_cli_args() -> CallbackArgs: parser = argparse.ArgumentParser() add_callback_relevant_args(parser) args = parser.parse_args() - return CallbackArgs(logging_level=args.logging_level, dev_mode=args.dev) + return CallbackArgs( + logging_level=args.logging_level or "INFO", dev_mode=args.dev or False + ) def parse_cli_args() -> HyperionArgs: @@ -61,9 +63,9 @@ def parse_cli_args() -> HyperionArgs: ) args = parser.parse_args() return HyperionArgs( - logging_level=args.logging_level, - verbose_event_logging=args.verbose_event_logging, - dev_mode=args.dev, - skip_startup_connection=args.skip_startup_connection, - use_external_callbacks=args.external_callbacks, + logging_level=args.logging_level or "INFO", + verbose_event_logging=args.verbose_event_logging or False, + dev_mode=args.dev or False, + skip_startup_connection=args.skip_startup_connection or False, + use_external_callbacks=args.external_callbacks or False, ) diff --git a/tests/unit_tests/external_interaction/callbacks/test_external_callbacks.py b/tests/unit_tests/external_interaction/callbacks/test_external_callbacks.py index 99e549dec..9f7f67791 100644 --- a/tests/unit_tests/external_interaction/callbacks/test_external_callbacks.py +++ b/tests/unit_tests/external_interaction/callbacks/test_external_callbacks.py @@ -13,6 +13,7 @@ setup_threads, ) from hyperion.log import ISPYB_LOGGER, NEXUS_LOGGER +from hyperion.parameters.cli import CallbackArgs @patch( @@ -46,7 +47,7 @@ def test_setup_callbacks(): @pytest.mark.skip_log_setup @patch( "hyperion.external_interaction.callbacks.__main__.parse_callback_cli_args", - return_value=("DEBUG", True), + return_value=CallbackArgs(logging_level="DEBUG", dev_mode=True), ) def test_setup_logging(parse_callback_cli_args): assert len(ISPYB_LOGGER.handlers) == 0