Merge pull request DiamondLightSource/hyperion#1104 from DiamondLight…

…Source/v8_7_fixes

v8.7 bugfixes from beamline testing

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=()

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 =

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,

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)

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

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)
 
 

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

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

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

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

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