From d5d41d9eac3a0eaeb3ea1148865eb3a4bd39d440 Mon Sep 17 00:00:00 2001 From: menzel Date: Fri, 4 Sep 2026 19:56:56 +0200 Subject: [PATCH] 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()