Improve self.wait_for_console() (#1363)

- Previously, if the message appeared on the console immediately before the call to self.wait_for_console(), the call would hang forever until the timeout. Now, it returns immediately.

- `wait_for_pyscript` now logs the time actually taken for waiting

- `wait_for_pyscript` takes a `timeout` argument so that we can tweak it on a test-by-test basis

pyscriptjs/tests/integration/support.py

@@ -221,25 +221,36 @@ class PyScriptTest:
 
     def wait_for_console(self, text, *, timeout=None, check_js_errors=True):
         """
-        Wait until the given message appear in the console.
+        Wait until the given message appear in the console. If the message was
+        already printed in the console, return immediately.
 
         Note: it must be the *exact* string as printed by e.g. console.log.
-        If you need more control on the predicate (e.g. if you want to match a
-        substring), use self.page.expect_console_message directly.
 
         timeout is expressed in milliseconds. If it's None, it will use
-        playwright's own default value, which is 30 seconds).
+        the same default as playwright, which is 30 seconds.
 
         If check_js_errors is True (the default), it also checks that no JS
         errors were raised during the waiting.
+
+        Return the elapsed time in ms.
         """
-
-        def pred(msg):
-            return msg.text == text
-
+        if timeout is None:
+            timeout = 30 * 1000
+        # NOTE: we cannot use playwright's own page.expect_console_message(),
+        # because if you call it AFTER the text has already been emitted, it
+        # waits forever. Instead, we have to use our own custom logic.
         try:
-            with self.page.expect_console_message(pred, timeout=timeout):
-                pass
+            t0 = time.time()
+            while True:
+                elapsed_ms = (time.time() - t0) * 1000
+                if elapsed_ms > timeout:
+                    raise TimeoutError(f"{elapsed_ms:.2f} ms")
+                #
+                if text in self.console.all.lines:
+                    # found it!
+                    return elapsed_ms
+                #
+                self.page.wait_for_timeout(50)
         finally:
             # raise JsError if there were any javascript exception. Note that
             # this might happen also in case of a TimeoutError. In that case,
@@ -260,16 +271,21 @@ class PyScriptTest:
         errors were raised during the waiting.
         """
         # this is printed by interpreter.ts:Interpreter.initialize
-        self.wait_for_console(
+        elapsed_ms = self.wait_for_console(
             "[pyscript/main] PyScript page fully initialized",
             timeout=timeout,
             check_js_errors=check_js_errors,
         )
+        self.logger.log(
+            "wait_for_pyscript", f"Waited for {elapsed_ms/1000:.2f} s", color="yellow"
+        )
         # We still don't know why this wait is necessary, but without it
         # events aren't being triggered in the tests.
         self.page.wait_for_timeout(100)
 
-    def pyscript_run(self, snippet, *, extra_head="", wait_for_pyscript=True):
+    def pyscript_run(
+        self, snippet, *, extra_head="", wait_for_pyscript=True, timeout=None
+    ):
         """
         Main entry point for pyscript tests.
 
@@ -295,11 +311,13 @@ class PyScriptTest:
           </body>
         </html>
         """
+        if not wait_for_pyscript and timeout is not None:
+            raise ValueError("Cannot set a timeout if wait_for_pyscript=False")
         filename = f"{self.testname}.html"
         self.writefile(filename, doc)
         self.goto(filename)
         if wait_for_pyscript:
-            self.wait_for_pyscript()
+            self.wait_for_pyscript(timeout=timeout)
 
     def iter_locator(self, loc):
         """
@@ -594,7 +612,7 @@ class Logger:
     def log(self, category, text, *, color=None):
         delta = time.time() - self.start_time
         text = self.colorize_prefix(text, color="teal")
-        line = f"[{delta:6.2f} {category:16}] {text}"
+        line = f"[{delta:6.2f} {category:17}] {text}"
         if color:
             line = Color.set(color, line)
         print(line)

pyscriptjs/tests/integration/test_00_support.py

@@ -2,7 +2,6 @@ import re
 import textwrap
 
 import pytest
-from playwright import sync_api
 
 from .support import JsErrors, JsErrorsDidNotRaise, PyScriptTest
 
@@ -266,7 +265,7 @@ class TestSupport(PyScriptTest):
         # cleared
         self.check_js_errors()
 
-    def test_wait_for_console(self):
+    def test_wait_for_console_simple(self):
         """
         Test that self.wait_for_console actually waits.
         If it's buggy, the test will try to read self.console.log BEFORE the
@@ -285,11 +284,46 @@ class TestSupport(PyScriptTest):
         """
         self.writefile("mytest.html", doc)
         self.goto("mytest.html")
-        # we use a timeout of 500ms to give plenty of time to the page to
+        # we use a timeout of 200ms to give plenty of time to the page to
         # actually run the setTimeout callback
         self.wait_for_console("Page loaded!", timeout=200)
         assert self.console.log.lines[-1] == "Page loaded!"
 
+    def test_wait_for_console_timeout(self):
+        doc = """
+        <html>
+          <body>
+          </body>
+        </html>
+        """
+        self.writefile("mytest.html", doc)
+        self.goto("mytest.html")
+        with pytest.raises(TimeoutError):
+            self.wait_for_console("This text will never be printed", timeout=200)
+
+    def test_wait_for_console_dont_wait_if_already_emitted(self):
+        """
+        If the text is already on the console, wait_for_console() should return
+        immediately without waiting.
+        """
+        doc = """
+        <html>
+          <body>
+            <script>
+                console.log('Hello world')
+                console.log('Page loaded!');
+            </script>
+          </body>
+        </html>
+        """
+        self.writefile("mytest.html", doc)
+        self.goto("mytest.html")
+        self.wait_for_console("Page loaded!", timeout=200)
+        assert self.console.log.lines[-2] == "Hello world"
+        assert self.console.log.lines[-1] == "Page loaded!"
+        # the following call should return immediately without waiting
+        self.wait_for_console("Hello world", timeout=1)
+
     def test_wait_for_console_exception_1(self):
         """
         Test that if a JS exception is raised while waiting for the console, we
@@ -316,12 +350,12 @@ class TestSupport(PyScriptTest):
         with pytest.raises(JsErrors) as exc:
             self.wait_for_console("Page loaded!", timeout=200)
         assert "this is an error" in str(exc.value)
-        assert isinstance(exc.value.__context__, sync_api.TimeoutError)
+        assert isinstance(exc.value.__context__, TimeoutError)
         #
         # if we use check_js_errors=False, the error are ignored, but we get the
         # Timeout anyway
         self.goto("mytest.html")
-        with pytest.raises(sync_api.TimeoutError):
+        with pytest.raises(TimeoutError):
             self.wait_for_console("Page loaded!", timeout=200, check_js_errors=False)
         # we still got a JsErrors, so we need to manually clear it, else the
         # test fails at teardown

pyscriptjs/tests/integration/test_zz_examples.py

@@ -102,7 +102,7 @@ class TestExamples(PyScriptTest):
     def test_bokeh(self):
         # XXX improve this test
         self.goto("examples/bokeh.html")
-        self.wait_for_pyscript()
+        self.wait_for_pyscript(timeout=90 * 1000)
         assert self.page.title() == "Bokeh Example"
         wait_for_render(self.page, "*", '<div.*?class="bk.*".*?>')
         self.assert_no_banners()
@@ -111,7 +111,7 @@ class TestExamples(PyScriptTest):
     def test_bokeh_interactive(self):
         # XXX improve this test
         self.goto("examples/bokeh_interactive.html")
-        self.wait_for_pyscript()
+        self.wait_for_pyscript(timeout=90 * 1000)
         assert self.page.title() == "Bokeh Example"
         wait_for_render(self.page, "*", '<div.*?class=\\"bk\\".*?>')
         self.assert_no_banners()
@@ -248,7 +248,7 @@ class TestExamples(PyScriptTest):
 
     def test_panel(self):
         self.goto("examples/panel.html")
-        self.wait_for_pyscript()
+        self.wait_for_pyscript(timeout=90 * 1000)
         assert self.page.title() == "Panel Example"
         wait_for_render(self.page, "*", "<div.*?class=['\"]bk-root['\"].*?>")
         slider_title = self.page.wait_for_selector(".bk-slider-title")
@@ -268,7 +268,7 @@ class TestExamples(PyScriptTest):
     def test_panel_deckgl(self):
         # XXX improve this test
         self.goto("examples/panel_deckgl.html")
-        self.wait_for_pyscript()
+        self.wait_for_pyscript(timeout=90 * 1000)
         assert self.page.title() == "PyScript/Panel DeckGL Demo"
         wait_for_render(self.page, "*", "<div.*?class=['\"]bk-root['\"].*?>")
         self.assert_no_banners()
@@ -277,7 +277,7 @@ class TestExamples(PyScriptTest):
     def test_panel_kmeans(self):
         # XXX improve this test
         self.goto("examples/panel_kmeans.html")
-        self.wait_for_pyscript()
+        self.wait_for_pyscript(timeout=90 * 1000)
         assert self.page.title() == "Pyscript/Panel KMeans Demo"
         wait_for_render(self.page, "*", "<div.*?class=['\"]bk-root['\"].*?>")
         self.assert_no_banners()
@@ -286,7 +286,7 @@ class TestExamples(PyScriptTest):
     def test_panel_stream(self):
         # XXX improve this test
         self.goto("examples/panel_stream.html")
-        self.wait_for_pyscript()
+        self.wait_for_pyscript(timeout=90 * 1000)
         assert self.page.title() == "PyScript/Panel Streaming Demo"
         wait_for_render(self.page, "*", "<div.*?class=['\"]bk-root['\"].*?>")
         self.assert_no_banners()