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..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 @@ -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 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..0daa2c00 --- /dev/null +++ b/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[]." + ) + + +@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." + ) 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()