From bbede883b0da25da5ecbb38130e661c7cdfff4e8 Mon Sep 17 00:00:00 2001 From: x12sa Date: Sun, 20 Sep 2026 11:47:04 +0200 Subject: [PATCH] fix(panda): retry arming once after a forced reset instead of hanging in pre_scan PandaBoxOMNY inherited on_pre_scan, which waits forever for the PandA READY event before sending Arm(). After rapid abort/retry cycles the readout thread can be left parked, so READY never arrives and pre_scan_all_devices() hangs with no error (flomni_fermat_scan 11998/12000). on_pre_scan now runs a bounded arm task: wait pre_scan_timeout (default 5 s) for READY; on failure force-reset the box, restart the readout thread (after the old loop finished its cleanup) and try once more, printing and logging a warning with diagnostics. If the second attempt fails too, the status fails with a RuntimeError so the scan aborts. Arm() is sent from the task, not a status callback, so the scan is only released after it went out. A stop is not retried. Also records the outcome and the still-open ophyd_devices race in AGENTS_mirko.md. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_017szgTwuHG65YhjoBGiK2Gj --- AGENTS_mirko.md | 33 +++++++ csaxs_bec/devices/panda_box/panda_box_omny.py | 99 +++++++++++++++++++ tests/tests_devices/test_panda.py | 90 +++++++++++++++++ 3 files changed, 222 insertions(+) diff --git a/AGENTS_mirko.md b/AGENTS_mirko.md index fd7a334a..ccf34012 100644 --- a/AGENTS_mirko.md +++ b/AGENTS_mirko.md @@ -13,3 +13,36 @@ repos, write it up (a short report or plan) instead of implementing/committing i Fixes that land in `csaxs_bec` itself (beamline plugin code, widgets, device configs, scans) are mine to implement, commit, and push directly. + +## TODO + +- 2026-09-20: `flomni_fermat_scan` hung on `pre_scan_all_devices()` after positions were + already sent to the rt controller (scans 11998, 12000 in `/var/log/bec/ScanServer.log` / + `DeviceServer.log`). Positions/PID-correction step (`prepare_setup_part_2()`) completed + fine; `kickoff()`/`start_scan()` (the actual rt-side trigger, logged as `Read N out of 106`) + was never reached because the joined `pre_scan_all_devices()` wait never returned. No error, + no timeout — DeviceServer just went silent until manually aborted. + Most likely culprit: `omny_panda_continuous` (PandaBox) — `on_pre_scan()` in + `ophyd_devices/devices/panda_box/panda_box.py:696` arms the PCAP block and returns a status + that only resolves on a `PandaState.READY`/`FRAME`/`END` event, with **no timeout**. Logs + show `Cannot emit async signal omny_panda_continuous_data ... with status aborted` spamming + throughout the hang window, consistent with the box being left in a stuck/unarmed state after + the preceding rapid interlock-triggered abort/retry cycle (11991–12001, ~11 attempts in 5 + minutes). + This traces into `ophyd_devices`, not `csaxs_bec` — per the ownership note above, not mine to + fix directly here. Follow-ups to consider: (a) file/flag this with whoever owns + `ophyd_devices` (add a timeout + explicit failure path to `PandaBox.on_pre_scan`'s status + callback so a stuck arm surfaces as an error instead of hanging forever), (b) check whether + `on_unstage`/`_reset_panda()` is reliably called on scan abort so the box doesn't carry a + stale state into the next attempt. + + **Status 2026-09-20 (csaxs_bec side done):** `PandaBoxOMNY.on_pre_scan` + (`csaxs_bec/devices/panda_box/panda_box_omny.py`) no longer waits for READY forever. Each + arming attempt waits `pre_scan_timeout` (default 5 s); if READY does not arrive, the box is + force-reset (`_reset_panda()`), the readout thread restarted and arming retried once (retry is + printed and logged as a warning with diagnostics). Only if the second attempt fails as well + does the status fail with a `RuntimeError`, so the scan aborts instead of hanging. + Still open for the ophyd_devices owner: the base-class race where the readout loop's + `finally: _reset_panda()` can clear `data_thread_run_event` after a fresh `on_stage()` set it + (likely root cause of the missing READY after rapid abort/retry); the new diagnostics line in + the DeviceServer log (`data_thread_run_event=False`) would confirm it. diff --git a/csaxs_bec/devices/panda_box/panda_box_omny.py b/csaxs_bec/devices/panda_box/panda_box_omny.py index 0033c8fa..52157433 100644 --- a/csaxs_bec/devices/panda_box/panda_box_omny.py +++ b/csaxs_bec/devices/panda_box/panda_box_omny.py @@ -8,6 +8,7 @@ from bec_lib.logger import bec_logger from bec_server.scan_server.scans.scan_base import ScanInfo as ScanServerScanInfo from ophyd_devices import StatusBase from ophyd_devices.devices.panda_box.panda_box import PandaBox, PandaState +from ophyd_devices.interfaces.base_classes.psi_device_base import DeviceStoppedError from pandablocks.responses import FrameData from csaxs_bec.devices.utils.utils import fetch_scan_info @@ -50,6 +51,11 @@ class PandaBoxOMNY(PandaBox): _GATE_SIGNAL_NAME = "gate_detector_active" _GATE_BIT_OFFSET = 0 + # Arming in on_pre_scan is tried this many times (one forced abort/reset in between) before + # the scan is failed. READY normally arrives within milliseconds of the readout thread + # connecting, so a missing READY means the readout thread/box is in a stale state. + _PRE_SCAN_ARM_ATTEMPTS = 2 + def __init__( self, *, @@ -61,6 +67,7 @@ class PandaBoxOMNY(PandaBox): raw_stream_mode: bool = False, raw_stream_flush_interval: float = 0.05, raw_stream_flush_row_count: int = 500, + pre_scan_timeout: float = 5.0, **kwargs, ) -> None: # Free-running raw-stream configuration. Defaults preserve today's behavior: @@ -74,6 +81,13 @@ class PandaBoxOMNY(PandaBox): self._raw_stream_buffer_lock = threading.Lock() self._raw_stream_last_flush = time.monotonic() + # Seconds to wait for the PandA READY event per arming attempt in on_pre_scan. + self.pre_scan_timeout = pre_scan_timeout + # Set while the data readout thread is parked (not inside _run_data_readout), so a + # retry in on_pre_scan can wait for the old readout loop's cleanup to be finished. + self._readout_idle = threading.Event() + self._readout_idle.set() + super().__init__( name=name, host=host, @@ -113,6 +127,91 @@ class PandaBoxOMNY(PandaBox): logger.info(f"PandaBox {self.name} on_stage completed in {time.time() - start_time:.3f}s.") + def _run_data_readout(self) -> None: + """Same as the base class, but tracks whether the readout loop is running. The base + loop ends with `_reset_panda()`, which clears `data_thread_run_event`; a retry in + `_arm_with_retry` must not set that event again before this cleanup has run.""" + self._readout_idle.clear() + try: + super()._run_data_readout() + finally: + self._readout_idle.set() + + def on_pre_scan(self): + """Arm the PCAP module. Unlike the base class this does not wait forever for the READY + event: if it does not arrive, the box is forcibly reset and arming is retried once, + and only if that fails as well the returned status fails, so the scan is aborted with + an error instead of hanging silently in pre_scan.""" + # Not registered with cancel_on_stop: the status of each single attempt in _try_arm is, + # so a stop makes the task raise DeviceStoppedError, which fails this status. Cancelling + # this one as well would make the task handler try to resolve it a second time. + return self.task_handler.submit_task(self._arm_with_retry, run=True) + + def _arm_with_retry(self) -> None: + """Task run by on_pre_scan: try to arm, force an abort/reset and try again if the + first attempt fails, raise if all attempts fail. Every retry is printed and logged.""" + attempts = self._PRE_SCAN_ARM_ATTEMPTS + for attempt in range(1, attempts + 1): + if self._try_arm(): + if attempt > 1: + logger.info( + f"PandaBox {self.name} armed successfully on attempt {attempt}/{attempts}." + ) + return + if attempt < attempts: + msg = ( + f"PandaBox {self.name} did not report READY within {self.pre_scan_timeout}s " + f"(arming attempt {attempt}/{attempts}). Forcing abort/reset and retrying." + ) + print(msg) + logger.warning(f"{msg} {self._arm_diagnostics()}") + self._reset_panda() + # Wait for the old readout loop to finish its own _reset_panda() cleanup, it + # would otherwise clear the run event we set next. + self._readout_idle.wait(timeout=2) + self.data_thread_run_event.set() + msg = ( + f"PandaBox {self.name} could not be armed after {attempts} attempts (no READY within " + f"{self.pre_scan_timeout}s each). The box was reset; check the connection and the " + "PandA state." + ) + logger.error(f"{msg} {self._arm_diagnostics()}") + self._reset_panda() + raise RuntimeError(msg) + + def _try_arm(self) -> bool: + """One arming attempt: wait for the READY event, then send Arm(). Returns False if + READY did not arrive in time or the box reported a conflicting state (FRAME/END, + i.e. an acquisition is still running). A stop/unstage is not retried.""" + if self.stopped: + raise DeviceStoppedError(f"Device {self.name} has been stopped") + status = StatusBase(obj=self) + cb_id = self.add_status_callback( + status=status, success=[PandaState.READY], failure=[PandaState.FRAME, PandaState.END] + ) + self.cancel_on_stop(status) + try: + status.wait(timeout=self.pre_scan_timeout) + except DeviceStoppedError: + self.remove_status_callback(cb_id) + raise + except Exception as exc: # pylint: disable=broad-except + # Timeout, or the box reported FRAME/END while we waited for READY + self.remove_status_callback(cb_id) + logger.warning(f"PandaBox {self.name} arming attempt failed: {exc!r}") + return False + # Sent from here rather than from a status callback (as the base class does), so the + # scan is only released after Arm() actually went out. + self._arm() + return True + + def _arm_diagnostics(self) -> str: + return ( + f"[host={self.host}, panda_state={self.panda_state}, " + f"data_thread_alive={self.data_thread.is_alive()}, " + f"data_thread_run_event={self.data_thread_run_event.is_set()}]" + ) + def on_unstage(self): """Make sure no buffered raw-stream data is left behind before resetting the device.""" self._flush_raw_stream_buffer() diff --git a/tests/tests_devices/test_panda.py b/tests/tests_devices/test_panda.py index 48f6f2f2..ee6626b3 100644 --- a/tests/tests_devices/test_panda.py +++ b/tests/tests_devices/test_panda.py @@ -3,11 +3,14 @@ # pylint: skip-file from __future__ import annotations +import threading from unittest import mock import numpy as np import pytest from ophyd import Staged +from ophyd_devices.devices.panda_box.panda_box import PandaState +from ophyd_devices.interfaces.base_classes.psi_device_base import DeviceStoppedError from pandablocks.responses import FrameData from csaxs_bec.devices.panda_box.panda_box import PandaBoxCSAXS @@ -294,6 +297,93 @@ def test_panda_omny_complete_free_running_timeout(panda_omny_raw_stream): mock_flush.assert_called_once() +def _deliver_ready_after(dev, delay: float) -> threading.Timer: + """Simulate the PandA data thread delivering the READY event `delay` seconds from now.""" + timer = threading.Timer(delay, dev._run_status_callbacks, args=(PandaState.READY,)) + timer.daemon = True + timer.start() + return timer + + +def test_panda_omny_pre_scan_arms_when_ready(panda_omny, capsys): + dev = panda_omny + dev.pre_scan_timeout = 2 + with ( + mock.patch.object(dev, "_arm") as mock_arm, + mock.patch.object(dev, "_reset_panda") as mock_reset, + ): + _deliver_ready_after(dev, 0.05) + status = dev.on_pre_scan() + status.wait(timeout=4) + assert status.success is True + mock_arm.assert_called_once() + mock_reset.assert_not_called() + assert "Forcing abort/reset" not in capsys.readouterr().out + + +def test_panda_omny_pre_scan_retries_once_then_succeeds(panda_omny, capsys): + """No READY on the first attempt: the box is force-reset and arming retried. The retry is + printed and logged.""" + dev = panda_omny + dev.pre_scan_timeout = 0.2 + + def _reset_then_ready(): + _deliver_ready_after(dev, 0.05) + + with ( + mock.patch.object(dev, "_arm") as mock_arm, + mock.patch.object(dev, "_reset_panda", side_effect=_reset_then_ready) as mock_reset, + mock.patch("csaxs_bec.devices.panda_box.panda_box_omny.logger") as mock_logger, + ): + status = dev.on_pre_scan() + status.wait(timeout=4) + assert status.success is True + mock_reset.assert_called_once() + mock_arm.assert_called_once() + assert any("Forcing abort/reset" in str(c) for c in mock_logger.warning.call_args_list) + assert any("armed successfully on attempt 2" in str(c) for c in mock_logger.info.call_args_list) + assert "Forcing abort/reset" in capsys.readouterr().out + + +def test_panda_omny_pre_scan_raises_after_retry_fails(panda_omny, capsys): + dev = panda_omny + dev.pre_scan_timeout = 0.1 + with ( + mock.patch.object(dev, "_arm") as mock_arm, + mock.patch.object(dev, "_reset_panda") as mock_reset, + mock.patch("csaxs_bec.devices.panda_box.panda_box_omny.logger") as mock_logger, + ): + status = dev.on_pre_scan() + with pytest.raises(RuntimeError, match="could not be armed after 2 attempts"): + status.wait(timeout=4) + mock_arm.assert_not_called() + # once for the forced reset before the retry, once to leave the box clean at the end + assert mock_reset.call_count == 2 + mock_logger.error.assert_called_once() + assert capsys.readouterr().out.count("Forcing abort/reset") == 1 + # stale status callbacks of the failed attempts are removed again + assert dev._status_callbacks == {} + + +def test_panda_omny_pre_scan_stop_is_not_retried(panda_omny, capsys): + dev = panda_omny + dev.pre_scan_timeout = 0.3 + with ( + mock.patch.object(dev, "_arm") as mock_arm, + mock.patch.object(dev, "_reset_panda") as mock_reset, + ): + status = dev.on_pre_scan() + threading.Event().wait(0.05) + dev._stop_stoppable_status_objects() + with pytest.raises(DeviceStoppedError): + status.wait(timeout=4) + # give a wrongly retrying task thread the time to show up + threading.Event().wait(0.5) + mock_arm.assert_not_called() + mock_reset.assert_not_called() + assert "Forcing abort/reset" not in capsys.readouterr().out + + def test_panda_omny_raw_stream_signal_alias(panda_omny_raw_stream): all_signal_names = [name for name, _ in panda_omny_raw_stream.data.signals] assert "gate_detector_active" in all_signal_names