From 599dd828e6a828f77674168f2d5731480f463a55 Mon Sep 17 00:00:00 2001 From: Vito Date: Thu, 29 Oct 2026 17:50:51 +0000 Subject: [PATCH 1/3] fix(inspect): keep a viewer whose video is still starting until it settles (#483) (#489) A new selection closed the shared viewer at once, resetting and removing its video even while that video was still starting. That is the WebKit (GStreamer) deadlock D62 guards the inline preview against, and it hung merge-queue run 40903238387. The viewer now stays open, untouched, until its video reports metadata or an error (or 15 s, or the user closes it), and the URL is revoked after that. An open asked for meanwhile runs once, latest wins, only while its selection is still current. --- TESTING.md | 6 + tests/browser/workspace-inspect.spec.mjs | 141 +++++++++++++++++++++++ web/js/workspace/inspect.mjs | 57 +++++++-- 3 files changed, 196 insertions(+), 8 deletions(-) diff --git a/TESTING.md b/TESTING.md index 7b1cb16d..96683564 100644 --- a/TESTING.md +++ b/TESTING.md @@ -2869,6 +2869,12 @@ mapped differences"): 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. + The shared viewer's own video gets the same guard (#483): a new selection while the + viewer D155 opened is still starting its video leaves the viewer open, untouched, until + that video reports metadata or an error (or 15 s), then closes it; the URL is revoked + after that, and a viewer asked for meanwhile (the new file's D155 open) opens then. The + merge queue hung once without it (run 40903238387: the PNG selection 12 ms after the + inline video showed, with the viewer's new video still starting). 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 diff --git a/tests/browser/workspace-inspect.spec.mjs b/tests/browser/workspace-inspect.spec.mjs index 3d77f112..81795e44 100644 --- a/tests/browser/workspace-inspect.spec.mjs +++ b/tests/browser/workspace-inspect.spec.mjs @@ -704,6 +704,147 @@ test('a video replaced while still starting is reset once it settles', async ({ } }); +test('a new selection while the viewer\'s own video is still starting leaves it until it settles (#483)', async ({ context, browserName }) => { + test.setTimeout(180000); + // D155 opens the viewer once the inline preview has settled; the viewer then starts a video of its own. A new + // selection from that video's own `loadstart` (readyState HAVE_NOTHING), or a few milliseconds after it, must not + // reset it or take it off the page while it starts (WebKit, GStreamer: TESTING.md D62; merge-queue run + // 40903238387). The viewer stays open until it reports metadata or an error, then closes; the URL goes last. + for (let attempt = 0; attempt < 10; 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')) { this.__resets = (this.__resets ?? 0) + 1; this.__resetReadyState ??= this.readyState; } return load.call(this); }; + const revoke = URL.revokeObjectURL; + URL.revokeObjectURL = url => { + const starting = window.__starting; + if (url === starting?.url) starting.revoked = { src: starting.node.hasAttribute('src'), connected: starting.node.isConnected, resets: starting.node.__resets ?? 0 }; + return revoke(url); + }; + }); + await openInspect(page); + await page.evaluate(() => { + const input = document.querySelector('#local-file'); + new MutationObserver((records, observer) => { + const video = document.querySelector('#viewer-dialog video'); + if (!video) return; + observer.disconnect(); + const replace = () => { + window.__starting = { node: video, url: video.getAttribute('src'), readyState: video.readyState }; + input.files = window.__pngFiles; input.dispatchEvent(new Event('change', { bubbles: true })); + window.__starting.replaced = { connected: video.isConnected, src: video.hasAttribute('src'), resets: video.__resets ?? 0 }; + }; + video.addEventListener('loadstart', () => { if (window.__delay) setTimeout(replace, window.__delay); else replace(); }, { once: true }); + }).observe(document.body, { childList: true, subtree: true }); + }); + const png = parityPng('f02.png'); + await page.evaluate(bytes => { + const transfer = new DataTransfer(); + transfer.items.add(new File([new Uint8Array(bytes)], 'f02.png', { type: 'image/png' })); + window.__pngFiles = transfer.files; + }, [...png.buffer]); + await page.evaluate(delay => { window.__delay = delay; }, attempt % 5); + await choose(page, localFixture('core-tags.webm', 'video/webm')); + await expect(preview(page).locator('img.local-file-preview')).toBeVisible({ timeout: 8000 }); + await expect.poll(() => page.evaluate(() => window.__starting?.revoked ?? null)).toEqual({ src: false, connected: false, resets: 1 }); + const { readyState, replaced } = await page.evaluate(() => ({ readyState: window.__starting.readyState, replaced: window.__starting.replaced })); + if (attempt % 5 === 0) expect(readyState).toBe(0); + // Starting when replaced: still on the page with its URL, never reset; settled: released at once. + expect(replaced).toEqual(readyState === 0 ? { connected: true, src: true, resets: 0 } : { connected: false, src: false, resets: 1 }); + expect(await page.evaluate(() => window.__starting.node.__resets)).toBe(1); + // Its one reset came after it had metadata, never while it was starting. + expect(await page.evaluate(() => window.__starting.node.__resetReadyState)).toBeGreaterThanOrEqual(1); + // The new file's viewer opens after the old one closed, and the page still answers. + await expect(viewer(page).getByRole('img', { name: 'f02.png', exact: true })).toBeVisible({ timeout: 8000 }); + await expect(viewer(page).locator('video')).toHaveCount(0); + if (attempt === 0) await saveCoverage(page, browserName); + } finally { + await page.close(); + } + } +}); + +/** #483: holds the viewer's video in HAVE_NOTHING (its `loadedmetadata` never fires) so a hold can be driven by hand. */ +async function stallViewerVideo(page) { + await page.addInitScript(() => { + const describe = Object.getOwnPropertyDescriptor(HTMLMediaElement.prototype, 'readyState'); + Object.defineProperty(HTMLMediaElement.prototype, 'readyState', { configurable: true, get() { + return this.closest?.('#viewer-dialog') && window.__stallViewer ? 0 : describe.get.call(this); + } }); + window.addEventListener('loadedmetadata', event => { + if (window.__stallViewer && event.target.closest?.('#viewer-dialog')) event.stopImmediatePropagation(); + }, true); + }); +} + +test('a held viewer closed by hand, or replaced twice, opens only the latest file\'s viewer at once (#483)', async ({ page }) => { + await stallViewerVideo(page); + await openInspect(page); + await page.evaluate(() => { window.__stallViewer = true; }); + await choose(page, localFixture('core-tags.webm', 'video/webm')); + await expect(viewer(page).locator('video')).toBeAttached(); + // Two selections while the viewer's video is (made to look) still starting: the viewer stays, untouched. + await chooser(page).setInputFiles(parityPng('f02.png', 'first.png')); + await chooser(page).setInputFiles(parityPng('f02.png', 'second.png')); + await expect(preview(page).locator('img.local-file-preview')).toBeVisible(); + await expect(viewer(page).locator('video')).toBeAttached(); + // Open file metadata pressed meanwhile (the page behind the viewer is inert, so by script): the latest request. + await action(page).evaluate(node => node.click()); + // Closing it by hand ends the hold at once: the latest file's viewer opens, once, well before D62's 15 s. + await page.keyboard.press('Escape'); + await expect(viewer(page).getByRole('img', { name: 'second.png', exact: true })).toBeVisible({ timeout: 5000 }); + await expect(viewer(page).getByRole('img', { name: 'first.png', exact: true })).toHaveCount(0); + await expect(viewer(page).locator('video')).toHaveCount(0); + await expect(page.locator('dialog[open]')).toHaveCount(1); +}); + +test('a held viewer revokes its URL only once it is gone, drops a stale open, and ends on page leave (#483)', async ({ page }) => { + await stallViewerVideo(page); + await openInspect(page); + await trackReleases(page); + await page.evaluate(() => { window.__stallViewer = true; }); + const videoUrl = () => page.evaluate(() => document.querySelector('#viewer-dialog video')?.getAttribute('src') ?? null); + const released = url => page.evaluate(url => window.__released.filter(item => item.url === url), url); + await choose(page, localFixture('core-tags.webm', 'video/webm')); + await expect(viewer(page).locator('video')).toBeAttached(); + const first = await videoUrl(); + await chooser(page).setInputFiles(parityPng('f02.png', 'held.png')); + await expect(preview(page).locator('img.local-file-preview')).toBeVisible(); + // The session asked to revoke the video's URL; it waits while the held viewer still plays it. + expect(await released(first)).toEqual([]); + // An Open asked for during the hold, then an AVI (which never opens the viewer by itself): the open for the earlier + // file is stale and is dropped when the hold ends. + await action(page).evaluate(node => node.click()); + const avi = { name: 'clip.avi', mimeType: 'video/x-msvideo', buffer: Buffer.concat([Buffer.from('RIFF'), Buffer.alloc(4), Buffer.from('AVI LIST'), Buffer.alloc(64)]) }; + await chooser(page).setInputFiles(avi); + await expect(page.locator('#workspace-toast')).toHaveText(TOAST); + await page.keyboard.press('Escape'); + await expect(page.locator('dialog[open]')).toHaveCount(0); + await expect.poll(() => released(first)).toEqual([{ url: first, live: 0 }]); + // Page leave while held: the viewer goes and the deferred URL is revoked with nothing holding it. + await choose(page, localFixture('core-tags.webm', 'video/webm')); + await expect(viewer(page).locator('video')).toBeAttached(); + const second = await videoUrl(); + await chooser(page).setInputFiles(parityPng('f02.png', 'leave.png')); + await expect(viewer(page).locator('video')).toBeAttached(); + expect(await released(second)).toEqual([]); + await page.evaluate(() => window.dispatchEvent(new PageTransitionEvent('pagehide', { persisted: true }))); + await expect(page.locator('dialog[open]')).toHaveCount(0); + await expect.poll(() => released(second)).toEqual([{ url: second, live: 0 }]); + // Another route while held: the page's dispose ends the hold and revokes the URL with nothing holding it. + await page.evaluate(() => window.dispatchEvent(new PageTransitionEvent('pageshow', { persisted: true }))); + await choose(page, localFixture('core-tags.webm', 'video/webm')); + await expect(viewer(page).locator('video')).toBeAttached(); + const third = await videoUrl(); + await chooser(page).setInputFiles(parityPng('f02.png', 'route.png')); + await expect(viewer(page).locator('video')).toBeAttached(); + await page.evaluate(() => { window.location.hash = '#/library'; }); + await expect(main(page).getByRole('heading', { level: 1, name: 'Prompt library', exact: true })).toBeVisible(); + await expect.poll(() => released(third)).toEqual([{ url: third, live: 0 }]); +}); + 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 diff --git a/web/js/workspace/inspect.mjs b/web/js/workspace/inspect.mjs index ee67d7ec..2a2ef612 100644 --- a/web/js/workspace/inspect.mjs +++ b/web/js/workspace/inspect.mjs @@ -115,9 +115,39 @@ export function mountInspect(main, { parentScope, api, sender }) { retiring.delete(url); entry.waiting.abort(); clearTimeout(entry.timer); releaseMedia(entry.preview); - if (entry.revoke) URL.revokeObjectURL(url); + if (entry.revoke) revokeObjectURL(url); entry.done(); } + // #483 (D62): the viewer's own video, when a new selection closes the viewer while that video is still starting. + // The viewer stays open until the video reports metadata or an error (or D62's 15 s), then closes; its URL, which + // the session asked to revoke, goes after that. A viewer asked for meanwhile opens then: only the latest request, + // and only if its selection is still current (an automatic open waits for its own inline video again). + let held = null; + function closeViewer() { + const node = document.querySelector('#viewer-dialog video'); + if (!node || !isStarting(node)) { viewer.close(); return; } + const waiting = new AbortController(); + held = { url: node.getAttribute('src'), revoke: false, waiting, pending: null, timer: setTimeout(finishHeld, STARTING_VIDEO_MS) }; + for (const type of ['loadedmetadata', 'error']) node.addEventListener(type, finishHeld, { once: true, signal: waiting.signal }); + } + function endHeld() { + const entry = held; + if (!entry) return null; + held = null; + entry.waiting.abort(); clearTimeout(entry.timer); + return entry; + } + function finishHeld() { + const entry = endHeld(); + if (!entry) return; + viewer.close(); + // Through the session's hook, so an inline video still starting on the same URL keeps it until it settles. + if (entry.revoke) revokeObjectURL(entry.url); + const request = entry.pending; + if (!request || scope.signal.aborted || session.entry !== request.entry || session.state.phase !== 'ready') return; + if (request.auto) autoOpen(request.entry); + else openViewer(request.trigger); + } function retire(preview, url) { const waiting = new AbortController(); const entry = { preview, waiting, revoke: false, timer: setTimeout(() => finishRetiring(url), STARTING_VIDEO_MS) }; @@ -129,6 +159,7 @@ export function mountInspect(main, { parentScope, api, sender }) { } const finishAllRetiring = () => { for (const url of [...retiring.keys()]) finishRetiring(url); }; const revokeObjectURL = url => { + if (held?.url === url) { held.revoke = true; return; } const entry = retiring.get(url); if (entry) entry.revoke = true; else URL.revokeObjectURL(url); @@ -136,7 +167,8 @@ export function mountInspect(main, { parentScope, api, sender }) { const session = createLocalSession({ parentScope: sessionScope, pageTarget: null, revokeObjectURL }); const viewer = createMediaViewer({ api, container: main, parentScope: scope, inspectionController: session.controller, sender, adapter: localFileAdapter, onRestoreFocus: () => { if (open.isConnected) open.focus({ preventScroll: true }); }, - onClose: () => { viewerKey = null; } }); + // A held viewer closed by hand (Escape, Close) ends its hold at once: its video is gone. + onClose: () => { viewerKey = null; if (held) finishHeld(); } }); let viewerKey = null, media = null, mediaUrl = null, statusLine = null, rejectionLine = null, rejectionTimer = 0, announced = null, chosen = null; function statusElement(message) { @@ -209,7 +241,7 @@ export function mountInspect(main, { parentScope, api, sender }) { scope.cleanup(session.subscribe(state => { // D155: a new selection can start while the viewer shows the previous one; it closes first, so no element holds // the old URL when the session revokes it (the new file's viewer opens once it is ready). - if (viewerKey !== null && (state.phase !== 'ready' || session.entry?.key !== viewerKey)) { viewer.close(); viewerKey = null; } + if (viewerKey !== null && (state.phase !== 'ready' || session.entry?.key !== viewerKey)) { closeViewer(); viewerKey = null; } showMedia(state); showStatus(state.message); const entry = session.entry; @@ -220,17 +252,14 @@ export function mountInspect(main, { parentScope, api, sender }) { // while this selection is still the current one and no other dialog is open (the viewer is replaced). D62: // a video opens it once the inline preview has settled, so a replacement while it starts never tears down a // second starting video in the viewer (that deadlocked WebKit). - if (AUTO_OPEN.has(state.message)) whenSettled(media, () => { - if (scope.signal.aborted || session.entry !== entry || session.state.phase !== 'ready' || document.querySelector('dialog[open]:not(#viewer-dialog)')) return; - openViewer(input); - }); + if (AUTO_OPEN.has(state.message)) autoOpen(entry); // An unreadable or failed preview says so in its alert; the toast never claims metadata is available. else if (TOASTABLE.has(state.message)) showWorkspaceToast(INSPECT_COPY.toast); } })); // A replacement or page leave revokes the URL after this subscriber dropped the media; a dispose closes the // viewer (on abort), drops the media, then ends the session. - scope.cleanup(() => viewer.dispose()); + scope.cleanup(() => { const entry = endHeld(); viewer.dispose(); if (entry?.revoke) revokeObjectURL(entry.url); }); scope.cleanup(() => { releaseMedia(media); media = null; mediaUrl = null; }); scope.cleanup(finishAllRetiring); scope.cleanup(() => sessionScope.dispose()); @@ -239,9 +268,11 @@ export function mountInspect(main, { parentScope, api, sender }) { // cleared, so a page restored from the back-forward cache never names a file beside the empty selection. function leave() { clearRejection(); + const entry = endHeld(); viewer.close(); releaseMedia(media); media = null; mediaUrl = null; finishAllRetiring(); + if (entry?.revoke) revokeObjectURL(entry.url); session.clear(); chosen = null; input.value = ''; } @@ -287,10 +318,20 @@ export function mountInspect(main, { parentScope, api, sender }) { for (const type of ['loadedmetadata', 'error']) preview.node.addEventListener(type, done, { once: true, signal: settled.signal }); scope.cleanup(done); } + /** D155: the viewer opens on `entry` once its inline preview has settled, while it is still the current selection. */ + function autoOpen(entry) { + whenSettled(media, () => { + if (scope.signal.aborted || session.entry !== entry || session.state.phase !== 'ready' || document.querySelector('dialog[open]:not(#viewer-dialog)')) return; + // #483: the previous viewer is still closing around its starting video; this one opens once it has. + if (held) { held.pending = { entry, auto: true }; return; } + openViewer(input); + }); + } /** The viewer on the current selection, details showing (D155 amends D97); focus returns to `trigger` on close. */ function openViewer(trigger) { const entry = session.entry; if (!entry || session.state.phase !== 'ready') return; + if (held) { held.pending = { entry, trigger, auto: false }; return; } viewer.open({ items: [entry], selectedKey: entry.key, trigger, details: 'shown' }); viewerKey = entry.key; } From c416c843474f1d376e275d19d0e06fa4c32bf8b3 Mon Sep 17 00:00:00 2001 From: Vito Date: Thu, 29 Oct 2026 18:26:13 +0000 Subject: [PATCH 2/3] test(collections): change sources only after the page's selected-file read is answered (#491) The details panel reads its selected file as soon as the page lists. When the test's source change landed before that read was answered, the page found the file again on its own (409 -> rescope -> relist), so the card under the old numbering the test was about to click was gone. Every test in the spec now waits for that read before changing sources. Closes #484 --- tests/browser/workspace-stale-source.spec.mjs | 23 +++++++++++++------ 1 file changed, 16 insertions(+), 7 deletions(-) diff --git a/tests/browser/workspace-stale-source.spec.mjs b/tests/browser/workspace-stale-source.spec.mjs index 1d6144fe..0e5392cf 100644 --- a/tests/browser/workspace-stale-source.spec.mjs +++ b/tests/browser/workspace-stale-source.spec.mjs @@ -37,6 +37,15 @@ test.afterEach(async ({ page, request, browserName }) => { await expect(await request.post('/__test__/tagging/reset', { data: {} })).toBeOK(); }); +async function openSettled(page, url) { + // The page reads its selected file's details as soon as it lists. A source change before that read is answered + // makes the page find the file again on its own, so the test's old-numbering locators are gone before they are + // used (#484): every test changes sources only after the read was answered. + const inspected = page.waitForResponse(item => new URL(item.url()).pathname.startsWith('/prompt_manager/images/inspect/') && + item.request().method() === 'GET'); + await page.goto(url); + expect((await inspected).status()).toBe(200); +} async function openTag(page, path = FIRST, root = 0) { const observed = answered(page, '/image-annotations/observe'); await tagButton(page, path, root).click(); @@ -53,7 +62,7 @@ async function savedTags(request, path, root) { } test('renumbered sources under an open Tag dialog: it finds the file again, keeps the draft and Generate works', async ({ page, request }) => { - await page.goto(images); + await openSettled(page, images); await expect(card(page, FIRST)).toHaveClass(/\bselected\b/); expect((await openTag(page)).status()).toBe(200); await manual(page).fill('kept_draft'); @@ -91,7 +100,7 @@ test('renumbered sources under an open Tag dialog: it finds the file again, keep }); test('the inspector finds a renumbered file again; checked files from the old numbering are cleared', async ({ page, request }) => { - await page.goto(images); + await openSettled(page, images); await expect(card(page, FIRST)).toHaveClass(/\bselected\b/); await card(page, FIRST).getByRole('checkbox', { name: /^Select / }).check(); await expect(page.locator('.bulkbar')).toBeVisible(); @@ -113,7 +122,7 @@ test('the inspector finds a renumbered file again; checked files from the old nu }); test('a scope that cannot be mapped: Generate and Save are visibly disabled, the reason and Refresh sit beside them', async ({ page }) => { - await page.goto(images); + await openSettled(page, images); await expect(card(page, FIRST)).toBeVisible(); await expect(await page.request.post('/__test__/scope-key/rotate')).toBeOK(); const rescoped = answered(page, '/images/rescope'); @@ -157,7 +166,7 @@ test('a scope that cannot be mapped: Generate and Save are visibly disabled, the }); test('an unmappable inspector read keeps its visible Refresh, and Refresh recovers the panel', async ({ page }) => { - await page.goto(images); + await openSettled(page, images); await expect(card(page, FIRST)).toHaveClass(/\bselected\b/); await expect(await page.request.post('/__test__/scope-key/rotate')).toBeOK(); const rescoped = answered(page, '/images/rescope'); @@ -173,7 +182,7 @@ test('an unmappable inspector read keeps its visible Refresh, and Refresh recove test('a Load more cursor the server cannot verify offers Refresh instead of a dead Retry', async ({ page, request }) => { await expect(await request.post('/__test__/tagging/reset', { data: { extra_images: 60 } })).toBeOK(); - await page.goto(images); + await openSettled(page, images); await expect(cards(page).first()).toBeVisible(); await expect(page.locator('#gallery-continuation')).toContainText('more load as you scroll'); await expect(await request.post('/__test__/scope-key/rotate')).toBeOK(); @@ -191,7 +200,7 @@ test('a Load more cursor the server cannot verify offers Refresh instead of a de }); test('a viewer whose media source was renumbered closes onto the file, kept selected', async ({ page, request }) => { - await page.goto(images); + await openSettled(page, images); await expect(card(page, FIRST)).toHaveClass(/\bselected\b/); await expect(await request.post('/__test__/sources/reverse')).toBeOK(); const rescoped = answered(page, '/images/rescope'); @@ -217,7 +226,7 @@ test('a collection page finds a renumbered member again and stays on its members await expect(added).toBeOK(); const collections = (await (await request.get('/prompt_manager/collections')).json()).collections; const { id } = collections.find(item => item.name === name); - await page.goto(`/prompt_manager/workspace#/collection/${id}`); + await openSettled(page, `/prompt_manager/workspace#/collection/${id}`); await expect(cards(page)).toHaveCount(1); await expect(card(page, FIRST)).toHaveClass(/\bselected\b/); await expect(await request.post('/__test__/sources/reverse')).toBeOK(); From dd247e3b6fb511b4a6eb2e105b6e2502c80dda05 Mon Sep 17 00:00:00 2001 From: Vito Date: Thu, 29 Oct 2026 18:28:47 +0000 Subject: [PATCH 3/3] ci(portability): cut the Windows Python suite time at its causes (#487) (#490) * test: list the slowest tests on request and stop waiting 30 s on a held WAL (#487) PM_TEST_SLOWEST=N makes tests/run_suite.py list the N slowest tests. Three history tests restored while their own read held a snapshot, so each publish sat out the 30 s WAL-truncate wait; they now use a short wait. Temporary diagnostics for the Windows timings ride along in this commit. * test(lora): check Windows folder rules without asking the network (#487) On Windows ntpath.realpath looks up \\server\share and waited about 2.8 s per test for a host that does not exist. The guard tests now use the lexical NT path rules, which is what they already ran on Linux and macOS. * ci(portability): keep Windows test files on the work disk (#487) The Windows runner's TEMP is on C:, where a flush took about 6 ms and a test database's create-to-delete about 111 ms; on D: the same took 0.5 ms and 23 ms. The job now points TEMP/TMP at RUNNER_TEMP and lists the 40 slowest tests. The fake HTTPS handlers get a TLS context that reads no certificate store, and the missing-share tests name localhost instead of an unknown server. The temporary diagnostics are removed. * ci(portability): spell the Windows test TEMP by its short name (#487) The runner's own TEMP was C:\Users\RUNNER~1\..., so tests met 8.3 short names in every temp path. The folder on D: keeps that when the disk has short names, and the step logs which spelling it got. TESTING.md notes that the slowest list is not printed when a job is cancelled. * ci(portability): switch on 8.3 names for the Windows test TEMP (#487) D: made no short names (run 40922502209 logged the long spelling), so the step now switches them on for D: before it creates the folder, and warns when the folder still has no short name. --- .github/workflows/portability.yml | 22 +++++++++++ TESTING.md | 15 ++++++++ tests/run_suite.py | 46 ++++++++++++++++++++++- tests/test_api_diagnostics_report.py | 4 +- tests/test_api_history.py | 20 +++++++++- tests/test_history_read_fence.py | 8 +++- tests/test_lora_manager_layout.py | 26 ++++++++++--- tests/test_lora_utils.py | 14 ++++++- tests/test_run_suite.py | 55 +++++++++++++++++++++++++++- 9 files changed, 195 insertions(+), 15 deletions(-) diff --git a/.github/workflows/portability.yml b/.github/workflows/portability.yml index 75122ab0..43782e03 100644 --- a/.github/workflows/portability.yml +++ b/.github/workflows/portability.yml @@ -51,5 +51,27 @@ jobs: python -m pip install --upgrade pip pip install -r requirements-dev.txt + # The runner's TEMP is on C:, the OS disk, where a flush took about 6 ms + # and a test database's create-to-delete about 111 ms; on the D: work + # disk the same took 0.5 ms and 23 ms (macOS: 19 ms). Tests write their + # databases under TEMP, so it moves to a folder on D: (measured in #487, + # run 40915866444). The runner's TEMP was an 8.3 short name + # (C:\Users\RUNNER~1\...), so the new one is spelled by its short name too + # and paths still have to be resolved. D: makes no short names by default + # (run 40922502209), so they are switched on for it first. + - name: Keep test files on the work disk (Windows) + if: runner.os == 'Windows' + shell: pwsh + run: | + fsutil 8dot3name set D: 0 + $folder = New-Item -ItemType Directory -Force -Path (Join-Path $env:RUNNER_TEMP "PromptManagerTests") + $short = (New-Object -ComObject Scripting.FileSystemObject).GetFolder($folder.FullName).ShortPath + Write-Output "test TEMP: $short (long name $($folder.FullName))" + if ($short -eq $folder.FullName) { Write-Output "::warning::D: gave the test TEMP no 8.3 short name" } + "TEMP=$short" >> $env:GITHUB_ENV + "TMP=$short" >> $env:GITHUB_ENV + - name: Run tests + env: + PM_TEST_SLOWEST: "40" run: python -m tests.run_suite -v diff --git a/TESTING.md b/TESTING.md index 96683564..7f140c1c 100644 --- a/TESTING.md +++ b/TESTING.md @@ -251,6 +251,21 @@ the process exits non-zero. stacks. - When the watchdog fires under coverage, that run's coverage data is lost; the job fails anyway and the dump is what matters. +- `PM_TEST_SLOWEST=N` (off by default) lists the N slowest tests after the + summary, each timed from its `start:` line to the next one like the hang + limit. The Windows and macOS jobs (`portability.yml`) set it to 40, so every + run shows where its time went (#487). The list prints only when the run + ends: a job GitHub cancels or a watchdog exit prints none, so read the + timestamps between `start:` lines instead. +- On the Windows runners `TEMP` sits on the OS disk C:, where a flush took about + 6 ms and a test database's create-to-delete about 111 ms (D: 0.5 ms and 23 ms, + macOS 19 ms). `portability.yml` points `TEMP`/`TMP` at a folder under + `RUNNER_TEMP` on D: before the suite. It switches 8.3 short names on for D: + and spells the folder by its short name, as the runner's own TEMP was + (`C:\Users\RUNNER~1\...`), logs it, and warns when there is none. + A test that waits on a fixed busy timeout, a network name (`\\server\share`: + use `\\localhost\`) or a default TLS context (it reads the + Windows certificate store) costs seconds there; the slowest list shows it. Every job in `test.yml`, `code-quality.yml` and `viewerjs-check.yml` has `timeout-minutes` (`tests/vendor/ci-workflow.test.mjs` checks it). The rule is diff --git a/tests/run_suite.py b/tests/run_suite.py index 9775d274..fc75199f 100644 --- a/tests/run_suite.py +++ b/tests/run_suite.py @@ -28,6 +28,10 @@ stack shows which). A dump after the summary is a hang at interpreter exit A limit is a measurement, not a dial: change it only with new measurements written next to it (TESTING.md "Time limits and hangs"). + +PM_TEST_SLOWEST=N (opt-in, #487) lists the N slowest tests after the summary. +A test's time runs from its ``start:`` line to the next one, so it includes +the class and module fixtures in between, like the hang limit. """ import argparse @@ -36,6 +40,7 @@ import os import shutil import sys import tempfile +import time import unittest from pathlib import Path @@ -63,23 +68,57 @@ def read_limit(name, default): return int(text) -def make_result_class(stream, per_test_limit, shutdown_limit): +class TestClock: + """Seconds from each test's start to the next start (or the run's end).""" + + def __init__(self, clock=time.perf_counter): + self._clock = clock + self._current = None + self._started = 0.0 + self.durations = [] + + def start(self, test_id): + self.stop() + self._current = test_id + self._started = self._clock() + + def stop(self): + if self._current is not None: + self.durations.append((self._clock() - self._started, self._current)) + self._current = None + + def report(self, count): + """Return the lines that list the ``count`` slowest tests.""" + slowest = sorted(self.durations, key=lambda item: item[0], reverse=True) + lines = [f"slowest {min(count, len(slowest))} of {len(slowest)} tests:"] + lines += [f"{seconds:8.2f}s {test_id}" for seconds, test_id in slowest[:count]] + return lines + + +def make_result_class(stream, per_test_limit, shutdown_limit, slowest=0): """Build a TextTestResult that names each test and re-arms the watchdog.""" def arm(seconds): faulthandler.dump_traceback_later(seconds, exit=True, file=stream) + clock = TestClock() + class WatchdogResult(unittest.TextTestResult): def startTest(self, test): # At default verbosity the progress dots share a line; start ours. prefix = "\n" if self.dots else "" stream.write(f"{prefix}start: {test.id()}\n") stream.flush() + clock.start(test.id()) super().startTest(test) arm(per_test_limit) def stopTestRun(self): + clock.stop() super().stopTestRun() + if slowest: + stream.write("\n".join(["", *clock.report(slowest), ""])) + stream.flush() arm(shutdown_limit) return WatchdogResult @@ -138,6 +177,7 @@ def main(argv=None): try: per_test_limit = read_limit("PM_TEST_HANG_LIMIT", DEFAULT_PER_TEST_LIMIT) shutdown_limit = read_limit("PM_TEST_SHUTDOWN_LIMIT", DEFAULT_SHUTDOWN_LIMIT) + slowest = read_limit("PM_TEST_SLOWEST", 0) except LimitError as error: stream.write(f"{error}\n") return USAGE_EXIT @@ -152,7 +192,9 @@ def main(argv=None): verbosity=args.verbosity, # As unittest.main does: show warnings unless -W/PYTHONWARNINGS set them. warnings=None if sys.warnoptions else "default", - resultclass=make_result_class(stream, per_test_limit, shutdown_limit), + resultclass=make_result_class( + stream, per_test_limit, shutdown_limit, slowest + ), ) result = runner.run(suite) finally: diff --git a/tests/test_api_diagnostics_report.py b/tests/test_api_diagnostics_report.py index 113d6c42..8b6ef318 100644 --- a/tests/test_api_diagnostics_report.py +++ b/tests/test_api_diagnostics_report.py @@ -45,7 +45,9 @@ SEEDED_PATHS = ( "/srv/someone/renders", "C:\\Users\\someone\\Documents\\renders", "D:/Users/someone/prompts.db", - "\\\\nas\\share\\someone\\renders", + # A share on this machine: on Windows the report resolves every source, + # and an unknown server name made that wait about 2.9 s (#487). + "\\\\localhost\\pm-no-such-share\\someone\\renders", ) _WINDOWS_ABSOLUTE = re.compile(r"^[A-Za-z]:[\\/]") TOP_KEYS = { diff --git a/tests/test_api_history.py b/tests/test_api_history.py index f42e4b60..9e1d8ceb 100644 --- a/tests/test_api_history.py +++ b/tests/test_api_history.py @@ -25,6 +25,7 @@ try: except ImportError: from tests.test_api_images import ImageAPITestCase +from database import restore_stage from database.operations import PromptDatabase from py.api.library import _encode, _scope from tests.test_execution_context_database import bundle, snapshot @@ -43,6 +44,21 @@ OTHER_SESSION = "aaaaaaaa-3333-4333-8333-333333333333" MISSING_RUN = "bbbbbbbb-4444-4444-8444-444444444444" +@contextmanager +def no_wal_truncate_wait(): + """Restore with the restore notification held back, as these tests need. + + The read under test keeps its snapshot open across the restore, so the + publish's WAL truncate can never succeed; without the short wait it would + sit out the full CHECKPOINT_BUSY_MS (30 s) each time (#487). + """ + with ( + patch("database.execution_history.notify_history_restore"), + patch.object(restore_stage, "CHECKPOINT_BUSY_MS", 50), + ): + yield + + class HistoryAPITests(ImageAPITestCase): async def tearDownAsync(self): if hasattr(self.api, "close_history_reads"): @@ -346,7 +362,7 @@ class HistoryAPITests(ImageAPITestCase): def during_snapshot(*args, **kwargs): result = original(*args, **kwargs) - with patch("database.execution_history.notify_history_restore"): + with no_wal_truncate_wait(): writer.model.restore_from_file(source) return result @@ -890,7 +906,7 @@ class HistoryAPITests(ImageAPITestCase): def during_snapshot(*args, **kwargs): result = original(*args, **kwargs) - with patch("database.execution_history.notify_history_restore"): + with no_wal_truncate_wait(): writer.model.restore_from_file(source) return result diff --git a/tests/test_history_read_fence.py b/tests/test_history_read_fence.py index 9e60dd5c..9b6f354f 100644 --- a/tests/test_history_read_fence.py +++ b/tests/test_history_read_fence.py @@ -7,6 +7,7 @@ from contextlib import closing from pathlib import Path from unittest.mock import patch +from database import restore_stage from database.execution_history import HistoryEpochChanged, notify_history_restore from tests import test_execution_history_database as history_tests @@ -41,7 +42,12 @@ class HistoryReadFenceTests(unittest.TestCase): generation = fence.begin() with reader.recorded_history_snapshot() as epoch: original = reader.get_history_run(start.run_id) - with patch("database.execution_history.notify_history_restore"): + # The open snapshot keeps the WAL from being truncated; do not + # sit out the full 30 s checkpoint wait for it (#487). + with ( + patch("database.execution_history.notify_history_restore"), + patch.object(restore_stage, "CHECKPOINT_BUSY_MS", 50), + ): writer.model.restore_from_file(source) self.assertEqual(reader.get_execution_epoch(), epoch) self.assertEqual(original["run"]["storage_epoch"], epoch) diff --git a/tests/test_lora_manager_layout.py b/tests/test_lora_manager_layout.py index 16c94cd2..8af50902 100644 --- a/tests/test_lora_manager_layout.py +++ b/tests/test_lora_manager_layout.py @@ -14,6 +14,7 @@ import sys import tempfile import unittest from pathlib import Path +from types import SimpleNamespace from unittest.mock import patch sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) @@ -753,6 +754,17 @@ class LocalMediaTests(LayoutTestCase): self.assertEqual(layout_module.VIDEO_SUFFIXES, frozenset(VIDEO_EXTENSIONS)) +# Windows path rules without the filesystem. On Windows ntpath.realpath asks +# the network for \\server\share and waits seconds for a host that does not +# exist (#487); elsewhere ntpath.realpath already is ntpath.abspath. +LEXICAL_NT = SimpleNamespace( + normcase=ntpath.normcase, + realpath=ntpath.abspath, + dirname=ntpath.dirname, + sep=ntpath.sep, +) + + class FolderGuardTests(unittest.TestCase): """Portable path-flavor controls (TESTING.md Windows portability preflight).""" @@ -762,7 +774,7 @@ class FolderGuardTests(unittest.TestCase): def guard_nt(self, path, home="C:\\Users\\Vito"): return layout_module._guard_folder( - path, home, pathmod=ntpath, isdir=lambda _p: True + path, home, pathmod=LEXICAL_NT, isdir=lambda _p: True ) def test_filesystem_roots_and_home_are_rejected(self): @@ -832,8 +844,12 @@ class FolderGuardTests(unittest.TestCase): def test_missing_folders_add_nothing(self): self.assertIsNone(layout_module._guard_folder(str(self.tmp / "x"), "/home")) + # A missing share on this machine: an unknown server name made + # Windows wait about 2.8 s for the network (#487). self.assertIsNone( - layout_module._guard_folder("\\\\server\\share\\loras", str(self.tmp)) + layout_module._guard_folder( + "\\\\localhost\\pm-no-such-share\\loras", str(self.tmp) + ) ) self.assertEqual( layout_module._guard_folder(str(self.tmp), "/nonexistent-home"), @@ -843,17 +859,17 @@ class FolderGuardTests(unittest.TestCase): def test_windows_model_path_matches_a_lower_case_root(self): self.assertTrue( layout_module._inside( - "C:/Models/Loras/A.safetensors", ("c:\\models\\loras",), ntpath + "C:/Models/Loras/A.safetensors", ("c:\\models\\loras",), LEXICAL_NT ) ) self.assertFalse( layout_module._inside( - "C:/Models/LorasX/A.safetensors", ("c:\\models\\loras",), ntpath + "C:/Models/LorasX/A.safetensors", ("c:\\models\\loras",), LEXICAL_NT ) ) self.assertFalse( layout_module._inside( - "\\\\other\\share\\A.safetensors", ("c:\\models\\loras",), ntpath + "\\\\other\\share\\A.safetensors", ("c:\\models\\loras",), LEXICAL_NT ) ) diff --git a/tests/test_lora_utils.py b/tests/test_lora_utils.py index d271c771..18476cfd 100644 --- a/tests/test_lora_utils.py +++ b/tests/test_lora_utils.py @@ -9,6 +9,7 @@ import email import json import os import shutil +import ssl import sys import tempfile import threading @@ -669,6 +670,15 @@ class TestStaleDownloadSweep(unittest.TestCase): self.assertTrue(old.exists()) +def _unused_tls_context(): + """A TLS context for the fake handlers, which never open a connection. + + HTTPSHandler() builds a default context, and on Windows that reads the + system certificate store: about 0.14 s per handler (#487). + """ + return ssl.SSLContext(ssl.PROTOCOL_TLS_CLIENT) + + class _FakeHTTPSHandler(urllib.request.HTTPSHandler): """Serves canned responses through a real urllib opener, recording requests. @@ -677,7 +687,7 @@ class _FakeHTTPSHandler(urllib.request.HTTPSHandler): """ def __init__(self, redirect_to): - super().__init__() + super().__init__(context=_unused_tls_context()) self.redirect_to = redirect_to self.requests = [] @@ -745,7 +755,7 @@ class _ChainHTTPSHandler(urllib.request.HTTPSHandler): urllib opener, recording every request; an unknown URL answers 404.""" def __init__(self, routes): - super().__init__() + super().__init__(context=_unused_tls_context()) self.routes = routes self.requests = [] diff --git a/tests/test_run_suite.py b/tests/test_run_suite.py index b35fe567..0ea3f859 100644 --- a/tests/test_run_suite.py +++ b/tests/test_run_suite.py @@ -18,11 +18,13 @@ from pathlib import Path REPO_ROOT = Path(__file__).resolve().parent.parent SUBPROCESS_TIMEOUT = 60 WATCHDOG_ENV = ("PM_TEST_HANG_LIMIT", "PM_TEST_SHUTDOWN_LIMIT") +# Integer settings the runner reads; a bad value is a usage error. +RUNNER_ENV = (*WATCHDOG_ENV, "PM_TEST_SLOWEST") def run_suite(folder, extra_env=None, *args, verbosity=("-v",)): """Run the runner on ``folder`` and return the completed process.""" - env = {k: v for k, v in os.environ.items() if k not in WATCHDOG_ENV} + env = {k: v for k, v in os.environ.items() if k not in RUNNER_ENV} # Windows writes a piped stderr in the ANSI codepage; ask for the UTF-8 # this helper decodes, so non-ASCII values and paths survive. env["PYTHONIOENCODING"] = "utf-8" @@ -269,8 +271,57 @@ class RunSuiteTests(unittest.TestCase): self.assertIn("ok", result.stderr, detail) self.assertIn("Timeout (", result.stderr, detail) + def test_slowest_tests_are_listed_when_asked(self): + self.write( + "test_probe_slowest.py", + """ + import time + import unittest + + class Probe(unittest.TestCase): + def test_fast(self): + pass + + def test_slow(self): + time.sleep(0.3) + + def test_slower(self): + time.sleep(0.6) + """, + ) + result = run_suite(self.folder, {"PM_TEST_SLOWEST": "2"}) + self.assertEqual(result.returncode, 0, result.stderr) + report = result.stderr.split("slowest 2 of 3 tests:\n", 1) + self.assertEqual(len(report), 2, result.stderr) + lines = [line.split() for line in report[1].strip().splitlines()[:2]] + self.assertEqual( + [line[1] for line in lines], + [ + "test_probe_slowest.Probe.test_slower", + "test_probe_slowest.Probe.test_slow", + ], + result.stderr, + ) + self.assertGreaterEqual(float(lines[0][0].rstrip("s")), 0.6) + self.assertNotIn("test_fast", report[1]) + + def test_slowest_tests_are_not_listed_by_default(self): + self.write( + "test_probe_quiet.py", + """ + import unittest + + class Probe(unittest.TestCase): + def test_ok(self): + pass + """, + ) + result = run_suite(self.folder) + self.assertEqual(result.returncode, 0, result.stderr) + self.assertNotIn("slowest", result.stderr) + def test_invalid_limit_is_a_usage_error(self): - for name in WATCHDOG_ENV: + for name in RUNNER_ENV: for value in ("abc", "0", "-3", "1.5", "\u00b2"): with self.subTest(name=name, value=value): result = run_suite(self.folder, {name: value})