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:

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

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