From 611a7b1e5382aad1347de9c540c8483e3619e427 Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 10 May 2024 08:55:55 +0100 Subject: [PATCH 1/6] (#487) Improve logging formatting for documents --- .../callbacks/logging_callback.py | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/src/hyperion/external_interaction/callbacks/logging_callback.py b/src/hyperion/external_interaction/callbacks/logging_callback.py index e0a6d206b..55416fa6b 100644 --- a/src/hyperion/external_interaction/callbacks/logging_callback.py +++ b/src/hyperion/external_interaction/callbacks/logging_callback.py @@ -1,18 +1,29 @@ +import json + from bluesky.callbacks import CallbackBase from hyperion.log import LOGGER +class _BestEffortEncoder(json.JSONEncoder): + def default(self, o): + return repr(o) + + +def _format(doc): + return json.dumps(doc, indent=2, cls=_BestEffortEncoder) + + class VerbosePlanExecutionLoggingCallback(CallbackBase): def start(self, doc): - LOGGER.info(f"START: {doc}") + LOGGER.info(f"START: {_format(doc)}") def descriptor(self, doc): - LOGGER.info(f"DESCRIPTOR: {doc}") + LOGGER.info(f"DESCRIPTOR: {_format(doc)}") def event(self, doc): - LOGGER.info(f"EVENT: {doc}") + LOGGER.info(f"EVENT: {_format(doc)}") return doc def stop(self, doc): - LOGGER.info(f"STOP: {doc}") + LOGGER.info(f"STOP: {_format(doc)}") From a785580e2a5355a8fd55248d72c671cb3181fdb6 Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 10 May 2024 16:23:06 +0100 Subject: [PATCH 2/6] (#487) Improve logging formatting for params --- src/hyperion/__main__.py | 2 +- .../grid_detect_then_xray_centre_plan.py | 4 ++-- .../callbacks/aperture_change_callback.py | 4 +++- .../callbacks/logging_callback.py | 10 +++++----- .../callbacks/rotation/nexus_callback.py | 12 +++++++++--- .../callbacks/xray_centre/ispyb_callback.py | 5 ++++- .../callbacks/xray_centre/nexus_callback.py | 5 ++++- tests/unit_tests/hyperion/test_main_system.py | 8 +++++++- 8 files changed, 35 insertions(+), 15 deletions(-) diff --git a/src/hyperion/__main__.py b/src/hyperion/__main__.py index df5b3d4e8..3dcfe092b 100755 --- a/src/hyperion/__main__.py +++ b/src/hyperion/__main__.py @@ -114,7 +114,7 @@ def start( plan_name: str, callbacks: Optional[CallbacksFactory], ) -> StatusAndMessage: - LOGGER.info(f"Started with parameters: {parameters}") + LOGGER.info(f"Started with parameters: {parameters.json(indent=2)}") devices: Any = PLAN_REGISTRY[plan_name]["setup"](self.context) diff --git a/src/hyperion/experiment_plans/grid_detect_then_xray_centre_plan.py b/src/hyperion/experiment_plans/grid_detect_then_xray_centre_plan.py index 22bc2638b..24404bc4e 100644 --- a/src/hyperion/experiment_plans/grid_detect_then_xray_centre_plan.py +++ b/src/hyperion/experiment_plans/grid_detect_then_xray_centre_plan.py @@ -111,7 +111,7 @@ def create_parameters_for_flyscan_xray_centre( params_json = json.loads(old_params.json()) params_json["experiment_params"] = json.loads(grid_parameters.json()) flyscan_xray_centre_parameters = GridscanInternalParameters(**params_json) - LOGGER.info(f"Parameters for FGS: {flyscan_xray_centre_parameters}") + LOGGER.info(f"Parameters for FGS: {flyscan_xray_centre_parameters.json(indent=2)}") return flyscan_xray_centre_parameters @@ -123,7 +123,7 @@ def create_parameters_for_panda_flyscan_xray_centre( params_json = json.loads(old_params.json()) params_json["experiment_params"] = json.loads(grid_parameters.json()) flyscan_xray_centre_parameters = PandAGridscanInternalParameters(**params_json) - LOGGER.info(f"Parameters for FGS: {flyscan_xray_centre_parameters}") + LOGGER.info(f"Parameters for FGS: {flyscan_xray_centre_parameters.json(indent=2)}") return flyscan_xray_centre_parameters diff --git a/src/hyperion/external_interaction/callbacks/aperture_change_callback.py b/src/hyperion/external_interaction/callbacks/aperture_change_callback.py index d90c5362c..3041278a2 100644 --- a/src/hyperion/external_interaction/callbacks/aperture_change_callback.py +++ b/src/hyperion/external_interaction/callbacks/aperture_change_callback.py @@ -3,6 +3,8 @@ from hyperion.log import LOGGER +from .logging_callback import format_doc_for_log + class ApertureChangeCallback(CallbackBase): """A callback that's used to send the selected aperture back to GDA""" @@ -13,7 +15,7 @@ def __init__(self, *args, **kwargs) -> None: def start(self, doc: RunStart): if doc.get("subplan_name") == "change_aperture": - LOGGER.info(f"START: {doc}") + LOGGER.debug(f"START: {format_doc_for_log(doc)}") ap_size = doc.get("aperture_size") assert isinstance(ap_size, str) LOGGER.info(f"Updating most recent in-plan aperture change to {ap_size}.") diff --git a/src/hyperion/external_interaction/callbacks/logging_callback.py b/src/hyperion/external_interaction/callbacks/logging_callback.py index 55416fa6b..997b935a5 100644 --- a/src/hyperion/external_interaction/callbacks/logging_callback.py +++ b/src/hyperion/external_interaction/callbacks/logging_callback.py @@ -10,20 +10,20 @@ def default(self, o): return repr(o) -def _format(doc): +def format_doc_for_log(doc): return json.dumps(doc, indent=2, cls=_BestEffortEncoder) class VerbosePlanExecutionLoggingCallback(CallbackBase): def start(self, doc): - LOGGER.info(f"START: {_format(doc)}") + LOGGER.info(f"START: {format_doc_for_log(doc)}") def descriptor(self, doc): - LOGGER.info(f"DESCRIPTOR: {_format(doc)}") + LOGGER.info(f"DESCRIPTOR: {format_doc_for_log(doc)}") def event(self, doc): - LOGGER.info(f"EVENT: {_format(doc)}") + LOGGER.info(f"EVENT: {format_doc_for_log(doc)}") return doc def stop(self, doc): - LOGGER.info(f"STOP: {_format(doc)}") + LOGGER.info(f"STOP: {format_doc_for_log(doc)}") diff --git a/src/hyperion/external_interaction/callbacks/rotation/nexus_callback.py b/src/hyperion/external_interaction/callbacks/rotation/nexus_callback.py index 7ac4e4aa1..50f5f8074 100644 --- a/src/hyperion/external_interaction/callbacks/rotation/nexus_callback.py +++ b/src/hyperion/external_interaction/callbacks/rotation/nexus_callback.py @@ -16,6 +16,8 @@ RotationInternalParameters, ) +from ..logging_callback import format_doc_for_log + if TYPE_CHECKING: from event_model.documents import Event, EventDescriptor, RunStart @@ -48,7 +50,7 @@ def activity_gated_event(self, doc: Event): assert isinstance(self.parameters, RotationInternalParameters) if event_descriptor is None: NEXUS_LOGGER.warning( - f"Rotation Nexus handler {self} received event doc {doc} and " + f"Rotation Nexus handler {self} received event doc {format_doc_for_log(doc)} and " "has no corresponding descriptor record" ) return doc @@ -56,7 +58,9 @@ def activity_gated_event(self, doc: Event): event_descriptor.get("name") == CONST.DESCRIPTORS.ISPYB_TRANSMISSION_FLUX_READ ): - NEXUS_LOGGER.info(f"Nexus handler received event from read hardware {doc}") + NEXUS_LOGGER.info( + f"Nexus handler received event from read hardware {format_doc_for_log(doc)}" + ) data = doc["data"] assert self.writer, "Nexus writer not initialised" ( @@ -68,7 +72,9 @@ def activity_gated_event(self, doc: Event): data["attenuator_actual_transmission"], ) if event_descriptor.get("name") == CONST.DESCRIPTORS.NEXUS_READ: - NEXUS_LOGGER.info(f"Nexus handler received event from read hardware {doc}") + NEXUS_LOGGER.info( + f"Nexus handler received event from read hardware {format_doc_for_log(doc)}" + ) vds_data_type = vds_type_based_on_bit_depth(doc["data"]["eiger_bit_depth"]) assert self.writer is not None self.writer.create_nexus_file(vds_data_type) diff --git a/src/hyperion/external_interaction/callbacks/xray_centre/ispyb_callback.py b/src/hyperion/external_interaction/callbacks/xray_centre/ispyb_callback.py index 1dfcbf1dd..eedbea3da 100644 --- a/src/hyperion/external_interaction/callbacks/xray_centre/ispyb_callback.py +++ b/src/hyperion/external_interaction/callbacks/xray_centre/ispyb_callback.py @@ -16,6 +16,7 @@ from hyperion.external_interaction.callbacks.ispyb_callback_base import ( BaseISPyBCallback, ) +from hyperion.external_interaction.callbacks.logging_callback import format_doc_for_log from hyperion.external_interaction.callbacks.xray_centre.ispyb_mapping import ( populate_xy_data_collection_info, populate_xz_data_collection_info, @@ -142,7 +143,9 @@ def activity_gated_event(self, doc: Event): crystal_summary = f"Zocalo processing took {proc_time:.2f} s. " bboxes: List[np.ndarray] = [] - ISPYB_LOGGER.info(f"Amending comment based on Zocalo reading doc: {doc}") + ISPYB_LOGGER.info( + f"Amending comment based on Zocalo reading doc: {format_doc_for_log(doc)}" + ) raw_results = doc["data"]["zocalo-results"] if len(raw_results) > 0: for n, res in enumerate(raw_results): diff --git a/src/hyperion/external_interaction/callbacks/xray_centre/nexus_callback.py b/src/hyperion/external_interaction/callbacks/xray_centre/nexus_callback.py index fd0ce5954..3960d25b4 100644 --- a/src/hyperion/external_interaction/callbacks/xray_centre/nexus_callback.py +++ b/src/hyperion/external_interaction/callbacks/xray_centre/nexus_callback.py @@ -2,6 +2,7 @@ from typing import TYPE_CHECKING, Dict +from hyperion.external_interaction.callbacks.logging_callback import format_doc_for_log from hyperion.external_interaction.callbacks.plan_reactive_callback import ( PlanReactiveCallback, ) @@ -83,7 +84,9 @@ def activity_gated_event(self, doc: Event) -> Event | None: data["attenuator_actual_transmission"], ) if event_descriptor.get("name") == CONST.DESCRIPTORS.NEXUS_READ: - NEXUS_LOGGER.info(f"Nexus handler received event from read hardware {doc}") + NEXUS_LOGGER.info( + f"Nexus handler received event from read hardware {format_doc_for_log(doc)}" + ) for nexus_writer in [self.nexus_writer_1, self.nexus_writer_2]: vds_data_type = vds_type_based_on_bit_depth( doc["data"]["eiger_bit_depth"] diff --git a/tests/unit_tests/hyperion/test_main_system.py b/tests/unit_tests/hyperion/test_main_system.py index 052a09c25..ef93b071f 100644 --- a/tests/unit_tests/hyperion/test_main_system.py +++ b/tests/unit_tests/hyperion/test_main_system.py @@ -17,6 +17,7 @@ from dodal.devices.attenuator import Attenuator from dodal.devices.zebra import Zebra from flask.testing import FlaskClient +from pydantic import BaseModel from hyperion.__main__ import ( Actions, @@ -472,9 +473,14 @@ def test_when_blueskyrunner_initiated_and_skip_flag_is_set_then_setup_called_upo }, clear=True, ): + + class MockParams(BaseModel): + mock_param: int + + mock_params = MockParams(mock_param=1) runner = BlueskyRunner(MagicMock(), MagicMock(), skip_startup_connection=True) mock_setup.assert_not_called() - runner.start(None, None, "flyscan_xray_centre", None) # type: ignore + runner.start(None, mock_params, "flyscan_xray_centre", None) # type: ignore mock_setup.assert_called_once() runner.shutdown() From be97b156b17a61b45f9d7621f887d4d9fe18893b Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 10 May 2024 16:43:02 +0100 Subject: [PATCH 3/6] (#487) fix test --- tests/unit_tests/hyperion/test_main_system.py | 10 ++-------- 1 file changed, 2 insertions(+), 8 deletions(-) diff --git a/tests/unit_tests/hyperion/test_main_system.py b/tests/unit_tests/hyperion/test_main_system.py index ef93b071f..500de7002 100644 --- a/tests/unit_tests/hyperion/test_main_system.py +++ b/tests/unit_tests/hyperion/test_main_system.py @@ -17,7 +17,6 @@ from dodal.devices.attenuator import Attenuator from dodal.devices.zebra import Zebra from flask.testing import FlaskClient -from pydantic import BaseModel from hyperion.__main__ import ( Actions, @@ -458,7 +457,7 @@ def fake_create_devices(context) -> FakeComposite: "hyperion.experiment_plans.flyscan_xray_centre_plan.create_devices", autospec=True ) def test_when_blueskyrunner_initiated_and_skip_flag_is_set_then_setup_called_upon_start( - mock_setup, + mock_setup, test_new_fgs_params ): mock_setup = MagicMock() with patch.dict( @@ -473,14 +472,9 @@ def test_when_blueskyrunner_initiated_and_skip_flag_is_set_then_setup_called_upo }, clear=True, ): - - class MockParams(BaseModel): - mock_param: int - - mock_params = MockParams(mock_param=1) runner = BlueskyRunner(MagicMock(), MagicMock(), skip_startup_connection=True) mock_setup.assert_not_called() - runner.start(None, mock_params, "flyscan_xray_centre", None) # type: ignore + runner.start(lambda: None, test_new_fgs_params, "flyscan_xray_centre", None) mock_setup.assert_called_once() runner.shutdown() From 24f130a55a96e2d11cfdf722fa96da52cd8a0a8b Mon Sep 17 00:00:00 2001 From: David Perl Date: Tue, 14 May 2024 09:52:54 +0100 Subject: [PATCH 4/6] (#487) format missed docs --- .../external_interaction/callbacks/ispyb_callback_base.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/hyperion/external_interaction/callbacks/ispyb_callback_base.py b/src/hyperion/external_interaction/callbacks/ispyb_callback_base.py index e36d91f0e..52222e011 100644 --- a/src/hyperion/external_interaction/callbacks/ispyb_callback_base.py +++ b/src/hyperion/external_interaction/callbacks/ispyb_callback_base.py @@ -34,6 +34,8 @@ ) from hyperion.utils.utils import convert_eV_to_angstrom +from .logging_callback import format_doc_for_log + D = TypeVar("D") if TYPE_CHECKING: from event_model.documents import Event, EventDescriptor, RunStart, RunStop @@ -88,7 +90,7 @@ def activity_gated_event(self, doc: Event) -> Event: event_descriptor = self.descriptors.get(doc["descriptor"]) if event_descriptor is None: ISPYB_LOGGER.warning( - f"Ispyb handler {self} recieved event doc {doc} and " + f"Ispyb handler {self} recieved event doc {format_doc_for_log(doc)} and " "has no corresponding descriptor record" ) return doc @@ -210,7 +212,7 @@ def activity_gated_stop(self, doc: RunStop) -> RunStop: self.ispyb.end_deposition(self.ispyb_ids, exit_status, reason) except Exception as e: ISPYB_LOGGER.warning( - f"Failed to finalise ISPyB deposition on stop document: {doc} with exception: {e}" + f"Failed to finalise ISPyB deposition on stop document: {format_doc_for_log(doc)} with exception: {e}" ) return self._tag_doc(doc) From 80a6f7691fdf9b412b7363952b57d48dce0293da Mon Sep 17 00:00:00 2001 From: David Perl Date: Thu, 16 May 2024 13:47:26 +0100 Subject: [PATCH 5/6] fix test --- tests/unit_tests/hyperion/test_main_system.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/unit_tests/hyperion/test_main_system.py b/tests/unit_tests/hyperion/test_main_system.py index 500de7002..cbb009269 100644 --- a/tests/unit_tests/hyperion/test_main_system.py +++ b/tests/unit_tests/hyperion/test_main_system.py @@ -457,7 +457,7 @@ def fake_create_devices(context) -> FakeComposite: "hyperion.experiment_plans.flyscan_xray_centre_plan.create_devices", autospec=True ) def test_when_blueskyrunner_initiated_and_skip_flag_is_set_then_setup_called_upon_start( - mock_setup, test_new_fgs_params + mock_setup, test_fgs_params ): mock_setup = MagicMock() with patch.dict( @@ -474,7 +474,7 @@ def test_when_blueskyrunner_initiated_and_skip_flag_is_set_then_setup_called_upo ): runner = BlueskyRunner(MagicMock(), MagicMock(), skip_startup_connection=True) mock_setup.assert_not_called() - runner.start(lambda: None, test_new_fgs_params, "flyscan_xray_centre", None) + runner.start(lambda: None, test_fgs_params, "flyscan_xray_centre", None) mock_setup.assert_called_once() runner.shutdown() From 2c13ecdcbe4b76207a1cc34ec9d7cb14baa53309 Mon Sep 17 00:00:00 2001 From: Dominic Oram Date: Thu, 16 May 2024 14:03:40 +0100 Subject: [PATCH 6/6] (DiamondLightSource/dodal#487) Pretty print more params --- .../experiment_plans/pin_centre_then_xray_centre_plan.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/hyperion/experiment_plans/pin_centre_then_xray_centre_plan.py b/src/hyperion/experiment_plans/pin_centre_then_xray_centre_plan.py index f21453549..7873cb115 100644 --- a/src/hyperion/experiment_plans/pin_centre_then_xray_centre_plan.py +++ b/src/hyperion/experiment_plans/pin_centre_then_xray_centre_plan.py @@ -39,7 +39,7 @@ def create_parameters_for_grid_detection( del params_json["tip_offset_um"] grid_detect_and_xray_centre = GridScanWithEdgeDetect(**params_json) LOGGER.info( - f"Parameters for grid detect and xray centre: {grid_detect_and_xray_centre}" + f"Parameters for grid detect and xray centre: {grid_detect_and_xray_centre.json(indent=2)}" ) return grid_detect_and_xray_centre