From 339f6666da887f37336d86cae28e480c0e338057 Mon Sep 17 00:00:00 2001 From: David Perl Date: Fri, 4 Sep 2026 11:23:54 +0200 Subject: [PATCH] fix: add more debug info logging to automation runs --- src/aare/daq/config.py | 5 +++++ src/aare/daq/daq.py | 12 +++++++++--- src/aare/devices/tell_client.py | 1 + 3 files changed, 15 insertions(+), 3 deletions(-) diff --git a/src/aare/daq/config.py b/src/aare/daq/config.py index 24b44759..1d0bfdda 100644 --- a/src/aare/daq/config.py +++ b/src/aare/daq/config.py @@ -2,6 +2,7 @@ import base64 import io import json import time +import traceback from dataclasses import asdict, is_dataclass from datetime import datetime @@ -583,6 +584,10 @@ class BeamlineConfig: @state_busy.setter def state_busy(self, i: bool): + + logger.debug( + f"Busy flag switched to: {i}, at:\n{''.join(traceback.format_stack(limit=5)[:-2])}" + ) if i: self._client.set(f"{self._bl}:busy", "1") else: diff --git a/src/aare/daq/daq.py b/src/aare/daq/daq.py index 2efa8a34..a9adf94e 100644 --- a/src/aare/daq/daq.py +++ b/src/aare/daq/daq.py @@ -522,6 +522,7 @@ class AareDAQ: raise StateTransitionFailed( f"Automation cannot continue because beamline is still in Moving state during {context}" ) + logger.debug(f"Automation state validated with context: {context}") def _run_noncritical( self, @@ -2607,6 +2608,7 @@ class AareDAQ: sample_prefix = f"{formatted_date}/{sample.puck_name}/{sample.pin:02d}/{sample.sample_name}" try: + logger.info("Automation-measure starting sequence") self._validate_automation_state(context="automation start") self._cfg.try_set_busy(timeout=self.AUTOMATION_BUSY_TIMEOUT_S) @@ -2618,6 +2620,7 @@ class AareDAQ: ) self._mark_progress_running(progress, WorkflowStateKind.MOUNT, "Mounting sample") + logger.info("Automation-measure initial setup complete") if not self._execute_mount_and_prepare(sample): mount_error_message = self._last_mount_error_message or "Mount failed" self._mark_progress_failed(progress, WorkflowStateKind.MOUNT, mount_error_message) @@ -2626,8 +2629,7 @@ class AareDAQ: self._mark_progress_success(progress, WorkflowStateKind.MOUNT, "Mount complete") self._set_state(BeamlineStateEnum.SampleAlignment) self._validate_automation_state(context="after transition to SampleAlignment") - - logger.info(f"mounting done at {time.perf_counter() - start}") + logger.info(f"Automation-measure mounting done at {time.perf_counter() - start}") self._mark_progress_running(progress, WorkflowStateKind.LOOP_CENTRE, "Centering sample") @@ -2650,6 +2652,7 @@ class AareDAQ: centered = False try: + logger.info("Automation-measure running loop centering") centered = self._execute_loop_centering(sample) except LoopCenteringFailed as e: self._record_best_effort_step_failure( @@ -2670,7 +2673,10 @@ class AareDAQ: ) self._validate_automation_state(context="after loop centering") - logger.info(f"Loop Centering done at {time.perf_counter() - start}") + logger.info( + f"Automation-measure - loop Centering done at {time.perf_counter() - start}" + ) + logger.debug(f"Automation-measure - current busy-state: {self._cfg.state_busy}") face_detection_result = self._execute_face_detection( steps=7, step_size=30, face_min_ratio=0.3, report_error=True diff --git a/src/aare/devices/tell_client.py b/src/aare/devices/tell_client.py index baccfd14..102f981e 100644 --- a/src/aare/devices/tell_client.py +++ b/src/aare/devices/tell_client.py @@ -425,6 +425,7 @@ class TellClient: def get_mounted_sample(self) -> SampleDewarAddress | None: ret = self.get_setting("mounted_sample_position").strip() + logger.debug(f"Get TELL setting 'mounted_sample_position' returned: {ret}") if not ret: return None -- 2.54.0