From ce3c31ccb4e1da021c1743faacf98969bda0fd8d Mon Sep 17 00:00:00 2001 From: menzel Date: Fri, 4 Sep 2026 18:50:15 +0200 Subject: [PATCH 1/3] fix(macros): look devices up in dev, not dev.devices The tensor-tomography branch of run_cont_grid_scan_for_table_row has never worked. `dev` is already the device container -- bec_lib binds dev = device_manager.devices in the client namespace -- so dev.devices[name] asks DeviceContainer for a device literally called "devices" and its __getattr__ raises DeviceConfigError before any motor moves. Observed at the beamline on a tensor table using sgchi/sgphi as the rotation axes: --> 72 roty_motor = dev.devices[row["roty_axis"]] DeviceConfigError: Device devices does not exist. The failure is deterministic, so @scan_repeat(max_repeats=3, default=True) retried it three times, and the surrounding except reported only "Error while moving motors to starting position for sample ..." -- the traceback goes to SciLog and nowhere else, which is why this survived undetected. Adds tests/tests_macros, which had no equivalent: macros run in the client namespace and are not executed by any test, so mistakes in them reach the beamline unfiltered. The check parses each macro and flags dev.devices attribute access rather than matching text, so comments and docstrings that mention the pattern do not trip it. Verified to fail against the unfixed macro. The rotation axes themselves are not hard-coded: rotx_axis/roty_axis are row fields holding a device name chosen from the SAXS widget's positioner combo boxes. Only the four row keys are fixed. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_0148tn6uK6oiTH25mzLfJcyc --- .../run_cont_grid_scan_for_table_row.py | 7 ++- .../tests_macros/test_macro_device_access.py | 44 +++++++++++++++++++ 2 files changed, 49 insertions(+), 2 deletions(-) create mode 100644 tests/tests_macros/test_macro_device_access.py diff --git a/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py b/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py index cdfbd530..ce19b5a3 100644 --- a/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py +++ b/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py @@ -69,11 +69,14 @@ def run_cont_grid_scan_for_table_row( try: # Move motors to the starting position of the scan move_command = [] - roty_motor = dev.devices[row["roty_axis"]] + # NOTE `dev` IS the device container (bec_lib client binds + # dev = device_manager.devices), so `dev.devices[...]` asks the container for a + # device named "devices" and raises DeviceConfigError before any motor moves. + roty_motor = dev[row["roty_axis"]] setpoint_roty = roty_motor.setpoint.get(cached=True) if not np.isclose(setpoint_roty, row["roty"]): move_command.extend([row["roty_axis"], row["roty"]]) - setpoint_rotx = dev.devices[row["rotx_axis"]].setpoint.get(cached=True) + setpoint_rotx = dev[row["rotx_axis"]].setpoint.get(cached=True) if not np.isclose(setpoint_rotx, row["rotx"]): move_command.extend([row["rotx_axis"], row["rotx"]]) # Wait for all motor movements to complete diff --git a/tests/tests_macros/test_macro_device_access.py b/tests/tests_macros/test_macro_device_access.py new file mode 100644 index 00000000..f46dcc60 --- /dev/null +++ b/tests/tests_macros/test_macro_device_access.py @@ -0,0 +1,44 @@ +"""Static checks on the user macros. + +Macros run in the BEC client namespace and are not covered by unit tests, so mistakes in +them surface only at the beamline -- and, because several macros wrap their body in a +try/except that reports to SciLog, often only as a generic message with the traceback +discarded. These checks catch the failure modes that are decidable statically. +""" + +import ast +import pathlib + +import pytest + +MACRO_DIR = pathlib.Path(__file__).resolve().parents[2] / "csaxs_bec" / "macros" +MACROS = sorted(p for p in MACRO_DIR.glob("*.py") if p.name != "__init__.py") + + +def test_macro_directory_is_found(): + """Guard against the glob silently matching nothing if the layout changes.""" + assert MACROS, f"no macros found under {MACRO_DIR}" + + +@pytest.mark.parametrize("macro", MACROS, ids=lambda p: p.name) +def test_macros_do_not_go_through_dev_devices(macro: pathlib.Path): + """`dev` is already the device container, so `dev.devices` cannot resolve. + + bec_lib binds `dev = device_manager.devices` in the client namespace, and + DeviceContainer.__getattr__ raises DeviceConfigError for an unknown attribute. So + `dev.devices[name]` asks for a device literally called "devices" and fails before + doing anything useful. Use `dev[name]`. + """ + tree = ast.parse(macro.read_text(), filename=str(macro)) + offenders = [ + node.lineno + for node in ast.walk(tree) + if isinstance(node, ast.Attribute) + and node.attr == "devices" + and isinstance(node.value, ast.Name) + and node.value.id == "dev" + ] + assert not offenders, ( + f"{macro.name}: line(s) {offenders} use dev.devices -- `dev` is the device " + "container itself, so this raises DeviceConfigError at runtime. Use dev[]." + ) -- 2.54.0 From cb21186e9d43072e12a95f72cb044c1593ef3c7e Mon Sep 17 00:00:00 2001 From: menzel Date: Fri, 4 Sep 2026 19:56:56 +0200 Subject: [PATCH 2/3] fix(macros): report failures fully instead of a one-line summary When a table row failed, the macro printed a headline, sent the actual error text to SciLog alone, and left both the SciLog post and the SMS unguarded. So the detail existed in exactly one place that nobody was watching, and if SciLog was unreachable its exception replaced the one being reported -- the bare `raise` at the end never ran. Combined with @scan_repeat retrying three times, a deterministic one-line DeviceConfigError produced three identical context-free messages and survived several hours of beamtime. Failures now go through _report_failure, which: - prints the exception type, message and full traceback to the console; - logs the same through bec_logger, so it reaches the log files AND Redis and is therefore visible in `bec-log-monitor` and afterwards in the logs, rather than only on whichever console ran the macro; - includes _row_context: sample, template, both scan axes with ranges and step sizes, exposure time, and for tensor rows the rotation axes and angles, so a report identifies the row without needing the table alongside it; - guards SciLog and SMS separately, each reporting its own failure without touching the original exception. The caller still re-raises, so scan_repeat and the queue behave as before. Tests cover the two masking cases that mattered -- an unreachable SciLog and a failing SMS must not replace the original error -- plus the tensor context and that no SMS is attempted without phone numbers. Not changed, but flagged: @scan_repeat(max_repeats=3, default=True) retries any error three times, including deterministic ones. The file's own TODO warns about this. It triples the noise while diagnosing a reliably failing scan. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_0148tn6uK6oiTH25mzLfJcyc --- .../run_cont_grid_scan_for_table_row.py | 92 ++++++++++++----- .../test_run_cont_grid_scan_for_table_row.py | 99 +++++++++++++++++++ 2 files changed, 167 insertions(+), 24 deletions(-) create mode 100644 tests/tests_macros/test_run_cont_grid_scan_for_table_row.py diff --git a/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py b/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py index ce19b5a3..aed5198c 100644 --- a/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py +++ b/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py @@ -7,9 +7,75 @@ This dictionary is the input for this macro. from __future__ import annotations +import traceback + import numpy as np +from bec_lib.logger import bec_logger from bec_lib.scan_repeat import scan_repeat +logger = bec_logger.logger + + +def _row_context(row: dict) -> str: + """One line of scan context, so a failure report identifies the row on its own.""" + parts = [ + f"sample '{row.get('sample_name')}'", + f"ID {row.get('sample_id')}", + f"template {row.get('template')}", + f"fast {row.get('fast_axis')} {row.get('fast_start')}..{row.get('fast_stop')}" + f" step {row.get('fast_step')}", + f"stepper {row.get('stepper_axis')} {row.get('stepper_start')}..{row.get('stepper_stop')}" + f" step {row.get('stepper_step')}", + f"exp_time {row.get('exposure_time')}", + ] + if row.get("template") == "tensor": + parts.append( + f"rotx {row.get('rotx_axis')}={row.get('rotx')}, " + f"roty {row.get('roty_axis')}={row.get('roty')}" + ) + return ", ".join(str(p) for p in parts) + + +def _report_failure(info_msg: str, exc: Exception, row: dict, phone_numbers) -> None: + """Report a failure everywhere it might be looked for, without ever masking it. + + The original exception is always re-raised by the caller. Notification channels are + best effort and individually guarded: an unreachable SciLog must not replace the + error it was trying to report, which is how a one-line DeviceConfigError went + undiagnosed through three retries and several beamtime hours. + + The traceback is printed AND logged. Logging matters because bec_logger fans out to + the log files and to Redis, so the failure is then visible in `bec-log-monitor` and + afterwards in the logs -- not only on whichever console happened to run the macro. + """ + context = _row_context(row) + detail = traceback.format_exc() + + print(f"{info_msg}\n {context}\n {type(exc).__name__}: {exc}\n{detail}") + logger.error(f"{info_msg} [{context}]\n{detail}") + + try: + msg = bec.messaging.scilog.new() + msg.add_tags("error") + msg.add_text(info_msg) + msg.add_text(context) + msg.add_text(f"Error details: {type(exc).__name__}: {exc}") + msg.add_text(f"```\n{detail}\n```") + msg.send() + except Exception: # pylint: disable=broad-except + # Never let the reporting channel become the reported error. + print(f"Additionally, posting this failure to SciLog failed:\n{traceback.format_exc()}") + logger.warning(f"SciLog post failed while reporting: {info_msg}") + + if phone_numbers: + try: + msg = bec.messaging.signal.new() + msg.add_text(f"{info_msg} {context}") + msg.send(scope=phone_numbers) + except Exception: # pylint: disable=broad-except + print(f"Additionally, the SMS notification failed:\n{traceback.format_exc()}") + logger.warning(f"SMS notification failed while reporting: {info_msg}") + # TODO Default True here means that ANY error will be retried up to 3 times. This is dangerous in the sense that # if the error is due to a misconfiguration of the scan parameters, it will just keep retrying and failing. @@ -87,18 +153,7 @@ def run_cont_grid_scan_for_table_row( "Error while moving motors to starting position for sample " f"'{row['sample_name']}' (ID: {row['sample_id']})." ) - print(info_msg) - # Send message to scilog with error tag and text - msg = bec.messaging.scilog.new() - msg.add_tags("error") - msg.add_text(info_msg) - msg.add_text(f"Error details: {e}") - msg.send() - # Notify the user via SMS if phone numbers are provided - if phone_numbers: - msg = bec.messaging.signal.new() - msg.add_text(info_msg) - msg.send(scope=phone_numbers) + _report_failure(info_msg, e, row, phone_numbers) raise # Scan command @@ -121,16 +176,5 @@ def run_cont_grid_scan_for_table_row( f"Error while executing cont_grid scan for sample '{row['sample_name']}' " f"with ID '{row['sample_id']}'." ) - print(info_msg) - # Send message to scilog with error tag and text - msg = bec.messaging.scilog.new() - msg.add_tags("error") - msg.add_text(info_msg) - msg.add_text(f"Error details: {e}") - msg.send() - # Notify the user via SMS if phone numbers are provided - if phone_numbers: - msg = bec.messaging.signal.new() - msg.add_text(info_msg) - msg.send(scope=phone_numbers) + _report_failure(info_msg, e, row, phone_numbers) raise diff --git a/tests/tests_macros/test_run_cont_grid_scan_for_table_row.py b/tests/tests_macros/test_run_cont_grid_scan_for_table_row.py new file mode 100644 index 00000000..9c19be78 --- /dev/null +++ b/tests/tests_macros/test_run_cont_grid_scan_for_table_row.py @@ -0,0 +1,99 @@ +"""Tests for the failure reporting of the cont_grid table-row macro. + +The macro runs in the BEC client namespace, where `bec`, `dev` and `scans` are globals +injected by the client. The tests inject a mock `bec` into the module namespace so the +reporting path can be exercised without a session. +""" + +from unittest import mock + +import pytest + +from csaxs_bec.macros import run_cont_grid_scan_for_table_row as macro + +ROW = { + "sample_name": "test40ms", + "sample_id": "3c6e18db10b547aeb86804f524a49489", + "template": "tensor", + "fast_axis": "samx", + "fast_start": -1, + "fast_stop": 1, + "fast_step": 0.01, + "stepper_axis": "samy", + "stepper_start": 0, + "stepper_stop": 1, + "stepper_step": 0.1, + "exposure_time": 0.04, + "rotx_axis": "sgchi", + "rotx": 12.0, + "roty_axis": "sgphi", + "roty": 34.0, +} + + +@pytest.fixture +def mock_bec(): + """Inject a mock `bec` global, as the client would.""" + with mock.patch.object(macro, "bec", mock.MagicMock(), create=True) as m: + yield m + + +def _raise_and_report(mock_row, phone_numbers=None): + """Call the reporter from inside a real except block, so format_exc() has a traceback.""" + try: + raise RuntimeError("the original failure") + except RuntimeError as exc: + macro._report_failure("Something went wrong.", exc, mock_row, phone_numbers) + return exc + + +def test_row_context_names_the_rotation_axes_for_tensor_rows(): + """A tensor failure report must identify which axes and angles were involved.""" + context = macro._row_context(ROW) + assert "sgchi=12.0" in context + assert "sgphi=34.0" in context + assert "test40ms" in context + + +def test_row_context_omits_rotations_for_scanning_rows(): + row = dict(ROW, template="scanning") + assert "sgchi" not in macro._row_context(row) + + +def test_report_prints_the_traceback(mock_bec, capsys): + """The detail must reach the console, not only SciLog.""" + _raise_and_report(ROW) + out = capsys.readouterr().out + assert "the original failure" in out + assert "RuntimeError" in out + assert "Traceback" in out + + +def test_scilog_failure_does_not_mask_the_original_error(mock_bec, capsys): + """A broken SciLog must not become the reported error. + + This is the defect that let a one-line DeviceConfigError survive three retries and + several hours: the unguarded post raised, replacing the exception it was reporting. + """ + mock_bec.messaging.scilog.new.side_effect = ConnectionError("scilog is down") + + _raise_and_report(ROW) # must not raise + + out = capsys.readouterr().out + assert "the original failure" in out # original still reported + assert "SciLog" in out # and the reporting failure is noted + + +def test_sms_failure_does_not_mask_the_original_error(mock_bec, capsys): + mock_bec.messaging.signal.new.side_effect = ConnectionError("no gateway") + + _raise_and_report(ROW, phone_numbers=["+41000000000"]) # must not raise + + out = capsys.readouterr().out + assert "the original failure" in out + assert "SMS" in out + + +def test_no_sms_is_attempted_without_phone_numbers(mock_bec): + _raise_and_report(ROW, phone_numbers=None) + mock_bec.messaging.signal.new.assert_not_called() -- 2.54.0 From d85da7073068697595d3e3ca960c1fde22c3d2cd Mon Sep 17 00:00:00 2001 From: menzel Date: Fri, 4 Sep 2026 20:27:51 +0200 Subject: [PATCH 3/3] fix(macros): no module-level assignment, or the loader refuses the file The previous commit added `logger = bec_logger.logger` at module level. The macro loader rejects any module-level ast.Assign (bec_lib.macro_update_handler.has_executable_code) and then refuses the whole file, so run_cont_grid_scan_for_table_row stopped being loaded at all: Macro file .../run_cont_grid_scan_for_table_row.py contains executable code at module level (line 16) and will not be loaded for security reasons. Imports, defs, classes, annotated assignments and docstrings are permitted; plain assignments are not. The logger is now fetched inside the functions. Adds a test that runs the real has_executable_code over every macro, so this is caught by the suite instead of by a WARNING in the log stream. Verified to fail when a module-level assignment is reintroduced. Noticed only because bec-log-monitor happened to be running at the time -- a refused macro is otherwise indistinguishable from one that was never installed. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_0148tn6uK6oiTH25mzLfJcyc --- .../macros/run_cont_grid_scan_for_table_row.py | 10 ++++++---- tests/tests_macros/test_macro_device_access.py | 18 ++++++++++++++++++ 2 files changed, 24 insertions(+), 4 deletions(-) diff --git a/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py b/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py index aed5198c..d4099d76 100644 --- a/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py +++ b/csaxs_bec/macros/run_cont_grid_scan_for_table_row.py @@ -13,7 +13,9 @@ import numpy as np from bec_lib.logger import bec_logger from bec_lib.scan_repeat import scan_repeat -logger = bec_logger.logger +# NOTE No module-level assignments in a macro: the loader rejects any ast.Assign at module +# level (bec_lib.macro_update_handler.has_executable_code) and refuses the whole file, so +# the logger is fetched inside the functions rather than bound to a module global. def _row_context(row: dict) -> str: @@ -52,7 +54,7 @@ def _report_failure(info_msg: str, exc: Exception, row: dict, phone_numbers) -> detail = traceback.format_exc() print(f"{info_msg}\n {context}\n {type(exc).__name__}: {exc}\n{detail}") - logger.error(f"{info_msg} [{context}]\n{detail}") + bec_logger.logger.error(f"{info_msg} [{context}]\n{detail}") try: msg = bec.messaging.scilog.new() @@ -65,7 +67,7 @@ def _report_failure(info_msg: str, exc: Exception, row: dict, phone_numbers) -> except Exception: # pylint: disable=broad-except # Never let the reporting channel become the reported error. print(f"Additionally, posting this failure to SciLog failed:\n{traceback.format_exc()}") - logger.warning(f"SciLog post failed while reporting: {info_msg}") + bec_logger.logger.warning(f"SciLog post failed while reporting: {info_msg}") if phone_numbers: try: @@ -74,7 +76,7 @@ def _report_failure(info_msg: str, exc: Exception, row: dict, phone_numbers) -> msg.send(scope=phone_numbers) except Exception: # pylint: disable=broad-except print(f"Additionally, the SMS notification failed:\n{traceback.format_exc()}") - logger.warning(f"SMS notification failed while reporting: {info_msg}") + bec_logger.logger.warning(f"SMS notification failed while reporting: {info_msg}") # TODO Default True here means that ANY error will be retried up to 3 times. This is dangerous in the sense that diff --git a/tests/tests_macros/test_macro_device_access.py b/tests/tests_macros/test_macro_device_access.py index f46dcc60..0daa2c00 100644 --- a/tests/tests_macros/test_macro_device_access.py +++ b/tests/tests_macros/test_macro_device_access.py @@ -10,6 +10,7 @@ import ast import pathlib import pytest +from bec_lib.macro_update_handler import has_executable_code MACRO_DIR = pathlib.Path(__file__).resolve().parents[2] / "csaxs_bec" / "macros" MACROS = sorted(p for p in MACRO_DIR.glob("*.py") if p.name != "__init__.py") @@ -42,3 +43,20 @@ def test_macros_do_not_go_through_dev_devices(macro: pathlib.Path): f"{macro.name}: line(s) {offenders} use dev.devices -- `dev` is the device " "container itself, so this raises DeviceConfigError at runtime. Use dev[]." ) + + +@pytest.mark.parametrize("macro", MACROS, ids=lambda p: p.name) +def test_macros_are_loadable_by_the_macro_loader(macro: pathlib.Path): + """A module-level statement makes the loader refuse the whole file, silently. + + bec_lib.macro_update_handler.has_executable_code rejects any module-level node that + is not an import, a def, a class, an annotated assignment or a docstring -- a plain + `logger = bec_logger.logger` is enough. The macro is then simply not loaded, and the + only trace is a WARNING in the log stream, so a broken macro looks like a macro that + was never there. The real checker is used here rather than a re-implementation. + """ + blocked, lineno = has_executable_code(macro.read_text()) + assert not blocked, ( + f"{macro.name}: module-level executable code at line {lineno}; the macro loader " + "will refuse the file. Move it inside a function, or use an annotated assignment." + ) -- 2.54.0