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