From 825206816bc8989ab7f536c0f383e6802cf06560 Mon Sep 17 00:00:00 2001 From: David Perl <115003895+dperl-dls@users.noreply.github.com> Date: Thu, 25 Jan 2024 11:03:54 +0000 Subject: [PATCH 01/10] Update setup.cfg --- setup.cfg | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/setup.cfg b/setup.cfg index 4e7e047d1..406a82d49 100644 --- a/setup.cfg +++ b/setup.cfg @@ -35,7 +35,7 @@ install_requires = xarray doct databroker - dls-dodal @ git+https://github.com/DiamondLightSource/dodal.git@0c0a5e4f475cf88e947be2177e72c1d16d2a392d + dls-dodal=1.13.1 pydantic<2.0 # See https://github.com/DiamondLightSource/hyperion/issues/774 scipy pyzmq From 16191d666455a488b68226e602069a674eb752b5 Mon Sep 17 00:00:00 2001 From: David Perl <115003895+dperl-dls@users.noreply.github.com> Date: Thu, 25 Jan 2024 11:07:22 +0000 Subject: [PATCH 02/10] Update setup.cfg --- setup.cfg | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/setup.cfg b/setup.cfg index 406a82d49..ceafe08f9 100644 --- a/setup.cfg +++ b/setup.cfg @@ -35,7 +35,7 @@ install_requires = xarray doct databroker - dls-dodal=1.13.1 + dls-dodal==1.13.1 pydantic<2.0 # See https://github.com/DiamondLightSource/hyperion/issues/774 scipy pyzmq From cc4a13fea235ac0f07edfffc9a1061401b122bc4 Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 26 Jan 2024 11:00:48 +0000 Subject: [PATCH 03/10] bugfixes --- run_hyperion.sh | 4 +-- .../callbacks/__main__.py | 17 +++++------ .../abstract_plan_callback_collection.py | 3 ++ src/hyperion/log.py | 9 ++++-- src/hyperion/parameters/cli.py | 28 ++++++++++--------- 5 files changed, 33 insertions(+), 28 deletions(-) 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/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, ) From a3e666b78063e84e254c80f4b3a882fe1445ffca Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 26 Jan 2024 12:00:38 +0000 Subject: [PATCH 04/10] init callbacks and logging when not external add them for registry where used in subplans --- src/hyperion/__main__.py | 10 +++++++++- src/hyperion/device_setup_plans/check_topup.py | 1 + src/hyperion/experiment_plans/experiment_registry.py | 6 +++--- 3 files changed, 13 insertions(+), 4 deletions(-) diff --git a/src/hyperion/__main__.py b/src/hyperion/__main__.py index 9fdcdfeac..bf4b80f67 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 ] @@ -298,6 +304,8 @@ def create_targets(): set_up_logging_handlers( logger=LOGGER, 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 ceddd9f0c..5615a8c0e 100644 --- a/src/hyperion/experiment_plans/experiment_registry.py +++ b/src/hyperion/experiment_plans/experiment_registry.py @@ -84,7 +84,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, @@ -96,7 +96,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, @@ -108,7 +108,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()) From 48ba6e70ced40bcd7b7ca34d01ef854bc641f143 Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 26 Jan 2024 13:29:14 +0000 Subject: [PATCH 05/10] fix and add logging --- src/hyperion/__main__.py | 4 +--- src/hyperion/experiment_plans/flyscan_xray_centre_plan.py | 8 +++++++- 2 files changed, 8 insertions(+), 4 deletions(-) diff --git a/src/hyperion/__main__.py b/src/hyperion/__main__.py index bf4b80f67..235834b74 100755 --- a/src/hyperion/__main__.py +++ b/src/hyperion/__main__.py @@ -301,9 +301,7 @@ 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( diff --git a/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py b/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py index 150461e47..6fb2da09a 100755 --- a/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py +++ b/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py @@ -203,24 +203,30 @@ 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 stage group") 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") yield from bps.wait("ready_for_data_collection") yield from bps.stage(fgs_composite.eiger) with TRACER.start_span("do_fgs"): yield from do_fgs() - + LOGGER.info("completed FGS, setting z_steps to 0") yield from bps.abs_set(fgs_motors.z_steps, 0, wait=False) From 09baf44133e18bd8ad6fb41ebda81b7eaa92e42e Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 26 Jan 2024 16:02:22 +0000 Subject: [PATCH 06/10] pin pyzmq version --- setup.cfg | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/setup.cfg b/setup.cfg index ceafe08f9..2a2e7efff 100644 --- a/setup.cfg +++ b/setup.cfg @@ -35,10 +35,10 @@ install_requires = xarray doct databroker - dls-dodal==1.13.1 + dls-dodal 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 = From 6b23ccd1c20732a032aa91b9996e87f3c8ef7458 Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 26 Jan 2024 16:05:52 +0000 Subject: [PATCH 07/10] update dodal pin --- setup.cfg | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/setup.cfg b/setup.cfg index 2a2e7efff..b36e4f623 100644 --- a/setup.cfg +++ b/setup.cfg @@ -35,7 +35,7 @@ install_requires = xarray doct databroker - dls-dodal + dls-dodal @ git+https://github.com/DiamondLightSource/dodal.git@0c434eecc8c99a1b80caab9dd5e8346fb7032ff34 pydantic<2.0 # See https://github.com/DiamondLightSource/hyperion/issues/774 scipy pyzmq<25 # See https://github.com/DiamondLightSource/hyperion/issues/1103 From e92c9bc52c0d1fdca30a1026f94a2d4cbf9e103b Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 26 Jan 2024 16:08:39 +0000 Subject: [PATCH 08/10] tidy up log messages --- src/hyperion/experiment_plans/flyscan_xray_centre_plan.py | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py b/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py index 6fb2da09a..1297b82cb 100755 --- a/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py +++ b/src/hyperion/experiment_plans/flyscan_xray_centre_plan.py @@ -211,22 +211,19 @@ def do_fgs(): ) LOGGER.info("kicking off FGS") yield from bps.kickoff(fgs_motors) - LOGGER.info("waiting for zocalo stage group") + 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") yield from bps.wait("ready_for_data_collection") yield from bps.stage(fgs_composite.eiger) with TRACER.start_span("do_fgs"): yield from do_fgs() - LOGGER.info("completed FGS, setting z_steps to 0") yield from bps.abs_set(fgs_motors.z_steps, 0, wait=False) From 816ff0249f9b5d7e8f11aacabdb9bc34d93e2e7c Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 26 Jan 2024 16:15:22 +0000 Subject: [PATCH 09/10] fix dodal pin --- setup.cfg | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/setup.cfg b/setup.cfg index b36e4f623..28a9a8123 100644 --- a/setup.cfg +++ b/setup.cfg @@ -35,7 +35,7 @@ install_requires = xarray doct databroker - dls-dodal @ git+https://github.com/DiamondLightSource/dodal.git@0c434eecc8c99a1b80caab9dd5e8346fb7032ff34 + dls-dodal @ git+https://github.com/DiamondLightSource/dodal.git@7574499cd97dfdd0e72030c421e198abb7afeb29 pydantic<2.0 # See https://github.com/DiamondLightSource/hyperion/issues/774 scipy pyzmq<25 # See https://github.com/DiamondLightSource/hyperion/issues/1103 From 3d16e8039df096dbfc8ad70c3f7cfcedc1bbfdb5 Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 26 Jan 2024 16:20:26 +0000 Subject: [PATCH 10/10] fix logging setup test --- .../external_interaction/callbacks/test_external_callbacks.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) 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