Merge pull request DiamondLightSource/hyperion#1373 from DiamondLight…

…Source/487_improve_logging_formatting

(Dodal DiamondLightSource/hyperion#487) Improve logging formatting for documents

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)
 

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
 

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}.")

src/hyperion/external_interaction/callbacks/ispyb_callback_base.py

@@ -35,6 +35,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
@@ -89,7 +91,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
@@ -218,7 +220,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)
 

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_for_log(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_for_log(doc)}")
 
     def descriptor(self, doc):
-        LOGGER.info(f"DESCRIPTOR: {doc}")
+        LOGGER.info(f"DESCRIPTOR: {format_doc_for_log(doc)}")
 
     def event(self, doc):
-        LOGGER.info(f"EVENT: {doc}")
+        LOGGER.info(f"EVENT: {format_doc_for_log(doc)}")
         return doc
 
     def stop(self, doc):
-        LOGGER.info(f"STOP: {doc}")
+        LOGGER.info(f"STOP: {format_doc_for_log(doc)}")

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,15 +50,17 @@ 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
         if (
             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)

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,
@@ -144,7 +145,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):

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"]

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,
+    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(None, None, "flyscan_xray_centre", None)  # type: ignore
+        runner.start(lambda: None, test_fgs_params, "flyscan_xray_centre", None)
         mock_setup.assert_called_once()
         runner.shutdown()