diff --git a/electron/tests/_harness.cjs b/electron/tests/_harness.cjs index b9587f6f..d5272072 100644 --- a/electron/tests/_harness.cjs +++ b/electron/tests/_harness.cjs @@ -15,6 +15,12 @@ * `PLOTAPP:` JSON line protocol, e.g. `nav_drag_result`). * - canvas-pixel helpers (`countColorPixels`, `waitForNonBlackCanvas`) lifted * from visual.spec.ts / vi_lazy.spec.ts / vector_om_lazy.spec.ts. + * - NEVER FAIL BLIND: SPYDE_LOG_LEVEL defaults to WARNING (backend + * warnings/errors tee to the captured stderr), and an app/window that dies + * mid-test immediately console.errors the exit code + the last ~60 backend + * log lines (`backend.tail()`), so "browser has been closed" is always + * adjacent to the backend's last words. `app.close()` also attaches the + * tail to the test report. */ const { _electron: electron } = require('@playwright/test') const { join } = require('path') @@ -82,6 +88,15 @@ async function launchApp(opts = {}) { // Only mint a scratch dir if the spec didn't bring its own — otherwise // every first_run launch would also leave an unused one behind. ...(env.SPYDE_SETTINGS_DIR ? {} : { SPYDE_SETTINGS_DIR: _seenSettingsDir() }), + // Backend WARNINGS/ERRORS must reach the stderr this harness captures. + // Setting SPYDE_LOG_LEVEL makes the backend tee logging to stderr + // (app.py); without it, errors travel only the PLOTAPP stdout protocol + // the main process consumes — so a backend that dies mid-test dies + // SILENTLY ("browser has been closed" with no cause in the CI log). + // Default WARNING when neither the spec nor the shell set a level; specs + // that wait on INFO/DEBUG log lines already pass their own. + ...(env.SPYDE_LOG_LEVEL || process.env.SPYDE_LOG_LEVEL + ? {} : { SPYDE_LOG_LEVEL: 'WARNING' }), // Never hand a path to the desktop from a test. On a headless runner // xdg-open has no file manager to reach and leaves the app unable to // exit — examples_menu's afterAll timed out for 120s on app.close(). @@ -92,8 +107,47 @@ async function launchApp(opts = {}) { }) const backend = createBackend(app) + + // ---- never fail blind ---------------------------------------------------- + // When the app dies mid-test, Playwright reports only "Target page, context + // or browser has been closed" — the WHY (a backend traceback, an OOM kill) + // never reaches the CI log. Dump the backend's last words next to it. + // + // Best-effort handle on the current test: specs call launchApp() inside the + // test body, so test.info() resolves there (null outside a test). + let testInfo = null + try { testInfo = require('@playwright/test').test.info() } catch { /* not in a test */ } + let expectedClose = false + app.process().on('exit', (code, signal) => { + if (expectedClose) return + console.error( + `\n[harness] Electron process exited MID-TEST (code=${code}, signal=${signal}).` + + ` Backend log tail:\n${backend.tail()}\n`) + }) + // Wrap app.close() so (a) the exit listener above stays quiet for the + // spec's own finally-block close, and (b) the backend log tail is attached + // to the test (visible in the CI report for any failure). + const origClose = app.close.bind(app) + app.close = async () => { + expectedClose = true + if (testInfo) { + try { + await testInfo.attach('backend-log-tail', + { body: backend.tail(), contentType: 'text/plain' }) + } catch { /* attaching after teardown — best-effort only */ } + } + return origClose() + } + const page = await app.firstWindow() await page.waitForLoadState('domcontentloaded') + // A window that closes without the process dying (a renderer crash) hits + // neither listener above — cover it too. + page.on('close', () => { + if (expectedClose) return + console.error( + `\n[harness] app window closed MID-TEST. Backend log tail:\n${backend.tail()}\n`) + }) // Capture renderer errors from the FIRST paint, not after the mount wait // below. A module-level throw (a bad import, a TDZ reference) means React @@ -224,6 +278,9 @@ function createBackend(app) { waitForDask(timeout = 60_000) { return this.waitForLog('dask_ready', timeout) }, + /** The last `n` captured backend stdout+stderr lines, newline-joined — + * what launchApp dumps when the app dies mid-test. */ + tail(n = 60) { return logBuffer.slice(-n).join('\n') }, get logBuffer() { return logBuffer }, get messages() { return messages }, } diff --git a/spyde/drawing/update_functions.py b/spyde/drawing/update_functions.py index 761630c7..421ae927 100644 --- a/spyde/drawing/update_functions.py +++ b/spyde/drawing/update_functions.py @@ -939,7 +939,45 @@ def _try_async_expensive_nav_read(current_signal, selector, child, indices, prof return False -def _prepare_nav_indices(current_signal, indices, integrating: bool): +def _nav_readable_data(signal, data) -> bool: + """Can *data* (a captured ``signal.data`` binding) be sliced with this + signal's navigation coordinates at all? + + The tripwire case is hyperspy's ``_deepcopy_with_new_data``: it TRANSIENTLY + rebinds ``self.data = None`` on the LIVE signal object while it deep-copies + (the data setter's ``np.atleast_1d(np.asanyarray(None))`` makes that an + ``array([None], dtype=object)``, shape ``(1,)``) — and EVERY hyperspy + operation (arithmetic, comparison, ``sum``, ``deepcopy``) passes through it. + The math console evaluates user expressions (``s1 + 0``, incl. the live + preview's nav-refresh re-runs) against the SAME bound signal objects on the + console thread, so a navigator update on the dispatcher thread can land + inside that window: the signal still reports nav_shape (6, 6) but its data + is the 1-element placeholder → "too many indices for array" — the + second-signal IndexError, console flavour. ``_pending_future_data`` can't + catch it because ``data[0]`` is None, not a future. + + A None / object-dtype / under-dimensioned ``.data`` is never a readable + frame source, transient or not, so the caller skips the frame (returns + None → the last good frame stays up, same as the pending-future skip).""" + if data is None: + return False + if isinstance(data, np.ndarray) and data.dtype == object: + # The wrapped-future shape was already skipped by _pending_future_data; + # any OTHER object array is the deepcopy placeholder (or equally not a + # frame source). Catches the 1-D-navigator case the ndim check below + # can't (placeholder ndim 1 == nav_dim 1). + return False + ndim = getattr(data, "ndim", None) + if ndim is None: + return True # not array-like; leave it to the branches (as before) + try: + nav_dim = int(signal.axes_manager.navigation_dimension) + except Exception: + return True + return int(ndim) >= nav_dim + + +def _prepare_nav_indices(current_signal, indices, integrating: bool, data=None): """Transform RAW selector indices into DATA-ORDER, clamped array indices — the shared index-prep for the navigator read. @@ -951,6 +989,10 @@ def _prepare_nav_indices(current_signal, indices, integrating: bool): * clamp every coordinate to the leading (navigation) data-axis sizes so a stale/larger-grid selector position can't IndexError. + ``data`` (optional) is the caller's already-captured ``current_signal.data`` + binding — pass it so the clamp bounds and the eventual read use the SAME + array even if ``.data`` is concurrently rebound (see ``_nav_readable_data``). + Extracted so the MDI-overlay layer read (:mod:`spyde.actions.overlay`) resolves the SAME nav position as the base frame from the same raw selector indices. Returns the prepared ndarray (or None on failure).""" @@ -968,7 +1010,7 @@ def _prepare_nav_indices(current_signal, indices, integrating: bool): indices = np.mean(indices, axis=0).astype(int) try: - data_obj = current_signal.data + data_obj = data if data is not None else current_signal.data data_shape = getattr(data_obj, "shape", None) if data_shape is None: nav_shape_xy = tuple(current_signal.axes_manager.navigation_shape) @@ -1065,6 +1107,28 @@ def update_from_navigation_selection( getattr(current_signal.metadata.General, "title", "")) return None + # Capture `.data` ONCE for this read, and skip if the captured binding + # cannot satisfy the nav indices. hyperspy transiently rebinds `.data` on + # the LIVE signal object during ordinary operations (`_deepcopy_with_new_data` + # parks a shape-(1,) `array([None], dtype=object)` placeholder while it + # deep-copies), and the math console runs user expressions (`s1 + 0` — the + # live preview's nav-refresh) against these SAME objects on the console + # thread. Working from one captured reference (rebinds are GIL-atomic) plus + # this guard makes that race structurally harmless: a mid-window read skips + # the frame (the last good frame stays up, exactly like the pending-future + # skip above); a post-capture swap still clamps + indexes the coherent + # pre-swap array. See _nav_readable_data. + data_now = getattr(current_signal, "data", None) + if not _nav_readable_data(current_signal, data_now): + log.debug( + "nav read skipped: data %s cannot satisfy nav_shape %s — transient " + "placeholder from a concurrent hyperspy op on this signal (e.g. a " + "console evaluation), or a mis-shaped signal", + getattr(data_now, "shape", type(data_now).__name__), + tuple(current_signal.axes_manager.navigation_shape), + ) + return None + # Per-frame trace — gated behind SPYDE_NAV_TIMING because it fires on EVERY # crosshair move and floods the IPC log/panel at DEBUG (which itself adds lag). if _NAV_TIMING: @@ -1122,10 +1186,11 @@ def update_from_navigation_selection( # The swap + mean-reduce + clamp is shared with the MDI-overlay layer read # (spyde.actions.overlay) so a layer resolves the SAME nav position from the # same raw selector indices — see _prepare_nav_indices. - indices = _prepare_nav_indices(current_signal, indices, selector.is_integrating) + indices = _prepare_nav_indices(current_signal, indices, + selector.is_integrating, data=data_now) if current_signal._lazy: - if is_future_like(current_signal.data[0]): + if is_future_like(data_now[0]): current_img = np.ones(current_signal.axes_manager.signal_shape, dtype=np.int8) if current_img.ndim == 2: #make checkerboard pattern to indicate loading @@ -1218,7 +1283,7 @@ def update_from_navigation_selection( # sources keep their (un-rounded) mean. (Pinned by test_nav_cached_read.py.) with _prof.stage("dtype"): try: - src_dtype = getattr(current_signal.data, "dtype", None) + src_dtype = getattr(data_now, "dtype", None) if (src_dtype is not None and np.issubdtype(src_dtype, np.integer) and np.issubdtype(current_img.dtype, np.floating)): @@ -1251,10 +1316,10 @@ def update_from_navigation_selection( _idx = np.asarray(indices) is_single = (not selector.is_integrating) or _idx.ndim <= 1 if (am.navigation_dimension == 1 and is_single - and hasattr(current_signal.data, "shape")): - n_time = int(current_signal.data.shape[0]) + and hasattr(data_now, "shape")): + n_time = int(data_now.shape[0]) center = int(np.atleast_1d(_idx).ravel()[0]) - _movie_prefetcher.prime(current_signal.data, center, n_time) + _movie_prefetcher.prime(data_now, center, n_time) except Exception as _e: log.debug("movie prefetch prime failed: %s", _e) _prof.done("cache=" + ("hit" if _cache_hit else "MISS")) @@ -1269,22 +1334,25 @@ def update_from_navigation_selection( # 2-D-navigation diffraction pattern to 1-D. The Qt app never hit this # because it always loaded lazily (the Future branch above); eager # example datasets do. + # Index the CAPTURED binding (data_now), never a fresh `.data` read — + # the clamp above used its shape, so clamp and read stay coherent even + # if a console-thread hyperspy op rebinds `.data` mid-read. idx = np.asarray(indices) try: with _prof.stage("read"): if idx.ndim <= 1: point = tuple(int(v) for v in np.atleast_1d(idx)) - current_img = current_signal.data[point] + current_img = data_now[point] else: sl = tuple(idx[:, k].astype(int) for k in range(idx.shape[1])) - current_img = current_signal.data[sl].mean(axis=0) + current_img = data_now[sl].mean(axis=0) _prof.set_frame(current_img) except Exception: log.exception( "NAV-DEBUG eager index RAISED: indices=%s data.shape=%s " "nav_shape=%s — the second-signal IndexError", idx.tolist(), - getattr(getattr(current_signal, "data", None), "shape", None), + getattr(data_now, "shape", None), tuple(current_signal.axes_manager.navigation_shape), ) raise diff --git a/spyde/tests/migrated/test_nav_second_signal_race.py b/spyde/tests/migrated/test_nav_second_signal_race.py new file mode 100644 index 00000000..874bdbe1 --- /dev/null +++ b/spyde/tests/migrated/test_nav_second_signal_race.py @@ -0,0 +1,180 @@ +""" +The "second-signal IndexError", console flavour — a navigator update must never +index a signal whose ``.data`` is hyperspy's transient deepcopy placeholder. + +Mechanism (found via console_preview.spec.ts CI evidence: ``NAV-DEBUG eager +index RAISED: indices=[0, 0] data.shape=(1,) nav_shape=(6, 6)``): EVERY +hyperspy signal operation (arithmetic, comparison, ``sum``, ``deepcopy``) goes +through ``BaseSignal._deepcopy_with_new_data``, which TRANSIENTLY rebinds +``self.data = None`` on the live signal object while it deep-copies — and the +data setter's ``np.atleast_1d(np.asanyarray(None))`` turns that into an +``array([None], dtype=object)`` of shape ``(1,)``. The math console evaluates +user expressions (``s1 + 0`` — the eye-toggle live preview, re-run on every +nav commit via ``NAV_CHANGE_HOOKS``) against the SAME bound root-signal objects +on the console thread, so a navigator update on the serial ``_NavDispatcher`` +thread can land inside that window: the signal still reports its real +nav_shape, but its data is the 1-element placeholder → "too many indices for +array: array is 1-dimensional, but 2 were indexed". ``_pending_future_data`` +cannot catch it (``data[0]`` is None, not a future). + +The fix (``update_functions``): capture ``.data`` ONCE per read, skip the frame +when the captured binding cannot satisfy the nav indices (``_nav_readable_data`` +— the last good frame stays up, exactly like the pending-future skip), and +clamp + index that SAME captured reference so a post-capture swap still reads +the coherent pre-swap array. No locks, no generation counters — the serial +dispatcher model is untouched. +""" +from __future__ import annotations + +import logging +import threading +import time + +import numpy as np + +from spyde.drawing import update_functions as uf +from spyde.drawing.selectors.base_selector import _nav_dispatcher + + +def _nav_error_records(caplog): + """ERROR+ records from the nav-read module (the spec's failure signal).""" + return [r for r in caplog.records + if r.name == "spyde.drawing.update_functions" + and r.levelno >= logging.ERROR] + + +def _wait_dispatcher_idle(timeout: float = 3.0) -> None: + """Wait until the serial dispatcher has drained its pending queue (from + test_navigator_race.py).""" + end = time.monotonic() + timeout + while time.monotonic() < end: + with _nav_dispatcher._lock: + empty = not _nav_dispatcher._pending + if empty: + time.sleep(0.05) # let the in-flight job finish + return + time.sleep(0.01) + + +class TestNavSecondSignalRace: + """Pin: a shape-(1,) placeholder on a 2-D-navigated signal is SKIPPED (no + ERROR, no exception, last good frame stays) and the read recovers.""" + + @staticmethod + def _sel_and_child(session): + """The tree's navigation selector (composite + inner crosshair) and its + signal-plot child — the same lever _test_nav_drag uses.""" + tree = session.signal_trees[0] + mgr = tree.navigator_plot_manager + pw = next(iter(mgr.navigation_selectors.keys())) + sel = mgr.navigation_selectors[pw][0] + inner = getattr(sel, "selector", None) or sel + child = next(iter(sel.children.keys())) + return tree, sel, inner, child + + @staticmethod + def _drive(sel, inner, x, y, wait: bool = True): + """Park the crosshair at widget position (x, y) and run one forced + update through the REAL dispatcher path.""" + pos = np.array([[int(x), int(y)]]) + inner.get_selected_indices = lambda: pos + sel.delayed_update_data(force=True) + if wait: + _wait_dispatcher_idle() + + @staticmethod + def _wait_frame(child, expected, timeout: float = 3.0) -> bool: + end = time.monotonic() + timeout + while time.monotonic() < end: + cd = child.current_data + if cd is not None and np.array_equal(np.asarray(cd), expected): + return True + time.sleep(0.01) + return False + + def test_placeholder_window_skips_frame_without_error( + self, stem_4d_dataset, caplog): + """A nav update landing inside the deepcopy window is skipped quietly: + no ERROR log, the last good frame stays painted — and the SAME position + paints normally once the window closes (the main signal still updates). + """ + session = stem_4d_dataset["window"] + tree, sel, inner, child = self._sel_and_child(session) + root = tree.root + assert child.plot_state.current_signal is root + expected = np.array(root.data) # the real (4, 5, 16, 16) array + + # Painted baseline at data position (1, 1). + self._drive(sel, inner, 1, 1) + assert self._wait_frame(child, expected[1, 1]), \ + "baseline frame at (1, 1) never painted" + before = child.current_data + + # Open EXACTLY the transient window _deepcopy_with_new_data opens on + # the live signal: data becomes array([None], dtype=object), shape (1,), + # while axes_manager still reports nav (5, 4). + old = root.data + root.data = None + assert root.data.shape == (1,) and root.data.dtype == object + try: + self._drive(sel, inner, 2, 3) # → data order (3, 2) + finally: + root.data = old + + assert not _nav_error_records(caplog), \ + f"nav read errored inside the deepcopy window: {caplog.text}" + assert child.current_data is before, \ + "the skipped read must leave the last good frame painted" + + # The window has closed — the same position now reads and paints. + self._drive(sel, inner, 2, 3) + assert self._wait_frame(child, expected[3, 2]), \ + "the nav read did not recover after the placeholder window closed" + assert not _nav_error_records(caplog) + + def test_update_returns_none_mid_window(self, stem_4d_dataset): + """Direct-call determinism: update_from_navigation_selection with the + placeholder parked returns None (skip) instead of raising.""" + session = stem_4d_dataset["window"] + tree, sel, inner, child = self._sel_and_child(session) + root = tree.root + + old = root.data + root.data = None + try: + out = uf.update_from_navigation_selection( + inner, child, np.array([[0, 0]])) + finally: + root.data = old + assert out is None + + def test_console_shaped_op_race_never_errors(self, stem_4d_dataset, caplog): + """The real race shape: hammer ``root + 0`` — the exact expression the + console's eye-toggle live preview evaluates against the LIVE bound + signal on its own thread — while driving the dispatcher through many + positions. Before the fix this logged the second-signal IndexError on + a large fraction of moves (119/300 measured); with it, never.""" + session = stem_4d_dataset["window"] + tree, sel, inner, child = self._sel_and_child(session) + root = tree.root + + stop = threading.Event() + + def hammer(): + while not stop.is_set(): + _ = root + 0 # _deepcopy_with_new_data window on every call + + t = threading.Thread(target=hammer, daemon=True) + t.start() + try: + for i in range(150): + self._drive(sel, inner, i % 5, i % 4, wait=False) + time.sleep(0.003) + finally: + stop.set() + t.join(timeout=2.0) + _wait_dispatcher_idle() + + assert not _nav_error_records(caplog), ( + f"{len(_nav_error_records(caplog))} nav-read ERRORs under the " + f"console-op race:\n{caplog.text[:2000]}")