From 8a6b38784edbc1e4822c3e220d5ba80906422eb2 Mon Sep 17 00:00:00 2001 From: wshallwshall Date: Mon, 27 Jul 2026 08:05:11 -0500 Subject: [PATCH] fix(console): stop the message list livelocking under sustained refresh MessagesPanel._apply cleared the in-flight guard, then re-fired any refresh latched during the read and returned early, discarding the snapshot as "superseded". Whenever a caller refreshes faster than a read completes there is ALWAYS a latch waiting when the read lands, so every snapshot was discarded and the table never rendered -- permanently stuck, not slow. This is BACKLOG #17, which presented as a flaky harness-monitor test on Windows CI. It was never a timing flake: the test polls refresh() every 50ms, so once it entered the loop no deadline could escape it. That is why 10s->30s and reruns=2 both failed. Locally the engine processes the message before the panel connects, so the single initial refresh in _build_inner renders it and the polling path is never exercised at all; a loaded runner lost that race about a third of the time. A 20s probe measured 391 reads served, 0 rendered. Render first, then drain. Costs at most one read of staleness -- the drained refresh re-reads the current filters and renders again immediately, so the list still converges on the latest filter -- but it can no longer starve itself. Tests: - tests/test_console_messages_refresh.py, new. MessagesPanel had no test file at all, which is how this shipped: a unit form (a latched refresh must not discard the render) and a sustained-pressure form. - test_monitor_observes_a_message_that_arrives_after_connect, new. Writes the message AFTER connect so the initial snapshot is empty by construction, exercising the livelocked path deterministically rather than depending on losing a race. - _spin now takes one deadline shared across both waits instead of two independent 30s budgets, names the condition, and reports elapsed plus the status label (which carries "poll failed: ..."). Four CI failures produced only "condition not met within timeout", identical from either wait, and revealed nothing. - reruns=2 removed. It was added for this bug, would now only mask the next one, and makes the fix unmeasurable -- a masked failure looks exactly like a working one. All three new tests were verified to FAIL against the previous ordering. Note that CPU saturation does NOT reproduce this (the old code passes 3/3 under full-core load), so load stress is not a valid gate for it; the after-connect ordering is. --- harness/_console_widgets.py | 16 ++-- tests/test_console_messages_refresh.py | 103 +++++++++++++++++++++++++ tests/test_harness_monitor.py | 96 ++++++++++++++++++----- 3 files changed, 190 insertions(+), 25 deletions(-) create mode 100644 tests/test_console_messages_refresh.py diff --git a/harness/_console_widgets.py b/harness/_console_widgets.py index f2e57f0..1a74acc 100644 --- a/harness/_console_widgets.py +++ b/harness/_console_widgets.py @@ -44,12 +44,11 @@ QWidget, ) +from harness._async import AsyncRunner from messagefoundry.api.models import MessageDetail, MessageSummary from messagefoundry.apiclient import ApiError, EngineClient from messagefoundry.parsing import HL7PeekError, parse_tree -from harness._async import AsyncRunner - #: Shared "error red" for inline error text — the message-detail error, the auth dialogs' #: error labels, and the heart's stopped state — so the palette can't drift across modules. #: Carried over from the retired console theme so there is a single source of truth for this colour. @@ -506,12 +505,9 @@ def _fetch( def _apply(self, snap: _MessagesSnapshot, *, autosize: bool = False) -> None: """Runs on the main thread (result slot) — safe to touch widgets.""" self._loading = False - # A refresh was requested mid-flight (e.g. the filter changed) — re-fire it and skip rendering - # this now-superseded snapshot, so the list always reflects the latest filter. - if self._drain_pending(): - return if snap.error is not None: self.error.emit(snap.error) + self._drain_pending() return messages = snap.messages assert messages is not None @@ -541,6 +537,14 @@ def _apply(self, snap: _MessagesSnapshot, *, autosize: bool = False) -> None: # The selected message rolled off the list (deleted / filtered / aged past the 200-row # limit); tell the detail pane to clear so it stops showing a now-absent message (M2). self.selection_cleared.emit() + # LAST, and only after rendering: re-fire a refresh that was latched while this one was in + # flight. This used to run FIRST and `return` early, discarding the snapshot as "superseded" + # — which livelocked the panel (BACKLOG #17). Under sustained refresh pressure there is ALWAYS + # a latched request when a fetch lands, so every snapshot was discarded and the table never + # updated: not slow, permanently stuck. Rendering first costs at most one fetch of staleness + # (the drained refresh re-reads the current filters and renders again immediately), and the + # list still converges on the latest filter — but it can no longer starve itself. + self._drain_pending() def _on_select(self) -> None: message_id = self._selected_id() diff --git a/tests/test_console_messages_refresh.py b/tests/test_console_messages_refresh.py new file mode 100644 index 0000000..83c1d26 --- /dev/null +++ b/tests/test_console_messages_refresh.py @@ -0,0 +1,103 @@ +# SPDX-License-Identifier: AGPL-3.0-or-later +# Copyright (C) 2026 MessageFoundry Organization and contributors +"""MessagesPanel refresh convergence — the BACKLOG #17 livelock. + +``refresh()`` reads the message list off the main thread and guards against pile-up with ``_loading``; +a refresh requested mid-flight is latched in ``_pending`` and re-fired when the read lands. ``_apply`` +used to drain that latch FIRST and ``return`` early, discarding the snapshot as "superseded". + +That is a livelock, not an optimisation. Whenever a caller refreshes faster than a fetch completes +there is ALWAYS a latched request when the fetch lands, so EVERY snapshot was discarded and the table +never rendered — permanently, not slowly. It surfaced as a flaky harness-monitor test on loaded CI +runners (which lose the race the local machine wins), but the same wedge is reachable in the real GUI. + +These tests would both fail against the old ordering. +""" + +from __future__ import annotations + +import time +from types import SimpleNamespace +from typing import Any + +import pytest + +pytest.importorskip("PySide6") + +from harness._console_widgets import MessagesPanel, _MessagesSnapshot # noqa: E402 + + +@pytest.fixture(scope="module") +def qapp() -> Any: + from PySide6.QtWidgets import QApplication + + return QApplication.instance() or QApplication([]) + + +def _msg(mid: str) -> Any: + return SimpleNamespace( + id=mid, + received_at=1_780_000_000.0, + channel_id="ch", + event="ADT^A01", + message_type="ADT", + status="delivered", + control_id=mid, + summary="", + metadata="", + ) + + +class _FakeClient: + """Only the surface MessagesPanel._fetch touches. ``delay`` makes the read slower than the caller's + refresh cadence, which is precisely the condition that used to wedge the panel.""" + + def __init__(self, *, delay: float = 0.0) -> None: + self._delay = delay + self.calls = 0 + + def list_messages(self, **_kw: Any) -> Any: + self.calls += 1 + if self._delay: + time.sleep(self._delay) + return SimpleNamespace(messages=[_msg("m1")], total=1) + + def search_messages(self, **_kw: Any) -> Any: # pragma: no cover - no filters are set here + raise AssertionError("content search should not be reached without a content/field filter") + + +def test_a_latched_refresh_no_longer_discards_the_snapshot(qapp: Any) -> None: + """The unit form: _apply must RENDER even when another refresh is already latched behind it.""" + panel = MessagesPanel(_FakeClient()) # type: ignore[arg-type] + try: + panel._loading = True # a read is in flight... + panel._pending = False # ...and a second refresh was latched behind it + panel._apply(_MessagesSnapshot([_msg("m1")], "1 shown of 1", False, None)) + + assert panel._table.rowCount() == 1, ( + "snapshot discarded as 'superseded' — this is the BACKLOG #17 livelock" + ) + # Dropping the render must not come back as dropping the re-fire either. + assert panel._pending is None, "the latched refresh was never drained" + finally: + panel.stop() + + +def test_sustained_refresh_pressure_still_converges(qapp: Any) -> None: + """The integration form, and the shape the harness-monitor test actually hits: a caller polling + refresh() faster than the read completes. Every _apply lands with a latch set, so under the old + ordering the table stayed empty forever and this loop ran to its deadline.""" + panel = MessagesPanel(_FakeClient(delay=0.05)) # type: ignore[arg-type] + deadline = time.time() + 15 + try: + while panel._table.rowCount() == 0 and time.time() < deadline: + panel.refresh() # 5ms cadence vs a 50ms read — always latches + qapp.processEvents() + time.sleep(0.005) + + assert panel._table.rowCount() > 0, ( + f"table never rendered in 15s under sustained refresh (livelock); " + f"the fake engine served {panel._client.calls} reads, every one discarded" # type: ignore[attr-defined] + ) + finally: + panel.stop() diff --git a/tests/test_harness_monitor.py b/tests/test_harness_monitor.py index b6ac177..7eb708a 100644 --- a/tests/test_harness_monitor.py +++ b/tests/test_harness_monitor.py @@ -88,18 +88,29 @@ def qapp() -> Any: return QApplication.instance() or QApplication([]) -def _spin(qapp: Any, predicate: Any, timeout: float = 30.0) -> None: - # 30s (was 10s): the predicate just needs the off-thread poller + file-poll + engine - # processing + API round-trips + a Qt event-loop turn to complete. That's a few seconds - # locally, but a loaded Windows CI runner intermittently overran 10s — a timing flake - # (BACKLOG #17), not a real failure. The generous deadline only ever extends a SLOW pass; - # a genuine hang still fails fast (predicate never true) well within the per-test watchdog. - deadline = time.time() + timeout +def _spin(qapp: Any, predicate: Any, what: str, deadline: float, context: Any = None) -> None: + """Pump the Qt event loop until ``predicate()`` holds, or the SHARED ``deadline`` passes. + + Takes an absolute deadline rather than a per-call timeout because this test makes two sequential + waits, and two independent budgets fail where one shared budget would not: a first wait that eats + 25s of its own 30s allowance still hands the second a full fresh 30s, so the pair can blow the + watchdog with most of it unspent — while a single budget simply absorbs the slow stage. + + ``what`` names the condition and ``context`` (called only on failure) reports live panel state, + including the status label — which carries ``poll failed: …`` when the background poller is + erroring. Both waits used to raise the same bare "condition not met within timeout", so four CI + failures never revealed which stage stalled, and the diagnosis had to start from nothing. + """ + start = time.time() while not predicate(): + if time.time() > deadline: + detail = f" | {context()}" if context is not None else "" + raise AssertionError( + f"{what}: still false after {time.time() - start:.1f}s " + f"(shared budget exhausted){detail}" + ) qapp.processEvents() time.sleep(0.05) - if time.time() > deadline: - raise AssertionError("condition not met within timeout") def test_poller_cancel_abandons_remaining_calls(qapp: Any) -> None: @@ -148,14 +159,16 @@ def test_monitor_panel_builds_disconnected(qapp: Any) -> None: panel.shutdown() # safe to call when never connected -# Override the global 60s per-test watchdog: this test makes two sequential _spin waits (30s each -# worst case) plus fixture/engine startup, so a slow-but-passing CI run could otherwise brush the -# 60s cap. 120s keeps an ample backstop without the watchdog itself becoming the flake. -# In-run auto-retry for the residual timing flake (BACKLOG #17): even with the 30s _spin + 120s -# watchdog, a heavily-loaded Windows runner still intermittently overran the _spin deadline. reruns=2 -# lets a single flake occurrence self-heal within the SAME CI run (up to 3 attempts) instead of reding -# the matrix and blocking the auto-merge pipeline; a genuine break still fails all attempts. -@pytest.mark.flaky(reruns=2) +# Override the global 60s per-test watchdog: the two waits share a 60s budget, and fixture/engine +# startup sits outside it, so a slow-but-passing CI run could otherwise brush the 60s cap. +# +# NO reruns=2 here any more, deliberately. It was added to let BACKLOG #17 "self-heal" within a run, +# on the theory that this was a residual timing flake on loaded Windows runners. It was not: the +# message list was livelocking (MessagesPanel._apply discarded every snapshot as superseded while this +# test polled refresh() at 50ms — see tests/test_console_messages_refresh.py), which is why neither +# 10s→30s nor the reruns ever fixed it. That is now fixed at the source. Keeping the retry would only +# hide the next real defect the same way it hid this one, and would make the fix unmeasurable — a +# masked failure looks exactly like a working one. @pytest.mark.timeout(120) def test_monitor_observes_engine(qapp: Any, server: tuple[str, Path]) -> None: url, inbox = server @@ -164,17 +177,62 @@ def test_monitor_observes_engine(qapp: Any, server: tuple[str, Path]) -> None: panel = MonitorPanel() panel._url.setText(url) panel._connect_btn.click() # connects (auth disabled) and starts the off-thread poller + deadline = time.time() + 60 # ONE budget spanning both waits, not 30s each try: assert panel._client is not None + + def ctx() -> str: + """Failure-path only. The status label carries 'poll failed: …' when the background + poller is erroring, which is otherwise invisible to this test.""" + return f"live_rows={_live_rows(panel)} status={panel._status.text()!r}" + # The poller runs on its own thread; processEvents() delivers its queued snapshot. - _spin(qapp, lambda: _live_rows(panel) > 0) + _spin( + qapp, lambda: _live_rows(panel) > 0, "live connections table populated", deadline, ctx + ) # The reused message list shows the delivered message with a disposition. - _spin(qapp, lambda: _has_message(panel, qapp)) + _spin(qapp, lambda: _has_message(panel, qapp), "delivered message in list", deadline, ctx) finally: panel.shutdown() assert panel._client is None +@pytest.mark.timeout(120) +def test_monitor_observes_a_message_that_arrives_after_connect( + qapp: Any, server: tuple[str, Path] +) -> None: + """The deterministic form of what CI kept hitting, and the reason BACKLOG #17 looked like a flake. + + The sibling test writes the message BEFORE the panel connects, so the single initial ``refresh()`` + in ``_build_inner`` normally renders it and the polling path below is never exercised at all. That + race is the whole difference between local and CI: a fast machine wins it every time, a loaded + runner lost it about a third of the time and then hit a livelock no timeout could escape. + + Connecting first makes the initial snapshot empty by construction, so the message can ONLY appear + via the 50ms ``refresh()`` polling — exercising the path that used to discard every snapshot. + """ + url, inbox = server + panel = MonitorPanel() + panel._url.setText(url) + panel._connect_btn.click() + (inbox / "a.hl7").write_bytes( + ADT.encode("utf-8") + ) # only AFTER the initial refresh has gone out + + deadline = time.time() + 60 + try: + assert panel._client is not None + _spin( + qapp, + lambda: _has_message(panel, qapp), + "message arriving after connect appears in list", + deadline, + lambda: f"status={panel._status.text()!r}", + ) + finally: + panel.shutdown() + + def _live_rows(panel: MonitorPanel) -> int: return panel._live_table.rowCount() if panel._live_table is not None else 0