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) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0148tn6uK6oiTH25mzLfJcyc
This commit is contained in:
2026-09-04 20:17:59 +02:00
committed by x12sa
co-authored by Claude Opus 5
parent e07320ce5d
commit d5d41d9eac
2 changed files with 167 additions and 24 deletions
@@ -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
@@ -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()