From 51edfa83f55d8ea4776bc1e022dbac066fd98422 Mon Sep 17 00:00:00 2001 From: Sylvain <35365065+sanderegg@users.noreply.github.com> Date: Fri, 20 Sep 2024 16:05:06 +0200 Subject: [PATCH] =?UTF-8?q?=E2=9C=A8E2E:=20increase=20timeout=20for=20vide?= =?UTF-8?q?o=20streaming=20and=20improve=20a=20bit=20logs=20about=20websoc?= =?UTF-8?q?kets=20(#6384)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../pytest_simcore/helpers/logging_tools.py | 6 +- .../src/pytest_simcore/helpers/playwright.py | 55 +++++++++++-------- .../helpers/playwright_sim4life.py | 8 ++- tests/e2e-playwright/tests/conftest.py | 37 +++++++++---- .../tests/sim4life/test_sim4life.py | 14 +++-- .../tests/sim4life/test_template.py | 10 ++-- 6 files changed, 81 insertions(+), 49 deletions(-) diff --git a/packages/pytest-simcore/src/pytest_simcore/helpers/logging_tools.py b/packages/pytest-simcore/src/pytest_simcore/helpers/logging_tools.py index 427117749aa..2bb29562d75 100644 --- a/packages/pytest-simcore/src/pytest_simcore/helpers/logging_tools.py +++ b/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)})" ) diff --git a/packages/pytest-simcore/src/pytest_simcore/helpers/playwright.py b/packages/pytest-simcore/src/pytest_simcore/helpers/playwright.py index 6060b2d026f..0225642cc4f 100644 --- a/packages/pytest-simcore/src/pytest_simcore/helpers/playwright.py +++ b/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: diff --git a/packages/pytest-simcore/src/pytest_simcore/helpers/playwright_sim4life.py b/packages/pytest-simcore/src/pytest_simcore/helpers/playwright_sim4life.py index 58c00e69597..ddbd444c5f6 100644 --- a/packages/pytest-simcore/src/pytest_simcore/helpers/playwright_sim4life.py +++ b/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[^:]+)://(?P[^\.]+)\.services\.(?P[^\/]+)\/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 diff --git a/tests/e2e-playwright/tests/conftest.py b/tests/e2e-playwright/tests/conftest.py index d7104c6fe70..997ac6b7138 100644 --- a/tests/e2e-playwright/tests/conftest.py +++ b/tests/e2e-playwright/tests/conftest.py @@ -25,8 +25,8 @@ 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, @@ -34,6 +34,7 @@ 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 diff --git a/tests/e2e-playwright/tests/sim4life/test_sim4life.py b/tests/e2e-playwright/tests/sim4life/test_sim4life.py index 23778f3f3f5..b993f262181 100644 --- a/tests/e2e-playwright/tests/sim4life/test_sim4life.py +++ b/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) diff --git a/tests/e2e-playwright/tests/sim4life/test_template.py b/tests/e2e-playwright/tests/sim4life/test_template.py index 9ac5d4ae065..a4f104a6291 100644 --- a/tests/e2e-playwright/tests/sim4life/test_template.py +++ b/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)