csaxs_bec/macros/run_cont_grid_scan_for_table_row.py

@@ -7,9 +7,77 @@ 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
 
+# 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:
+    """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}")
+    bec_logger.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()}")
+        bec_logger.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()}")
+            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
 # if the error is due to a misconfiguration of the scan parameters, it will just keep retrying and failing.
@@ -69,11 +137,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
@@ -84,18 +155,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
@@ -118,16 +178,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

tests/tests_macros/test_macro_device_access.py

@@ -0,0 +1,62 @@
+"""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
+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")
+
+
+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[<name>]."
+    )
+
+
+@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."
+    )

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()