chore: support client side event logging (#827)

Author: mxschmitt

playwright/_impl/_frame.py

@@ -153,6 +153,9 @@ def expect_navigation(
             timeout = self._page._timeout_settings.navigation_timeout()
         deadline = monotonic_time() + timeout
         wait_helper = self._setup_navigation_wait_helper("expect_navigation", timeout)
+
+        to_url = f' to "{url}"' if url else ""
+        wait_helper.log(f"waiting for navigation{to_url} until '{wait_until}'")
         matcher = (
             URLMatcher(self._page._browser_context._options.get("baseURL"), url)
             if url
@@ -163,6 +166,7 @@ def predicate(event: Any) -> bool:
             # Any failed navigation results in a rejection.
             if event.get("error"):
                 return True
+            wait_helper.log(f'  navigated to "{event["url"]}"')
             return not matcher or matcher.matches(event["url"])
 
         wait_helper.wait_for_event(
@@ -211,8 +215,15 @@ async def wait_for_load_state(
         if state in self._load_states:
             return
         wait_helper = self._setup_navigation_wait_helper("wait_for_load_state", timeout)
+
+        def handle_load_state_event(actual_state: str) -> bool:
+            wait_helper.log(f'"{actual_state}" event fired')
+            return actual_state == state
+
         wait_helper.wait_for_event(
-            self._event_emitter, "loadstate", lambda s: s == state
+            self._event_emitter,
+            "loadstate",
+            handle_load_state_event,
         )
         await wait_helper.result()
 

playwright/_impl/_page.py

@@ -15,6 +15,7 @@
 import asyncio
 import base64
 import inspect
+import re
 import sys
 from pathlib import Path
 from types import SimpleNamespace
@@ -787,13 +788,26 @@ def expect_event(
         event: str,
         predicate: Callable = None,
         timeout: float = None,
+    ) -> EventContextManagerImpl:
+        return self._expect_event(
+            event, predicate, timeout, f'waiting for event "{event}"'
+        )
+
+    def _expect_event(
+        self,
+        event: str,
+        predicate: Callable = None,
+        timeout: float = None,
+        log_line: str = None,
     ) -> EventContextManagerImpl:
         if timeout is None:
             timeout = self._timeout_settings.timeout()
         wait_helper = WaitHelper(self, f"page.expect_event({event})")
         wait_helper.reject_on_timeout(
             timeout, f'Timeout while waiting for event "{event}"'
         )
+        if log_line:
+            wait_helper.log(log_line)
         if event != Page.Events.Crash:
             wait_helper.reject_on_event(self, Page.Events.Crash, Error("Page crashed"))
         if event != Page.Events.Close:
@@ -858,8 +872,13 @@ def my_predicate(request: Request) -> bool:
                 return predicate(request)
             return True
 
-        return self.expect_event(
-            Page.Events.Request, predicate=my_predicate, timeout=timeout
+        trimmed_url = trim_url(url_or_predicate)
+        log_line = f"waiting for request {trimmed_url}" if trimmed_url else None
+        return self._expect_event(
+            Page.Events.Request,
+            predicate=my_predicate,
+            timeout=timeout,
+            log_line=log_line,
         )
 
     def expect_request_finished(
@@ -892,8 +911,13 @@ def my_predicate(response: Response) -> bool:
                 return predicate(response)
             return True
 
-        return self.expect_event(
-            Page.Events.Response, predicate=my_predicate, timeout=timeout
+        trimmed_url = trim_url(url_or_predicate)
+        log_line = f"waiting for response {trimmed_url}" if trimmed_url else None
+        return self._expect_event(
+            Page.Events.Response,
+            predicate=my_predicate,
+            timeout=timeout,
+            log_line=log_line,
         )
 
     def expect_websocket(
@@ -986,3 +1010,17 @@ async def call(self, func: Callable) -> None:
                     "reject", dict(error=dict(error=serialize_error(e, tb)))
                 )
             )
+
+
+def trim_url(param: URLMatchRequest) -> Optional[str]:
+    if isinstance(param, re.Pattern):
+        return trim_end(param.pattern)
+    if isinstance(param, str):
+        return trim_end(param)
+    return None
+
+
+def trim_end(s: str) -> str:
+    if len(s) > 50:
+        return s[:50] + "\u2026"
+    return s

playwright/_impl/_wait_helper.py

@@ -13,6 +13,7 @@
 # limitations under the License.
 
 import asyncio
+import math
 import uuid
 from asyncio.tasks import Task
 from typing import Any, Callable, List, Tuple
@@ -31,6 +32,7 @@ def __init__(self, channel_owner: ChannelOwner, event: str) -> None:
         self._pending_tasks: List[Task] = []
         self._channel = channel_owner._channel
         self._registered_listeners: List[Tuple[EventEmitter, str, Callable]] = []
+        self._logs: List[str] = []
         self._wait_for_event_info_before(self._wait_id, event)
 
     def _wait_for_event_info_before(self, wait_id: str, event: str) -> None:
@@ -101,6 +103,9 @@ def _fulfill(self, result: Any) -> None:
 
     def _reject(self, exception: Exception) -> None:
         self._cleanup()
+        if exception:
+            base_class = TimeoutError if isinstance(exception, TimeoutError) else Error
+            exception = base_class(str(exception) + format_log_recording(self._logs))
         if not self._result.done():
             self._result.set_exception(exception)
         self._wait_for_event_info_after(self._wait_id, exception)
@@ -121,10 +126,37 @@ def listener(event_data: Any = None) -> None:
     def result(self) -> asyncio.Future:
         return self._result
 
+    def log(self, message: str) -> None:
+        self._logs.append(message)
+        try:
+            self._channel.send_no_reply(
+                "waitForEventInfo",
+                {
+                    "info": {
+                        "waitId": self._wait_id,
+                        "phase": "log",
+                        "message": message,
+                    },
+                },
+            )
+        except Exception:
+            pass
+
 
 def throw_on_timeout(timeout: float, exception: Exception) -> asyncio.Task:
     async def throw() -> None:
         await asyncio.sleep(timeout / 1000)
         raise exception
 
     return asyncio.create_task(throw())
+
+
+def format_log_recording(log: List[str]) -> str:
+    if not log:
+        return ""
+    header = " logs "
+    header_length = 60
+    left_length = math.floor((header_length - len(header)) / 2)
+    right_length = header_length - len(header) - left_length
+    new_line = "\n"
+    return f"{new_line}{'=' * left_length}{header}{'=' * right_length}{new_line}{new_line.join(log)}{new_line}{'=' * header_length}"