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 593460ef..16a22edb 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 @@ -2922,6 +2937,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/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(); 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}) 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; }