Compare commits

...
Author SHA1 Message Date
Vito Sansevero 1f134b3b64 Merge remote-tracking branch 'origin/main' into fix/inspect-video-settle-followups 2026-10-23 03:24:38 -07:00
Vito 4f1c6e236b test(browser): report a slow test reset with every thread's stack (#299)
* test(browser): report a slow test reset with every thread's stack

On #291 (run 39904288262, WebKit shard 2/2) one /__test__/reset
{chronological_history} waited 16 s on its worker's server, with nothing
on the server's stderr. The cause did not reproduce: the same worker's
file sequence (library, library editor, tagging lifecycle, visual) at
2 CPUs three times, and WebKit shard 2/2 at 2 CPUs, kept every reset
under 2 s.

A reset still running after 2 s now reports, while it waits, every
thread's stack (faulthandler), the default executor's threads and queue,
the open connections and WAL size, and on Linux each thread's scheduler
state and kernel wait channel. When it ends it reports the total and how
long each executor call queued and ran. The lines carry a
"pm-slow-reset| " prefix and the worker fixture copies them to the job
log, so the next one shows up even in a test that passes.

The report never reads another thread's connection. Reading even
in_transaction on a connection busy in SQLite blocks on its mutex with
the GIL held: a first version of this report froze the whole server
until the 30 s busy timeout. A test holds a real write lock behind a
reset and checks the server keeps answering while it waits.

* test(browser): name each thread in the slow-reset stacks

Before Python 3.14 faulthandler prints thread ids only, so the report
now lists which name each id belongs to. CI on 3.10 to 3.13 failed the
unit test that looks for the blocked thread by name.

* test(browser): keep the slow-reset summary on a coarse clock

