Merge remote-tracking branch 'origin/main' into fix/inspect-video-settle-followups

TESTING.md

@@ -50,6 +50,13 @@ stdin open and the server (`--exit-on-stdin-eof`) shuts down cleanly, removing i
 temp root, when that pipe closes, so a worker killed without teardown leaves no
 server behind. A test that fails gets the stderr its server wrote during the test
 attached to the report as `server-stderr` (an aiohttp traceback behind a 500).
+A `/__test__/.../reset` still running after 2 s writes a report to the job log,
+passing test or not: every thread's stack taken while it waits, the default
+executor's threads and queue, the open connections and WAL size, then the total
+and how long each executor call queued and ran. Its lines start with
+`pm-slow-reset| ` (`tests/browser/slow_reset_watch.py`). The report never reads a
+connection another thread is using: one that is busy inside SQLite would block
+that read with the GIL held and freeze the whole server.
 
 The coverage run can be split the way CI splits it, and each shard keeps the raw
 V8 files it writes under `coverage/js/raw`:

tests/browser/server.py

@@ -19,6 +19,7 @@ from PIL import Image
 from PIL.PngImagePlugin import PngInfo
 
 from tests.browser.request_hold import register_request_holds
+from tests.browser import slow_reset_watch
 from tests.browser.workspace_activity_fixture import register_activity_commands
 from tests.browser.workspace_concept_fixture import (
     MAX_EXTRA_IMAGES as CONCEPT_MAX_EXTRA_IMAGES,
@@ -198,6 +199,7 @@ def create_app(root: Path) -> web.Application:
     reveal_stub = register_reveal_stub(routes, api, root)
     register_activity_commands(app, routes, api)
     request_holds = register_request_holds(app, routes)
+    slow_reset_watch.install(app, api)
 
     async def canonical_asset(request: web.Request) -> web.Response:
         filename, content_type = CANONICAL_ASSETS[request.path]

tests/browser/slow_reset_watch.py

@@ -0,0 +1,237 @@
+"""Report a slow test reset with what the server was doing while it waited.
+
+A reset normally answers within about a second. Once one runs past
+SLOW_RESET_SECONDS, this writes to stderr, while the reset is still waiting:
+
+- every thread's stack, so a reset waiting on a lock, a full executor or a
+  slow disk shows where it waits and who holds it;
+- the default executor's threads and queued work;
+- how many database connections are open, and the WAL size;
+- on Linux, each thread's scheduler state and the kernel function it sleeps
+  in (``D`` with a journal or writeback wait is a slow disk flush, a nanosleep
+  is SQLite's busy handler, a futex is a Python lock or an idle worker).
+
+When the reset ends it writes how long it took and, for each executor call it
+made, how long the call queued and how long it ran.
+
+Every report line starts with REPORT_PREFIX. The worker fixture
+(tools/vendor/start-browser-server.mjs) copies those lines to the job log,
+so a slow reset is visible even in a test that still passes.
+"""
+
+import asyncio
+import contextvars
+import faulthandler
+import os
+import sys
+import tempfile
+import threading
+import time
+from typing import Callable, TextIO
+
+from aiohttp import web
+
+SLOW_RESET_SECONDS = 2.0
+REPORT_PREFIX = "pm-slow-reset| "
+
+_current: contextvars.ContextVar["ResetWatch | None"] = contextvars.ContextVar(
+    "pm_reset_watch", default=None
+)
+
+
+def is_reset_path(path: str) -> bool:
+    return path.startswith("/__test__/") and path.endswith("/reset")
+
+
+class ResetWatch:
+    """Time one reset; dump the server's state if it passes the threshold."""
+
+    def __init__(
+        self,
+        label: str,
+        describe: Callable[[], list[str]],
+        *,
+        threshold: float = SLOW_RESET_SECONDS,
+        stream: TextIO | None = None,
+    ) -> None:
+        self.label = label
+        self.threshold = threshold
+        self._describe = describe
+        self._stream = stream
+        self._start = time.monotonic()
+        self._calls: list[str] = []
+        self._calls_lock = threading.Lock()
+        self._stalled = threading.Event()
+        self._timer = threading.Timer(threshold, self._report_stall)
+        self._timer.daemon = True
+        self._timer.name = "pm-slow-reset-watch"
+
+    def start(self) -> "ResetWatch":
+        self._timer.start()
+        return self
+
+    def elapsed(self) -> float:
+        return time.monotonic() - self._start
+
+    def record_call(self, name: str, queued: float, ran: float) -> None:
+        with self._calls_lock:
+            self._calls.append(
+                f"executor call {name}: queued {queued:.3f}s, ran {ran:.3f}s"
+            )
+
+    def finish(self, outcome: str) -> None:
+        self._timer.cancel()
+        elapsed = self.elapsed()
+        # A coarse clock (Windows) can fire the timer just short of the
+        # threshold; a reset that was reported always gets its summary.
+        if elapsed < self.threshold and not self._stalled.is_set():
+            return
+        with self._calls_lock:
+            calls = list(self._calls)
+        self._write([f"{self.label} {outcome} after {elapsed:.3f}s", *calls])
+
+    def _report_stall(self) -> None:
+        self._stalled.set()
+        lines = [f"{self.label} still running after {self.elapsed():.3f}s"]
+        try:
+            lines.extend(self._describe())
+        except Exception as error:  # a diagnostic never breaks the reset
+            lines.append(f"state unavailable: {error!r}")
+        lines.extend(thread_stacks())
+        self._write(lines)
+
+    def _write(self, lines: list[str]) -> None:
+        stream = self._stream or sys.stderr
+        text = "".join(
+            f"{REPORT_PREFIX}{part}\n" for line in lines for part in line.splitlines()
+        )
+        try:
+            stream.write(text)
+            stream.flush()
+        except (OSError, ValueError):
+            pass
+
+
+def thread_stacks() -> list[str]:
+    """Every thread's stack, from faulthandler.
+
+    Formatting sys._current_frames() showed a thread blocked in SQLite as idle
+    (Python 3.14); faulthandler reports where each thread really is.
+    """
+    # Before Python 3.14 faulthandler prints ids only; name each id here.
+    names = [
+        f"thread 0x{thread.ident:016x} is {thread.name}"
+        for thread in threading.enumerate()
+        if thread.ident is not None
+    ]
+    with tempfile.TemporaryFile() as dump:
+        faulthandler.dump_traceback(file=dump, all_threads=True)
+        dump.seek(0)
+        return [*names, *dump.read().decode("utf-8", "replace").splitlines()]
+
+
+def executor_state(loop: asyncio.AbstractEventLoop) -> list[str]:
+    executor = getattr(loop, "_default_executor", None)
+    if executor is None:
+        return ["default executor: not started"]
+    threads = getattr(executor, "_threads", ())
+    queue = getattr(executor, "_work_queue", None)
+    queued = queue.qsize() if queue is not None else "?"
+    return [
+        f"default executor: {len(threads)} of "
+        f"{getattr(executor, '_max_workers', '?')} threads, {queued} queued"
+    ]
+
+
+def database_state(model) -> list[str]:
+    """How many connections are open, and the WAL size.
+
+    Never touches another thread's connection: a connection busy in SQLite
+    holds its mutex, and reading even ``in_transaction`` from here would block
+    on it while holding the GIL, freezing every thread until that query ends.
+    """
+    with model._conn_lock:
+        count = len(model._connections)
+    wal = model.db_path + "-wal"
+    size = os.path.getsize(wal) if os.path.exists(wal) else 0
+    return [f"database: {count} connections, WAL {size} bytes"]
+
+
+def kernel_wait_state() -> list[str]:
+    """Each thread's state and kernel wait channel, where /proc has them."""
+    lines = []
+    for thread in threading.enumerate():
+        task = f"/proc/self/task/{thread.native_id}"
+        try:
+            with open(f"{task}/stat", encoding="ascii") as stat:
+                state = stat.read().rsplit(")", 1)[1].split()[0]
+            with open(f"{task}/wchan", encoding="ascii") as wchan:
+                channel = wchan.read().strip() or "0"
+        except (OSError, IndexError):
+            continue
+        # The id matches the "Thread 0x..." headers of the stacks below.
+        lines.append(
+            f"kernel: {thread.name} (0x{thread.ident:016x}) state {state}, "
+            f"waiting in {channel}"
+        )
+    return lines
+
+
+def install(app: web.Application, api) -> None:
+    """Watch every reset route, and time the executor calls each one makes."""
+    run_in_executor = api._run_in_executor
+
+    async def timed_run_in_executor(func, *args, **kwargs):
+        watch = _current.get()
+        if watch is None:
+            return await run_in_executor(func, *args, **kwargs)
+        queued_at = time.monotonic()
+        started: list[float] = []
+
+        def timed(*call_args, **call_kwargs):
+            started.append(time.monotonic())
+            return func(*call_args, **call_kwargs)
+
+        try:
+            return await run_in_executor(timed, *args, **kwargs)
+        finally:
+            end = time.monotonic()
+            begin = started[0] if started else end
+            watch.record_call(
+                getattr(func, "__qualname__", repr(func)),
+                begin - queued_at,
+                end - begin,
+            )
+
+    api._run_in_executor = timed_run_in_executor
+
+    @web.middleware
+    async def watch_resets(request: web.Request, handler):
+        if not is_reset_path(request.path):
+            return await handler(request)
+        loop = asyncio.get_running_loop()
+
+        def describe() -> list[str]:
+            return [
+                *executor_state(loop),
+                *database_state(api.db.model),
+                *kernel_wait_state(),
+            ]
+
+        watch = ResetWatch(
+            f"{request.method} {request.path}", describe, threshold=SLOW_RESET_SECONDS
+        ).start()
+        token = _current.set(watch)
+        outcome = "failed"
+        try:
+            response = await handler(request)
+            outcome = f"answered {response.status}"
+            return response
+        except web.HTTPException as error:
+            outcome = f"answered {error.status}"
+            raise
+        finally:
+            _current.reset(token)
+            watch.finish(outcome)
+
+    app.middlewares.append(watch_resets)

tests/browser/workspace-tagging.spec.mjs

@@ -340,6 +340,9 @@ test('Tag opens the dialog without selecting the card', async ({ page }) => {
     const panel = page.getByRole('complementary', { name: 'Selected image details', exact: true });
     await page.goto(images);
     await expect(card(page, FIRST)).toHaveClass(/\bselected\b/);
+    // Capture the panel once it shows the first card's details, not while it is still reading them.
+    await expect(panel.getByRole('heading', { level: 2 })).toBeVisible();
+    await expect(panel).not.toContainText('Loading file details');
     const before = await panel.innerText();
     await openTag(page, SECOND, { goto: false });
     await page.keyboard.press('Escape');

tests/test_browser_slow_reset_watch.py

@@ -0,0 +1,234 @@
+"""A slow page-workflow reset reports where the server waited.
+
+CI run 39904288262 had one ``/__test__/reset`` wait 16 s with nothing in the
+server's stderr. tests/browser/slow_reset_watch.py reports any reset past
+SLOW_RESET_SECONDS with every thread's stack, taken while it still waits.
+These tests hold a real SQLite write lock behind a real test server's reset.
+"""
+
+import glob
+import io
+import os
+import sqlite3
+import subprocess
+import sys
+import tempfile
+import threading
+import time
+import unittest
+import urllib.request
+from pathlib import Path
+
+from tests.browser import slow_reset_watch
+from tests.browser.slow_reset_watch import REPORT_PREFIX, ResetWatch, is_reset_path
+
+REPO_ROOT = Path(__file__).resolve().parent.parent
+SERVER_TIMEOUT_S = 60
+HOLD_SECONDS = slow_reset_watch.SLOW_RESET_SECONDS + 4
+# The reset may take a little longer than the hold, never the 30 s busy timeout.
+RESET_MARGIN_SECONDS = 10
+# While the reset waits, the server still answers other requests this fast.
+# Reading the waiting connection from the report's thread froze it (the GIL is
+# held while SQLite's connection mutex is awaited) until the lock was released.
+RESPONSIVE_SECONDS = 2.0
+PROBE_INTERVAL_SECONDS = 0.1
+
+
+def blocked_here(gate: threading.Event) -> None:
+    gate.wait()
+
+
+class TestResetWatch(unittest.TestCase):
+    def test_reset_paths_are_the_test_reset_routes(self):
+        self.assertTrue(is_reset_path("/__test__/reset"))
+        self.assertTrue(is_reset_path("/__test__/tagging/reset"))
+        self.assertFalse(is_reset_path("/prompt_manager/reset"))
+        self.assertFalse(is_reset_path("/__test__/reset/extra"))
+
+    def test_a_stalled_reset_reports_state_and_stacks_while_it_waits(self):
+        stream = io.StringIO()
+        reported = threading.Event()
+
+        class Stream(io.StringIO):
+            def flush(self):
+                reported.set()
+
+        stream = Stream()
+        gate = threading.Event()
+        worker = threading.Thread(target=blocked_here, args=(gate,), name="held-up")
+        worker.start()
+        self.addCleanup(worker.join)
+        self.addCleanup(gate.set)
+        watch = ResetWatch(
+            "POST /__test__/reset",
+            lambda: ["database: 1 connections"],
+            threshold=0.05,
+            stream=stream,
+        ).start()
+        self.assertTrue(reported.wait(SERVER_TIMEOUT_S))
+        report = stream.getvalue().splitlines()
+        self.assertTrue(all(line.startswith(REPORT_PREFIX) for line in report))
+        text = "\n".join(report)
+        self.assertIn("POST /__test__/reset still running after", text)
+        self.assertIn("database: 1 connections", text)
+        self.assertIn(f"thread 0x{worker.ident:016x} is held-up", text)
+        self.assertIn("in blocked_here", text)
+
+        watch.record_call("seed", 0.25, 1.5)
+        watch.finish("answered 200")
+        self.assertIn("POST /__test__/reset answered 200 after", stream.getvalue())
+        self.assertIn(
+            "executor call seed: queued 0.250s, ran 1.500s", stream.getvalue()
+        )
+
+    def test_a_fast_reset_writes_nothing_and_stops_its_timer(self):
+        stream = io.StringIO()
+        watch = ResetWatch("reset", lambda: [], threshold=60, stream=stream).start()
+        watch.finish("answered 200")
+        self.assertTrue(watch._timer.finished.is_set())
+        self.assertEqual(stream.getvalue(), "")
+
+    def test_a_failing_state_probe_still_reports_the_stacks(self):
+        def broken():
+            raise RuntimeError("no state")
+
+        reported = threading.Event()
+
+        class Stream(io.StringIO):
+            def flush(self):
+                reported.set()
+
+        stream = Stream()
+        ResetWatch("reset", broken, threshold=0.01, stream=stream).start()
+        self.assertTrue(reported.wait(SERVER_TIMEOUT_S))
+        self.assertIn("state unavailable: RuntimeError('no state')", stream.getvalue())
+        self.assertIn("most recent call first", stream.getvalue())
+
+
+class TestSlowResetOnTheServer(unittest.TestCase):
+    """A reset behind another process's write lock, on tests/browser/server.py."""
+
+    def setUp(self):
+        self.tmp = tempfile.TemporaryDirectory()
+        self.addCleanup(self.tmp.cleanup)
+        env = {**os.environ, "TMPDIR": self.tmp.name}
+        env.update(TEMP=self.tmp.name, TMP=self.tmp.name)
+        self.stderr = tempfile.TemporaryFile()
+        self.addCleanup(self.stderr.close)
+        process = subprocess.Popen(
+            [sys.executable, "-m", "tests.browser.server", "--port", "0"],
+            cwd=REPO_ROOT,
+            env=env,
+            stdin=subprocess.PIPE,
+            stdout=subprocess.PIPE,
+            stderr=self.stderr,
+        )
+
+        def stop():
+            if process.poll() is None:
+                process.kill()
+            process.wait(timeout=SERVER_TIMEOUT_S)
+            for stream in (process.stdin, process.stdout):
+                stream.close()
+
+        self.addCleanup(stop)
+        line = process.stdout.readline().decode()
+        self.assertTrue(line.startswith("PM_TEST_SERVER_PORT="), line)
+        self.base = f"http://127.0.0.1:{int(line.split('=', 1)[1])}"
+        deadline = time.monotonic() + SERVER_TIMEOUT_S
+        while True:
+            try:
+                with urllib.request.urlopen(  # nosec B310
+                    self.base + "/prompt_manager/test", timeout=1
+                ):
+                    break
+            except OSError:
+                self.assertIsNone(process.poll(), "the server exited early")
+                self.assertLess(time.monotonic(), deadline, "never ready")
+                time.sleep(0.1)
+        [self.db_path] = glob.glob(
+            os.path.join(self.tmp.name, "pm-browser-*", "browser.db")
+        )
+
+    def reset(self) -> tuple[int, float]:
+        request = urllib.request.Request(
+            self.base + "/__test__/reset",
+            data=b"{}",
+            headers={"Content-Type": "application/json"},
+            method="POST",
+        )
+        start = time.monotonic()
+        with urllib.request.urlopen(  # nosec B310
+            request, timeout=SERVER_TIMEOUT_S
+        ) as response:
+            return response.status, time.monotonic() - start
+
+    def server_stderr(self) -> str:
+        self.stderr.seek(0)
+        return self.stderr.read().decode("utf-8", "replace")
+
+    def test_a_reset_held_behind_a_write_lock_names_the_wait_and_ends_with_it(self):
+        self.assertEqual(self.reset()[0], 200, self.server_stderr())
+        self.assertNotIn(REPORT_PREFIX, self.server_stderr())
+
+        held = threading.Event()
+
+        def hold_write_lock():
+            holder = sqlite3.connect(self.db_path, timeout=SERVER_TIMEOUT_S)
+            try:
+                holder.execute("BEGIN IMMEDIATE")
+                held.set()
+                time.sleep(HOLD_SECONDS)
+                holder.rollback()
+            finally:
+                holder.close()
+
+        lock = threading.Thread(target=hold_write_lock)
+        lock.start()
+        self.addCleanup(lock.join)
+        self.assertTrue(held.wait(SERVER_TIMEOUT_S))
+        outcome = []
+        resetting = threading.Thread(target=lambda: outcome.append(self.reset()))
+        resetting.start()
+        self.addCleanup(resetting.join)
+        slowest = 0.0
+        while resetting.is_alive():
+            start = time.monotonic()
+            with urllib.request.urlopen(  # nosec B310
+                self.base + "/prompt_manager/test", timeout=SERVER_TIMEOUT_S
+            ):
+                slowest = max(slowest, time.monotonic() - start)
+            time.sleep(PROBE_INTERVAL_SECONDS)
+        resetting.join()
+        lock.join()
+        self.assertEqual(len(outcome), 1, self.server_stderr())
+        [(status, elapsed)] = outcome
+
+        self.assertLess(slowest, RESPONSIVE_SECONDS)
+        self.assertEqual(status, 200)
+        self.assertGreaterEqual(elapsed, HOLD_SECONDS - 0.5)
+        self.assertLess(elapsed, HOLD_SECONDS + RESET_MARGIN_SECONDS)
+        report = [
+            line[len(REPORT_PREFIX) :]
+            for line in self.server_stderr().splitlines()
+            if line.startswith(REPORT_PREFIX)
+        ]
+        text = "\n".join(report)
+        self.assertIn("POST /__test__/reset still running after", text)
+        self.assertIn("default executor:", text)
+        if sys.platform.startswith("linux"):
+            # SQLite's busy handler sleeps between its retries.
+            self.assertRegex(
+                text, r"kernel: asyncio_\d+ \(0x[0-9a-f]{16}\) state \w, waiting in "
+            )
+        # The plain reset's seed() waits on its first DELETE.
+        self.assertRegex(text, r"line \d+ in seed\n")
+        self.assertIn("POST /__test__/reset answered 200 after", text)
+        self.assertRegex(
+            text,
+            r"executor call create_app.<locals>.seed: queued \d+\.\d+s, ran \d+\.\d+s",
+        )
+
+
+if __name__ == "__main__":
+    unittest.main()

tests/test_execution_output_writer.py

@@ -299,45 +299,126 @@ class OutputWriterTests(fixtures.unittest.TestCase):
         )
         self.assertEqual(writer.context_budget.charged_bytes, 0)
 
+    def isolated_writer(self) -> HistoryWriter:
+        """A ready writer whose budget no other writer or test can charge."""
+        writer = HistoryWriter(
+            lambda: self.db, clock=self.clock, context_budget=ContextBudget()
+        )
+        self.writers.append(writer)
+        writer.start()
+        self.wait_for(lambda: writer.status().accepting)
+        return writer
+
+    def rotate_between_transactions(self, writer, start, after, restore, hold=None):
+        """Wrap ``after`` so a restore or invalidation lands right after it.
+
+        Returns the patch and an event set once that rotation has returned on
+        the worker. A restore is a full verify/migrate/backup/replace cycle, so
+        the handoff waits on this event with the generous ``BLOCK_SECONDS``
+        ceiling instead of the short worker-behavior deadline (TESTING.md,
+        Windows portability preflight).
+        """
+        backup = os.path.join(self.directory.name, f"restore-{start.run_id}.db")
+        self.assertTrue(self.db.model.backup_database(backup))
+        original = getattr(self.db, after)
+        rotated = threading.Event()
+
+        def write(*args, **kwargs):
+            result = original(*args, **kwargs)
+            try:
+                if hold is not None:
+                    entered, release = hold
+                    entered.set()
+                    release.wait(BLOCK_SECONDS)
+                if restore:
+                    self.db.model.restore_from_file(backup)
+                else:
+                    writer.invalidate()
+            finally:
+                rotated.set()
+            return result
+
+        return patch.object(self.db, after, write), rotated
+
     def test_restore_or_generation_rotation_between_transactions_discards_evidence(
         self,
     ):
         for after in ("write_execution_finish", "write_execution_contexts_for_finish"):
             for restore in (False, True):
                 with self.subTest(after=after, restore=restore):
-                    writer = self.writer()
-                    start = self.start_command(len(self.writers))
-                    self.db.write_execution_start(start)
-                    backup = os.path.join(self.directory.name, "restore.db")
-                    self.assertTrue(self.db.model.backup_database(backup))
-                    original = getattr(self.db, after)
+                    # Each subtest owns its writer and budget and retires them
+                    # before the next starts, so one slow restore cannot leave
+                    # in-flight charges or an epoch rotation for the next.
+                    writer = self.isolated_writer()
+                    try:
+                        start = self.start_command(len(self.writers))
+                        self.db.write_execution_start(start)
+                        rotation, rotated = self.rotate_between_transactions(
+                            writer, start, after, restore
+                        )
+                        with rotation:
+                            self.finalization(writer, start)
+                            self.assertTrue(rotated.wait(BLOCK_SECONDS))
+                            self.wait_for(lambda: writer.status().pending == 0)
+                        self.assertEqual(
+                            self.db.get_execution_outputs(start.run_id)["state"],
+                            "not_captured",
+                        )
+                        self.assertEqual(
+                            self.db.get_execution_contexts(start.run_id)["state"],
+                            (
+                                "complete"
+                                if after == "write_execution_contexts_for_finish"
+                                and not restore
+                                else "not_captured"
+                            ),
+                        )
+                        self.assertEqual(writer.context_budget.charged_bytes, 0)
+                    finally:
+                        self.assertTrue(writer.close(BLOCK_SECONDS))
 
-                    def write(*args, **kwargs):
-                        result = original(*args, **kwargs)
-                        if restore:
-                            self.db.model.restore_from_file(backup)
-                        else:
-                            writer.invalidate()
-                        return result
-
-                    with patch.object(self.db, after, write):
-                        self.finalization(writer, start)
-                        self.wait_for(lambda: writer.status().pending == 0)
-                    self.assertEqual(
-                        self.db.get_execution_outputs(start.run_id)["state"],
-                        "not_captured",
-                    )
-                    self.assertEqual(
-                        self.db.get_execution_contexts(start.run_id)["state"],
-                        (
-                            "complete"
-                            if after == "write_execution_contexts_for_finish"
-                            and not restore
-                            else "not_captured"
-                        ),
-                    )
-                    self.assertEqual(writer.context_budget.charged_bytes, 0)
-                    self.assertTrue(writer.close())
+    def test_slow_restore_between_transactions_holds_charge_only_while_in_flight(
+        self,
+    ):
+        writer = self.isolated_writer()
+        start = self.start_command()
+        self.db.write_execution_start(start)
+        entered, release = self.block()
+        rotation, rotated = self.rotate_between_transactions(
+            writer, start, "write_execution_finish", True, (entered, release)
+        )
+        with rotation:
+            context = self.sealed(writer)
+            outputs = self.outputs(writer, context.lease.byte_count)
+            charge = writer.context_budget.charged_bytes
+            self.assertGreater(charge, 0)
+            self.assertTrue(
+                writer.submit_finalization(self.finish_command(start), context, outputs)
+            )
+            self.assertTrue(entered.wait(BLOCK_SECONDS))
+            # The worker is between transactions: the payload is owned, not leaked.
+            self.assertEqual(writer.status().pending, 1)
+            self.assertEqual(writer.context_budget.charged_bytes, charge)
+            release.set()
+            self.assertTrue(rotated.wait(BLOCK_SECONDS))
+            self.wait_for(lambda: writer.status().pending == 0)
+        self.assertEqual(writer.context_budget.charged_bytes, 0)
+        self.assertFalse(writer.status().accepting)
+        self.assertEqual(
+            self.db.get_execution_outputs(start.run_id)["state"], "not_captured"
+        )
+        # The restored epoch is probed again and new evidence is accepted.
+        self.clock.advance(5)
+        self.wait_for(lambda: writer.status().accepting)
+        restored = self.start_command(2)
+        self.db.write_execution_start(restored)
+        self.finalization(writer, restored)
+        self.wait_for(lambda: writer.status().pending == 0)
+        self.assertEqual(
+            self.db.get_execution_outputs(restored.run_id)["state"], "complete"
+        )
+        self.assertEqual(writer.context_budget.charged_bytes, 0)
+        self.assertTrue(writer.close(BLOCK_SECONDS))
 
     def test_invalidation_during_output_preparation_rechecks_actual_commit(self):
         import database.execution_outputs as outputs_db

tests/vendor/browser-server-fixture.test.mjs

@@ -6,7 +6,7 @@ import { once } from 'node:events';
 import { readFileSync } from 'node:fs';
 import { fileURLToPath, pathToFileURL } from 'node:url';
 import { setTimeout as delay } from 'node:timers/promises';
-import { startBrowserServer, createServerSupervisor, attachServerStderr } from '../../tools/vendor/start-browser-server.mjs';
+import { startBrowserServer, createServerSupervisor, attachServerStderr, forwardPrefixedLines, SLOW_RESET_PREFIX } from '../../tools/vendor/start-browser-server.mjs';
 import { workflowWorkers } from '../../tools/vendor/test-workers.mjs';
 
 const fakeServer = fileURLToPath(new URL('./fake-browser-server.mjs', import.meta.url));
@@ -193,6 +193,29 @@ test('a failed test gets the server stderr written during it attached; a passing
     assert.equal(String(attached[0].body), 'Traceback (most recent call last): boom\n');
 });
 
+test('only complete slow-reset report lines are forwarded, however the chunks split them', () => {
+    const written = [];
+    const forward = forwardPrefixedLines(SLOW_RESET_PREFIX, text => written.push(text));
+    forward(`aiohttp access line\n${SLOW_RESET_PREFIX}POST /__test__/reset still`);
+    assert.deepEqual(written, [], 'a report line waits for its newline');
+    forward(` running after 2.000s\nplain stderr\n${SLOW_RESET_PREFIX}Thread 0x1 [asyncio_0]\n${SLOW_RESET_PREFIX.slice(0, 5)}`);
+    forward(`${SLOW_RESET_PREFIX.slice(5)}  File "server.py", line 1\nnot a report ${SLOW_RESET_PREFIX}\n`);
+    assert.deepEqual(written, [
+        `${SLOW_RESET_PREFIX}POST /__test__/reset still running after 2.000s\n${SLOW_RESET_PREFIX}Thread 0x1 [asyncio_0]\n`,
+        `${SLOW_RESET_PREFIX}  File "server.py", line 1\n`,
+    ]);
+});
+
+test('a slow-reset report on server stderr reaches the worker stderr; other stderr does not', async t => {
+    const reported = [];
+    const server = await startBrowserServer({ ...fake(), report: text => reported.push(text) });
+    t.after(() => server.stop());
+    await writeStderr(server, 'Traceback: ordinary stderr\n');
+    await writeStderr(server, `${SLOW_RESET_PREFIX}POST /__test__/reset answered 200 after 16.064s\n`);
+    assert.deepEqual(reported, [`${SLOW_RESET_PREFIX}POST /__test__/reset answered 200 after 16.064s\n`]);
+    assert.ok(server.stderrTail().includes('Traceback: ordinary stderr'), 'the stderr tail still keeps everything');
+});
+
 test('a server exits with its worker even when the worker is SIGKILLed', async () => {
     const pid = await serverOfKilledWorker(`{ command: process.execPath, args: port => [${JSON.stringify(fakeServer)}, '--port', String(port), '--exit-on-stdin-eof'] }`);
     await waitFor(() => !alive(pid), `server ${pid} to exit after its worker died`);

tools/vendor/start-browser-server.mjs

@@ -17,6 +17,22 @@ const HOST = '127.0.0.1';
 // tests/browser/server.py prints this once it holds its listening socket. Only a
 // complete line counts: a chunk may end mid-number.
 const PORT_ANNOUNCEMENT = /^PM_TEST_SERVER_PORT=(\d+)\r?\n/m;
+// tests/browser/slow_reset_watch.py starts every line of a slow-reset report with
+// this. Those lines go to the worker's stderr, so the job log shows a slow reset
+// even when its test passes.
+export const SLOW_RESET_PREFIX = 'pm-slow-reset| ';
+
+// A stderr chunk handler that passes every complete line starting with `prefix`
+// to `write`. A line split across chunks is held until its newline arrives.
+export function forwardPrefixedLines(prefix, write) {
+    let pending = '';
+    return chunk => {
+        const lines = (pending + chunk).split('\n');
+        pending = lines.pop().slice(-STDERR_TAIL_BYTES);
+        const matched = lines.filter(line => line.startsWith(prefix));
+        if (matched.length) write(matched.map(line => `${line}\n`).join(''));
+    };
+}
 
 // The server exits when its stdin closes, so a worker that dies without teardown
 // (SIGKILL) leaves no server behind; the launcher holds the pipe's other end.
@@ -40,6 +56,7 @@ export async function startBrowserServer({
     cwd = repositoryRoot,
     timeoutMs = STARTUP_TIMEOUT_MS,
     stderrLogChars = STDERR_LOG_CHARS,
+    report = chunk => process.stderr.write(chunk),
 } = {}) {
     if (!Number.isInteger(port) || port < 0 || port > 65535) {
         throw new Error(`startBrowserServer needs a port from 0 to 65535, got ${port}`);
@@ -50,7 +67,9 @@ export async function startBrowserServer({
     let stderr = '';
     let stderrTotal = 0;
     child.stderr.setEncoding('utf8');
+    const forwardReport = forwardPrefixedLines(SLOW_RESET_PREFIX, report);
     child.stderr.on('data', chunk => {
+        forwardReport(chunk);
         stderr = (stderr + chunk).slice(-Math.max(stderrLogChars, STDERR_TAIL_BYTES));
         stderrTotal += chunk.length;
     });