fix(panda): retry arming once after a forced reset instead of hanging in pre_scan
CI for csaxs_bec / test (push) Failing after 2m11s
CI for csaxs_bec / test (push) Failing after 2m11s
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 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_017szgTwuHG65YhjoBGiK2Gj
This commit is contained in:
@@ -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.
|
||||
|
||||
@@ -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()
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user