On Windows the report timer can fire a few milliseconds short of the
threshold, and the summary was then dropped. A reset that was reported
now always gets its summary. The server test uses the plain reset, which
the Windows jobs can seed, and puts the server stderr in its failure
messages.
2026-10-23 03:24:20 -07:00
Vito 5b2c21bdaf test(annotations): capture the details panel after it has loaded (#292)
"Tag opens the dialog without selecting the card" read the panel while it
still said "Loading file details…", then compared it with the same card's
finished details. On a slow WebKit runner the read raced the load.
2026-10-23 03:03:38 -07:00
Vito Sansevero d15fcfa3ce Merge remote-tracking branch 'origin/main' into fix/inspect-video-settle-followups
# Conflicts:
#	TESTING.md
#	web/js/workspace/inspect.mjs
2026-10-23 02:20:11 -07:00
Vito Sansevero ae4cf50f11 fix(inspect): hold a route change until a starting video settles
A route change within the workspace detaches the Inspect page, and WebKit
(GStreamer) deadlocks when a video still starting is detached. Route
changes at loadstart + 0-7 ms hung 4-5 of 120 fresh pages (14 of 120 with
no page code releasing anything, so the detach itself is the trigger).

Inspect now exposes leaveGuard(): a promise while a video on the page is
still starting (current or replaced). The shell renders the next route
once it settles (metadata, error, or the 15 s bound); the latest route
wins. Route changes at loadstart + 0-7 ms now hang 0 of 120.

Not changed, with numbers in TESTING.md D62:
- A replaced video still shows above the new preview until it settles.
  Same-slot stacking changes the video's own box and hung again
  (absolute 5/120, absolute + opacity 0 8/120, one-cell grid 4/120).
- A real page leave cannot wait. Navigating away hung 8/120 and reload
  22/120 even with no page-side release, so it stays a known limitation.
2026-10-22 21:41:46 -07:00
Vito Sansevero 552553edf9 Merge remote-tracking branch 'origin/main' into fix/inspect-webkit-video-replace 2026-10-22 20:38:52 -07:00
Vito Sansevero 9e9adae264 fix(inspect): keep a replaced video in place until its pipeline has started
WebKit (GStreamer) deadlocks the page when a video leaves the page or the
viewport before its pipeline has started: the main thread changes the
pipeline state and waits for the source's streaming thread, which waits on
the main thread in a synchronous bus handler (native stacks of the hung WPE
web process in the pinned image). Removing, hiding or merely pushing the
video below the fold all hung; none of pause(), removing src, load() or the
revoke was the cause on its own.

A video replaced while still starting now stays where it is, inert and
aria-hidden, with the new preview inserted after it, and the session's
revoke of its URL waits. Once it reports metadata or an error (or after
15 s) it is paused, loses its src, is reset with load() and removed, and
only then is its URL revoked. Every released video is reset with load(), so
no decoder is kept per replaced video.

The loadstart replacement spec now runs on WebKit too (15 fresh pages,
replaced at loadstart + 0-4 ms). TESTING.md D62 records the cause.
2026-10-22 20:15:42 -07:00
10 changed files with 630 additions and 9 deletions
+24 -4
View File
@@ -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`:
@@ -1677,8 +1684,20 @@ mapped differences"):
A video replaced while still starting (a source, but neither metadata nor an error yet)
stays where it is, inert and `aria-hidden`, with the new preview inserted after it, and
the session's revoke of its URL waits; once it reports metadata or an error (or after
15 s) it is released as above and only then is its URL revoked. Page leave and dispose
release it at once. Cause, found with native stacks of the hung WPE web process in the
15 s) it is released as above and only then is its URL revoked. For that moment (the
time to metadata, or at most 15 s for a video that never settles) the old video and the
new preview both show, the new one below it: a known, brief overlap. Stacking them in one
slot instead hung again, because it changes the video's own box: the old video
absolutely positioned in its own box hung 5 of 120 pages (8 of 120 with `opacity: 0`),
and a one-cell grid 4 of 120. Only `opacity: 0` on the video, left in the flow, did not
hang (0 of 120), and alone it would leave an empty hole above the new preview. A route
change within the workspace waits the same way: the shell renders the next route once a
video still starting on Inspect settles (`leaveGuard`; the latest route wins). Route
changes at `loadstart` + 0–7 ms hung 4–5 of 120 pages before and 0 of 120 after.
A real page leave cannot wait. With no page code releasing anything, navigating
away hung 8 of 120 pages and reload 22 of 120 (3 and 8 of 120 with the page's own
release), so that WebKit teardown stays a known limitation; dispose still releases at
once. Cause, found with native stacks of the hung WPE web process in the
pinned image: WebKit (GStreamer) deadlocks when a video leaves the page or the viewport
before its pipeline has started. The main thread changes the pipeline state and waits
for the source's streaming thread, which is itself waiting on the main thread in a
@@ -1689,8 +1708,9 @@ mapped differences"):
`loadedmetadata` hung 0 of 180. Specs: `replacing a video that just started loading
never blocks the page`, and `a video replaced while still starting is reset once it
settles`, which now runs on WebKit too (15 fresh pages, replaced at `loadstart` + 0–4
ms). The viewer's own video teardown was checked the same way (`closing the viewer on a
video that just started never blocks the page`, 15 fresh pages on WebKit) and needed no
ms), and `leaving for another route while a video starts waits for it to settle`. The
viewer's own video teardown was checked the same way (`closing the viewer on a video
that just started never blocks the page`, 15 fresh pages on WebKit) and needed no
change.
- **D63** (status line): one `p.small.spaced-16` in `#local-preview`, for states the
concept never shows: "Drop one file at a time.", "Folders cannot be inspected. Choose
+2
View File
@@ -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]
+237
View File
@@ -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)
+48
View File
@@ -577,6 +577,54 @@ test('a video replaced while still starting is reset once it settles', async ({
}
});
test('leaving for another route while a video starts waits for it to settle', async ({ context, browserName }) => {
test.setTimeout(180000);
// A WebKit (GStreamer) video detached before its pipeline had started deadlocked the page (TESTING.md D62); a
// route change detaches the whole page, so the shell renders the next route once the video reports metadata or an
// error. The route changes from the video's own `loadstart`, or a few milliseconds after it.
for (let attempt = 0; attempt < 15; attempt++) {
const page = await context.newPage();
try {
if (attempt === 0) await startCoverage(page, browserName);
await page.addInitScript(() => {
const load = HTMLMediaElement.prototype.load;
HTMLMediaElement.prototype.load = function () {
if (!this.hasAttribute('src') && window.__starting?.node === this) window.__starting.reset = { readyState: this.readyState, failed: this.error !== null, connected: this.isConnected };
return load.call(this);
};
});
await openInspect(page);
await page.evaluate(delay => {
const slot = document.querySelector('#local-preview');
new MutationObserver((records, observer) => {
const video = slot.querySelector('video');
if (!video) return;
observer.disconnect();
const leave = () => {
window.__starting = { node: video, readyState: video.readyState };
location.hash = '#/overview';
};
video.addEventListener('loadstart', () => { if (delay) setTimeout(leave, delay); else leave(); }, { once: true });
}).observe(slot, { childList: true });
}, attempt % 5);
await choose(page, localFixture('core-tags.webm', 'video/webm'));
await expect(main(page).getByRole('heading', { level: 1, name: 'Overview', exact: true })).toBeVisible({ timeout: 8000 });
const { readyState, reset } = await page.evaluate(() => ({ readyState: window.__starting.readyState, reset: window.__starting.reset }));
if (attempt % 5 === 0) expect(readyState).toBe(0);
// The video was reset and left the page only once it had settled.
expect(reset.readyState >= 1 || reset.failed).toBe(true);
expect(reset.connected).toBe(true);
// The page still answers.
await page.locator('aside.sidebar nav').getByRole('link', { name: 'Inspect a file', exact: true }).click();
await chooser(page).setInputFiles(parityPng('f02.png'), { timeout: 8000 });
await expect(preview(page).locator('img.local-file-preview')).toBeVisible({ timeout: 8000 });
if (attempt === 0) await saveCoverage(page, browserName);
} finally {
await page.close();
}
}
});
test('closing the viewer on a video that just started never blocks the page', async ({ context, browserName }) => {
test.setTimeout(180000);
// The viewer's video teardown resets its element; on WebKit a reset of a still-starting pipeline blocked the page.
+3
View File
@@ -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');
+234
View File
@@ -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()
+24 -1
View File
@@ -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`);
+19
View File
@@ -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;
});
+15 -1
View File
@@ -132,9 +132,23 @@ function mountWorkspace() {
refreshCounts(NAV_COUNT_ROUTES);
let viewScope;
let firstRender = true;
// D62: a page whose teardown must wait (Inspect, while a video is still starting) holds the next route until it
// settles; the latest route wins.
let leaveGuard = null, renderToken = 0;
scope.cleanup(() => viewScope?.dispose());
function render(route) {
const token = ++renderToken;
const hold = leaveGuard?.();
if (hold) {
hold.then(() => { if (token === renderToken && !scope.signal.aborted) renderNow(route); });
return;
}
renderNow(route);
}
function renderNow(route) {
leaveGuard = null;
// A shared page dialog never stays open over the next route.
closeWorkspaceDialog();
viewScope?.dispose();
@@ -240,7 +254,7 @@ function mountWorkspace() {
if (route.id === 'inspect') {
// The concept's Inspect a file (app.js renderMetadata): a local file, read only in this browser.
description.textContent = route.description;
mountInspect(main, { parentScope: view, api, sender: createPromptSender({ scope: view }) });
({ leaveGuard } = mountInspect(main, { parentScope: view, api, sender: createPromptSender({ scope: view }) }));
return;
}
if (isHandoff(route)) {
+24 -3
View File
@@ -64,8 +64,10 @@ function releaseMedia(preview) {
/**
* Mounts the page into `main` below the heading the shell rendered. `sender` is the shared prompt sender; `api` is
* only handed to the viewer (the local adapter never calls it). Returns `{dispose}`; the page also ends with
* `parentScope`.
* only handed to the viewer (the local adapter never calls it). Returns `{dispose, leaveGuard}` (`{dispose}` when
* `parentScope` has already ended); the page also ends with `parentScope`. `leaveGuard()` is a promise while a video
* on the page is still starting (D62): the shell renders the next route once it settles, since detaching it then
* deadlocked WebKit.
*/
export function mountInspect(main, { parentScope, api, sender }) {
const scope = createScope();
@@ -110,10 +112,12 @@ export function mountInspect(main, { parentScope, api, sender }) {
entry.waiting.abort(); clearTimeout(entry.timer);
releaseMedia(entry.preview);
if (entry.revoke) URL.revokeObjectURL(url);
entry.done();
}
function retire(preview, url) {
const waiting = new AbortController();
const entry = { preview, waiting, revoke: false, timer: setTimeout(() => finishRetiring(url), STARTING_VIDEO_MS) };
entry.finished = new Promise(resolve => { entry.done = resolve; });
retiring.set(url, entry);
preview.listeners.abort();
preview.node.inert = true; preview.node.setAttribute('aria-hidden', 'true');
@@ -262,5 +266,22 @@ export function mountInspect(main, { parentScope, api, sender }) {
if (open.getAttribute('aria-disabled') === 'true' || !entry || session.state.phase !== 'ready') return;
viewer.open({ items: [entry], selectedKey: entry.key, trigger: open });
});
return { dispose };
/** Settles when no video on the page is still starting; `null` when none is. */
function leaveGuard() {
if (scope.signal.aborted) return null;
const waits = [];
for (const entry of retiring.values()) waits.push(entry.finished);
if (media && isStarting(media.node)) {
const { node } = media;
waits.push(new Promise(resolve => {
const settled = new AbortController();
const done = () => { settled.abort(); clearTimeout(timer); resolve(); };
const timer = setTimeout(done, STARTING_VIDEO_MS);
for (const type of ['loadedmetadata', 'error']) node.addEventListener(type, done, { once: true, signal: settled.signal });
scope.signal.addEventListener('abort', done, { once: true, signal: settled.signal });
}));
}
return waits.length ? Promise.all(waits) : null;
}
return { dispose, leaveGuard };
}