diff --git a/moli-cdp-smoke/moli_cdp_smoke/groups/browser_semantics.py b/moli-cdp-smoke/moli_cdp_smoke/groups/browser_semantics.py index 4a3f2fb0a1..54c6195f8f 100644 --- a/moli-cdp-smoke/moli_cdp_smoke/groups/browser_semantics.py +++ b/moli-cdp-smoke/moli_cdp_smoke/groups/browser_semantics.py @@ -9,6 +9,7 @@ from urllib.parse import urlsplit from ..assertions import SmokeError, assert_equal, record_contract, wait_until from ..helpers import attach_cdp_event_collector +from ..progress import await_with_progress from ..raw_cdp import RawCdpClient, RawCdpError, connect_raw_cdp from ..state import SmokeState @@ -33,7 +34,10 @@ async def run_target_semantics_group( ) -> None: for item in _raw_semantic_contracts(): try: - observed = await item.scenario(endpoint, fixture) + observed = await await_with_progress( + f"scenario/raw/target-semantics/{item.name}", + item.scenario(endpoint, fixture), + ) except Exception as error: results.append( { @@ -150,7 +154,10 @@ def _raw_semantic_contracts() -> tuple[RawSemanticContract, ...]: async def run_browser_semantics_group(state: SmokeState) -> None: for name, contract, source, commands, scenario in _semantic_scenarios(): try: - observed = await scenario(state) + observed = await await_with_progress( + f"scenario/page/browser-semantics/{name}", + scenario(state), + ) except Exception as error: state.results.append( { @@ -368,13 +375,25 @@ def _semantic_scenarios() -> tuple[ @asynccontextmanager async def _isolated_page(state: SmokeState) -> AsyncIterator[tuple[Any, Any, Any]]: - context = await state.browser.new_context() + context = await await_with_progress( + "playwright/browser-semantics/isolated-context-new", + state.browser.new_context(), + ) try: - page = await context.new_page() - cdp = await context.new_cdp_session(page) + page = await await_with_progress( + "playwright/browser-semantics/isolated-page-new", + context.new_page(), + ) + cdp = await await_with_progress( + "playwright/browser-semantics/isolated-cdp-session-new", + context.new_cdp_session(page), + ) yield context, page, cdp finally: - await context.close() + await await_with_progress( + "playwright/browser-semantics/isolated-context-close", + context.close(), + ) async def _multi_session_child_frame_realm_routing( @@ -1696,9 +1715,13 @@ async def _autofill_trigger_card_semantics(state: SmokeState) -> dict[str, Any]: async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str, Any]: async with _isolated_page(state) as (_context, page, cdp): - await cdp.send("DOM.enable") - await page.set_content( - """ + progress_prefix = "command/page/browser-semantics/dom-mutation-edit" + + async def step(label: str, awaitable: Awaitable[Any]) -> Any: + return await await_with_progress(f"{progress_prefix}/{label}", awaitable) + + await step("DOM.enable", cdp.send("DOM.enable")) + html = """
old

attribute target

old text

@@ -1707,12 +1730,23 @@ async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str,
outer target
""" + await step( + "Page.setContent", + page.set_content(html), ) - root_id = (await cdp.send("DOM.getDocument", {"depth": 0}))["root"]["nodeId"] + root_id = ( + await step( + "DOM.getDocument-shallow", + cdp.send("DOM.getDocument", {"depth": 0}), + ) + )["root"]["nodeId"] unrequested_id = ( - await cdp.send( - "DOM.querySelector", - {"nodeId": root_id, "selector": "#unrequested"}, + await step( + "DOM.querySelector-unrequested", + cdp.send( + "DOM.querySelector", + {"nodeId": root_id, "selector": "#unrequested"}, + ), ) )["nodeId"] @@ -1734,12 +1768,13 @@ async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str, ) async def send_and_require_events( + label: str, method: str, params: dict[str, Any], expected_methods: list[str], ) -> tuple[dict[str, Any], list[dict[str, Any]]]: start = len(wire_order) - result = await cdp.send(method, params) + result = await step(label, cdp.send(method, params)) wire_order.append({"kind": "response", "method": method}) command_order = wire_order[start:] observed_methods = [ @@ -1753,6 +1788,7 @@ async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str, return result, command_order _, shallow_runtime_order = await send_and_require_events( + "Runtime.evaluate-shallow-mutation", "Runtime.evaluate", { "expression": "document.querySelector('#unrequested').append(document.createElement('i'))" @@ -1760,7 +1796,12 @@ async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str, ["DOM.childNodeCountUpdated"], ) - document = (await cdp.send("DOM.getDocument", {"depth": -1}))["root"] + document = ( + await step( + "DOM.getDocument-deep", + cdp.send("DOM.getDocument", {"depth": -1}), + ) + )["root"] def node_for_selector(selector: str) -> int: node = _find_dom_node_by_attribute(document, "id", selector.removeprefix("#")) @@ -1771,6 +1812,7 @@ async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str, attrs_id = node_for_selector("#attrs") _, attributes_order = await send_and_require_events( + "DOM.setAttributesAsText", "DOM.setAttributesAsText", { "nodeId": attrs_id, @@ -1787,18 +1829,23 @@ async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str, text_node_id = value_children[0].get("nodeId") _require(isinstance(text_node_id, int) and text_node_id > 0, f"invalid text node: {value_children[0]}") _, value_order = await send_and_require_events( + "DOM.setNodeValue-change", "DOM.setNodeValue", {"nodeId": text_node_id, "value": "updated text"}, ["DOM.characterDataModified"], ) - same_value_result = await cdp.send( - "DOM.setNodeValue", - {"nodeId": text_node_id, "value": "updated text"}, + same_value_result = await step( + "DOM.setNodeValue-same", + cdp.send( + "DOM.setNodeValue", + {"nodeId": text_node_id, "value": "updated text"}, + ), ) assert_equal(same_value_result, {}, "DOM.setNodeValue same-value result") rename_id = node_for_selector("#rename") rename_result, rename_order = await send_and_require_events( + "DOM.setNodeName-element", "DOM.setNodeName", {"nodeId": rename_id, "name": "article"}, ["DOM.childNodeRemoved", "DOM.childNodeInserted"], @@ -1817,6 +1864,7 @@ async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str, move_id = node_for_selector("#move") destination_id = node_for_selector("#destination") move_result, move_order = await send_and_require_events( + "DOM.moveTo", "DOM.moveTo", {"nodeId": move_id, "targetNodeId": destination_id}, ["DOM.childNodeRemoved", "DOM.childNodeInserted"], @@ -1834,6 +1882,7 @@ async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str, outer_id = node_for_selector("#outer") _, outer_order = await send_and_require_events( + "DOM.setOuterHTML", "DOM.setOuterHTML", { "nodeId": outer_id, @@ -1842,21 +1891,33 @@ async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str, ["DOM.childNodeRemoved", "DOM.childNodeInserted"], ) assert_equal( - await page.evaluate("document.querySelector('#outer-replacement')?.localName"), + await step( + "Runtime.evaluate-outer-replacement", + page.evaluate("document.querySelector('#outer-replacement')?.localName"), + ), "aside", "DOM.setOuterHTML replacement", ) pi_object = ( - await cdp.send( - "Runtime.evaluate", - { - "expression": "(() => { const pi = document.createProcessingInstruction('old-target', 'data'); document.insertBefore(pi, document.firstChild); return pi; })()" - }, + await step( + "Runtime.evaluate-create-processing-instruction", + cdp.send( + "Runtime.evaluate", + { + "expression": "(() => { const pi = document.createProcessingInstruction('old-target', 'data'); document.insertBefore(pi, document.firstChild); return pi; })()" + }, + ), ) )["result"]["objectId"] - pi_node_id = (await cdp.send("DOM.requestNode", {"objectId": pi_object}))["nodeId"] + pi_node_id = ( + await step( + "DOM.requestNode-processing-instruction", + cdp.send("DOM.requestNode", {"objectId": pi_object}), + ) + )["nodeId"] pi_rename_result, pi_rename_order = await send_and_require_events( + "DOM.setNodeName-processing-instruction", "DOM.setNodeName", {"nodeId": pi_node_id, "name": "xml"}, ["DOM.childNodeRemoved", "DOM.childNodeInserted"], @@ -1872,7 +1933,10 @@ async def _dom_mutation_events_and_edit_commands(state: SmokeState) -> dict[str, "DOM.setNodeName processing-instruction node id", ) assert_equal( - await page.evaluate("document.firstChild.target"), + await step( + "Runtime.evaluate-processing-instruction-target", + page.evaluate("document.firstChild.target"), + ), "xml", "DOM.setNodeName processing-instruction xml target", ) diff --git a/moli-cdp-smoke/moli_cdp_smoke/progress.py b/moli-cdp-smoke/moli_cdp_smoke/progress.py new file mode 100644 index 0000000000..aa900cd24b --- /dev/null +++ b/moli-cdp-smoke/moli_cdp_smoke/progress.py @@ -0,0 +1,35 @@ +from __future__ import annotations + +import asyncio +import sys +from typing import Awaitable, TypeVar + + +ProgressResult = TypeVar("ProgressResult") + + +async def await_with_progress( + label: str, + awaitable: Awaitable[ProgressResult], +) -> ProgressResult: + loop = asyncio.get_running_loop() + started_at = loop.time() + print(f"[moli-cdp-smoke] START {label}", file=sys.stderr, flush=True) + try: + result = await awaitable + except BaseException as error: + elapsed = loop.time() - started_at + print( + f"[moli-cdp-smoke] FAIL {label} elapsed={elapsed:.3f}s " + f"error={type(error).__name__}", + file=sys.stderr, + flush=True, + ) + raise + elapsed = loop.time() - started_at + print( + f"[moli-cdp-smoke] DONE {label} elapsed={elapsed:.3f}s", + file=sys.stderr, + flush=True, + ) + return result diff --git a/moli-cdp-smoke/moli_cdp_smoke/runner.py b/moli-cdp-smoke/moli_cdp_smoke/runner.py index 22e6b48be9..e4aea6ec20 100644 --- a/moli-cdp-smoke/moli_cdp_smoke/runner.py +++ b/moli-cdp-smoke/moli_cdp_smoke/runner.py @@ -56,6 +56,7 @@ from .groups.url_policy import run_url_policy_group from .groups.workers import run_workers_group from .groups.xhr_sync_semantics import run_xhr_sync_semantics_group from .helpers import attach_cdp_event_collector +from .progress import await_with_progress from .serve import MoliServe, start_moli_serve, stop_moli_serve, wait_for_cdp_server from .state import SmokeState @@ -411,16 +412,29 @@ async def run_smoke( if results is None: results = [] temp_dir = Path(tempfile.mkdtemp(prefix="moli-pw-smoke-")) - async with async_playwright() as playwright: - browser = await playwright.chromium.connect_over_cdp(endpoint, timeout=10_000) + playwright = await await_with_progress("playwright/start", async_playwright().start()) + try: + browser = await await_with_progress( + "playwright/connect-over-cdp", + playwright.chromium.connect_over_cdp(endpoint, timeout=10_000), + ) try: record(results, "connect_over_cdp", {"browserContexts": len(browser.contexts)}) - context = await browser.new_context(accept_downloads=True) + context = await await_with_progress( + "playwright/browser-new-context", + browser.new_context(accept_downloads=True), + ) record(results, "browser_new_context") - page = await context.new_page() - cdp = await context.new_cdp_session(page) + page = await await_with_progress( + "playwright/context-new-page", + context.new_page(), + ) + cdp = await await_with_progress( + "playwright/context-new-cdp-session", + context.new_cdp_session(page), + ) websocket_events = attach_cdp_event_collector( cdp, [ @@ -442,7 +456,10 @@ async def run_smoke( "Network.loadingFailed", ], ) - await cdp.send("Network.enable") + await await_with_progress( + "playwright/network-enable", + cdp.send("Network.enable"), + ) state = SmokeState( endpoint=endpoint, @@ -459,15 +476,23 @@ async def run_smoke( ) for group in selection.page_groups: - await group.runner(state) # type: ignore[misc] + await await_with_progress( + f"group/{group.phase}/{group.name}", + group.runner(state), # type: ignore[misc] + ) - await context.close() + await await_with_progress("playwright/context-close", context.close()) for group in selection.browser_groups: - await group.runner(browser, fixture_server.url, results) # type: ignore[misc] + await await_with_progress( + f"group/{group.phase}/{group.name}", + group.runner(browser, fixture_server.url, results), # type: ignore[misc] + ) return results finally: - await browser.close() + await await_with_progress("playwright/browser-close", browser.close()) shutil.rmtree(temp_dir, ignore_errors=True) + finally: + await await_with_progress("playwright/stop", playwright.stop()) def parse_args(argv: list[str] | None = None) -> argparse.Namespace: @@ -514,10 +539,16 @@ async def async_main(argv: list[str] | None = None) -> int: endpoint = f"http://127.0.0.1:{port}" await wait_for_cdp_server(endpoint, serve) for group in selection.raw_groups: - await group.runner(endpoint, fixture.url, results) # type: ignore[misc] + await await_with_progress( + f"group/{group.phase}/{group.name}", + group.runner(endpoint, fixture.url, results), # type: ignore[misc] + ) await run_smoke(endpoint, fixture, selection, results) for group in selection.external_groups: - await group.runner(endpoint, fixture.url, results) # type: ignore[misc] + await await_with_progress( + f"group/{group.phase}/{group.name}", + group.runner(endpoint, fixture.url, results), # type: ignore[misc] + ) ok = not any(result.get("ok") is False for result in results) print( json.dumps( diff --git a/moli-cdp-smoke/tests/test_runner_progress.py b/moli-cdp-smoke/tests/test_runner_progress.py new file mode 100644 index 0000000000..5867a5a4a7 --- /dev/null +++ b/moli-cdp-smoke/tests/test_runner_progress.py @@ -0,0 +1,66 @@ +from __future__ import annotations + +import asyncio +import io +import unittest +from contextlib import redirect_stderr + +from moli_cdp_smoke.progress import await_with_progress + + +class RunnerProgressTests(unittest.IsolatedAsyncioTestCase): + async def test_success_reports_start_and_done(self) -> None: + stderr = io.StringIO() + + with redirect_stderr(stderr): + result = await await_with_progress( + "test/success", + asyncio.sleep(0, result="done"), + ) + + self.assertEqual(result, "done") + lines = stderr.getvalue().splitlines() + self.assertEqual(lines[0], "[moli-cdp-smoke] START test/success") + self.assertRegex( + lines[1], + r"^\[moli-cdp-smoke\] DONE test/success elapsed=\d+\.\d{3}s$", + ) + + async def test_failure_reports_error_type_before_reraising(self) -> None: + async def fail() -> None: + raise RuntimeError("expected failure") + + stderr = io.StringIO() + with redirect_stderr(stderr), self.assertRaisesRegex( + RuntimeError, + "expected failure", + ): + await await_with_progress("test/failure", fail()) + + lines = stderr.getvalue().splitlines() + self.assertEqual(lines[0], "[moli-cdp-smoke] START test/failure") + self.assertRegex( + lines[1], + r"^\[moli-cdp-smoke\] FAIL test/failure " + r"elapsed=\d+\.\d{3}s error=RuntimeError$", + ) + + async def test_cancellation_is_reported_before_propagating(self) -> None: + async def cancel() -> None: + raise asyncio.CancelledError + + stderr = io.StringIO() + with redirect_stderr(stderr), self.assertRaises(asyncio.CancelledError): + await await_with_progress("test/cancel", cancel()) + + lines = stderr.getvalue().splitlines() + self.assertEqual(lines[0], "[moli-cdp-smoke] START test/cancel") + self.assertRegex( + lines[1], + r"^\[moli-cdp-smoke\] FAIL test/cancel " + r"elapsed=\d+\.\d{3}s error=CancelledError$", + ) + + +if __name__ == "__main__": + unittest.main()