✨E2E: increase timeout for video streaming and improve a bit logs about websockets (#6384)

Author: sanderegg

packages/pytest-simcore/src/pytest_simcore/helpers/logging_tools.py

@@ -133,14 +133,14 @@ def log_context(
     else:
         ctx_msg = msg
 
-    started_time = datetime.datetime.now(tz=datetime.timezone.utc)
+    started_time = datetime.datetime.now(tz=datetime.UTC)
     try:
         DynamicIndentFormatter.cls_increase_indent()
 
         logger.log(level, ctx_msg.starting, *args, **kwargs)
         with _increased_logger_indent(logger):
             yield SimpleNamespace(logger=logger, messages=ctx_msg)
-        elapsed_time = datetime.datetime.now(tz=datetime.timezone.utc) - started_time
+        elapsed_time = datetime.datetime.now(tz=datetime.UTC) - started_time
         done_message = (
             f"{ctx_msg.done} ({_timedelta_as_minute_second_ms(elapsed_time)})"
         )
@@ -152,7 +152,7 @@ def log_context(
         )
 
     except:
-        elapsed_time = datetime.datetime.now(tz=datetime.timezone.utc) - started_time
+        elapsed_time = datetime.datetime.now(tz=datetime.UTC) - started_time
         error_message = (
             f"{ctx_msg.raised} ({_timedelta_as_minute_second_ms(elapsed_time)})"
         )

packages/pytest-simcore/src/pytest_simcore/helpers/playwright.py

@@ -3,10 +3,10 @@
 import logging
 import re
 from collections import defaultdict
-from contextlib import ExitStack
+from collections.abc import Generator, Iterator
 from dataclasses import dataclass, field
 from enum import Enum, unique
-from typing import Any, Final, Generator
+from typing import Any, Final
 
 from playwright.sync_api import FrameLocator, Page, Request, WebSocket
 from pytest_simcore.helpers.logging_tools import log_context
@@ -263,28 +263,37 @@ def wait_for_pipeline_state(
     return current_state
 
 
-def on_web_socket_default_handler(ws) -> None:
-    """Usage
-
-    from pytest_simcore.playwright_utils import on_web_socket_default_handler
-
-    page.on("websocket", on_web_socket_default_handler)
-
-    """
-    stack = ExitStack()
-    ctx = stack.enter_context(
-        log_context(
-            logging.INFO,
-            (
-                f"WebSocket opened: {ws.url}",
-                "WebSocket closed",
-            ),
-        )
-    )
+@contextlib.contextmanager
+def web_socket_default_log_handler(web_socket: WebSocket) -> Iterator[None]:
 
-    ws.on("framesent", lambda payload: ctx.logger.info("⬇️ %s", payload))
-    ws.on("framereceived", lambda payload: ctx.logger.info("⬆️ %s", payload))
-    ws.on("close", lambda payload: stack.close())  # noqa: ARG005
+    try:
+        with log_context(
+            logging.DEBUG,
+            msg="handle websocket message (set to --log-cli-level=DEBUG level if you wanna see all of them)",
+        ) as ctx:
+
+            def on_framesent(payload: str | bytes) -> None:
+                ctx.logger.debug("⬇️ Frame sent: %s", payload)
+
+            def on_framereceived(payload: str | bytes) -> None:
+                ctx.logger.debug("⬆️ Frame received: %s", payload)
+
+            def on_close(payload: WebSocket) -> None:
+                ctx.logger.warning("⚠️ Websocket closed: %s", payload)
+
+            def on_socketerror(error_msg: str) -> None:
+                ctx.logger.error("❌ Websocket error: %s", error_msg)
+
+            web_socket.on("framesent", on_framesent)
+            web_socket.on("framereceived", on_framereceived)
+            web_socket.on("close", on_close)
+            web_socket.on("socketerror", on_socketerror)
+            yield
+    finally:
+        web_socket.remove_listener("framesent", on_framesent)
+        web_socket.remove_listener("framereceived", on_framereceived)
+        web_socket.remove_listener("close", on_close)
+        web_socket.remove_listener("socketerror", on_socketerror)
 
 
 def _node_started_predicate(request: Request) -> bool:

packages/pytest-simcore/src/pytest_simcore/helpers/playwright_sim4life.py

@@ -6,6 +6,8 @@
 
 import arrow
 from playwright.sync_api import FrameLocator, Page, WebSocket, expect
+from pydantic import TypeAdapter  # pylint: disable=no-name-in-module
+from pydantic import ByteSize
 
 from .logging_tools import log_context
 from .playwright import (
@@ -17,7 +19,7 @@
     wait_for_service_running,
 )
 
-_S4L_STREAMING_ESTABLISHMENT_MAX_TIME: Final[int] = 15 * SECOND
+_S4L_STREAMING_ESTABLISHMENT_MAX_TIME: Final[int] = 30 * SECOND
 _S4L_SOCKETIO_REGEX: Final[re.Pattern] = re.compile(
     r"^(?P<protocol>[^:]+)://(?P<node_id>[^\.]+)\.services\.(?P<hostname>[^\/]+)\/socket\.io\/.+$"
 )
@@ -63,7 +65,7 @@ def __call__(self, message: str) -> bool:
                     self._initial_bit_rate_time = arrow.utcnow().datetime
                     self.logger.info(
                         "%s",
-                        f"{self._initial_bit_rate=} at {self._initial_bit_rate_time.isoformat()}",
+                        f"{TypeAdapter(ByteSize).validate_python(self._initial_bit_rate).human_readable()}/s at {self._initial_bit_rate_time.isoformat()}",
                     )
                     return False
 
@@ -78,7 +80,7 @@ def __call__(self, message: str) -> bool:
                     bitrate_test = bool(self._initial_bit_rate != current_bitrate)
                     self.logger.info(
                         "%s",
-                        f"{current_bitrate=} after {elapsed_time=}: {'good!' if bitrate_test else 'failed! bitrate did not change! TIP: talk with MaG about underwater cables!'}",
+                        f"{TypeAdapter(ByteSize).validate_python(current_bitrate).human_readable()}/s after {elapsed_time=}: {'good!' if bitrate_test else 'failed! bitrate did not change! TIP: talk with MaG about underwater cables!'}",
                     )
                     return bitrate_test
 

tests/e2e-playwright/tests/conftest.py

@@ -25,15 +25,16 @@
 from pytest import Item
 from pytest_simcore.helpers.logging_tools import log_context
 from pytest_simcore.helpers.playwright import (
-    SECOND,
     MINUTE,
+    SECOND,
     AutoRegisteredUser,
     RunningState,
     ServiceType,
     SocketIOEvent,
     SocketIOProjectClosedWaiter,
     SocketIOProjectStateUpdatedWaiter,
     decode_socketio_42_message,
+    web_socket_default_log_handler,
 )
 
 _PROJECT_CLOSING_TIMEOUT: Final[int] = 10 * MINUTE
@@ -171,9 +172,11 @@ def pytest_runtest_makereport(item: Item, call):
             diagnostics["duration"] = str(end_time - start_time)
 
         # Print the diagnostics report
-        print(f"\nDiagnostics repoort for {test_name} ---")
-        print(json.dumps(diagnostics, indent=2))
-        print("---")
+        with log_context(
+            logging.WARNING,
+            f"ℹ️ Diagnostics report for {test_name} ---",  # noqa: RUF001
+        ) as ctx:
+            ctx.logger.warning(json.dumps(diagnostics, indent=2))
 
 
 @pytest.hookimpl(tryfirst=True)
@@ -369,7 +372,8 @@ def log_in_and_out(
     if quickStartWindowCloseBtnLocator.is_visible():
         quickStartWindowCloseBtnLocator.click()
 
-    yield ws
+    with web_socket_default_log_handler(ws):
+        yield ws
 
     with log_context(
         logging.INFO,
@@ -410,12 +414,17 @@ def _(
             f"Open project in {product_url=} as {product_billable=}",
         ) as ctx:
             waiter = SocketIOProjectStateUpdatedWaiter(expected_states=expected_states)
-            timeout = _OPENING_TUTORIAL_MAX_WAIT_TIME if template_id is not None else _OPENING_NEW_EMPTY_PROJECT_MAX_WAIT_TIME
+            timeout = (
+                _OPENING_TUTORIAL_MAX_WAIT_TIME
+                if template_id is not None
+                else _OPENING_NEW_EMPTY_PROJECT_MAX_WAIT_TIME
+            )
             with (
-                log_in_and_out.expect_event("framereceived", waiter, timeout=timeout + 10 * SECOND),
+                log_in_and_out.expect_event(
+                    "framereceived", waiter, timeout=timeout + 10 * SECOND
+                ),
                 page.expect_response(
-                    re.compile(r"/projects/[^:]+:open"),
-                    timeout=timeout + 5 * SECOND
+                    re.compile(r"/projects/[^:]+:open"), timeout=timeout + 5 * SECOND
                 ) as response_info,
             ):
                 # Project detail view pop-ups shows
@@ -436,8 +445,11 @@ def _(
                             # From the long running tasks response's urls, only their path is relevant
                             def url_to_path(url):
                                 return urllib.parse.urlparse(url).path
+
                             def wait_for_done(response):
-                                if url_to_path(response.url) == url_to_path(lrt_data["status_href"]):
+                                if url_to_path(response.url) == url_to_path(
+                                    lrt_data["status_href"]
+                                ):
                                     resp_data = response.json()
                                     resp_data = resp_data["data"]
                                     assert "task_progress" in resp_data
@@ -448,10 +460,13 @@ def wait_for_done(response):
                                         task_progress["message"],
                                     )
                                     return False
-                                if url_to_path(response.url) == url_to_path(lrt_data["result_href"]):
+                                if url_to_path(response.url) == url_to_path(
+                                    lrt_data["result_href"]
+                                ):
                                     copying_logger.logger.info("project created")
                                     return response.status == 201
                                 return False
+
                             with page.expect_response(wait_for_done, timeout=timeout):
                                 # if the above calls go to fast, this test could fail
                                 # not expected in the sim4life context though

tests/e2e-playwright/tests/sim4life/test_sim4life.py

@@ -11,7 +11,10 @@
 from typing import Any
 
 from playwright.sync_api import Page, WebSocket
-from pytest_simcore.helpers.playwright import ServiceType
+from pytest_simcore.helpers.playwright import (
+    ServiceType,
+    web_socket_default_log_handler,
+)
 from pytest_simcore.helpers.playwright_sim4life import (
     check_video_streaming,
     interact_with_s4l,
@@ -49,8 +52,9 @@ def test_sim4life(
         page, node_ids[0], log_in_and_out, autoscaled=autoscaled, copy_workspace=False
     )
     s4l_websocket = resp["websocket"]
-    s4l_iframe = resp["iframe"]
-    interact_with_s4l(page, s4l_iframe)
+    with web_socket_default_log_handler(s4l_websocket):
+        s4l_iframe = resp["iframe"]
+        interact_with_s4l(page, s4l_iframe)
 
-    if check_videostreaming:
-        check_video_streaming(page, s4l_iframe, s4l_websocket)
+        if check_videostreaming:
+            check_video_streaming(page, s4l_iframe, s4l_websocket)

tests/e2e-playwright/tests/sim4life/test_template.py

@@ -11,6 +11,7 @@
 from typing import Any
 
 from playwright.sync_api import Page, WebSocket
+from pytest_simcore.helpers.playwright import web_socket_default_log_handler
 from pytest_simcore.helpers.playwright_sim4life import (
     check_video_streaming,
     interact_with_s4l,
@@ -39,8 +40,9 @@ def test_template(
         page, node_ids[0], log_in_and_out, autoscaled=autoscaled, copy_workspace=True
     )
     s4l_websocket = resp["websocket"]
-    s4l_iframe = resp["iframe"]
-    interact_with_s4l(page, s4l_iframe)
+    with web_socket_default_log_handler(s4l_websocket):
+        s4l_iframe = resp["iframe"]
+        interact_with_s4l(page, s4l_iframe)
 
-    if check_videostreaming:
-        check_video_streaming(page, s4l_iframe, s4l_websocket)
+        if check_videostreaming:
+            check_video_streaming(page, s4l_iframe, s4l_websocket)