Represent timing info better

Also add some more timeouts

Author: yuvipanda

simulate.py

@@ -8,13 +8,18 @@
 from dataclasses import dataclass
 from datetime import datetime
 from functools import partial
+import time
 from typing import List
 
 import aiohttp
 import aiometer
 from playwright.async_api import Browser, async_playwright
 from yarl import URL
 
+@dataclass
+class TimedResult[T]:
+    duration: float
+    result: T
 
 @dataclass
 class HubAccess:
@@ -43,8 +48,6 @@ class RunningServer(Server):
     Represents a running user server
     """
 
-    start_request_time: datetime
-    start_completion_time: datetime
     server_url: URL
     startup_events: List[dict]
 
@@ -86,29 +89,30 @@ async def load_nbgitpuller_url(
     token: str,
     nbgitpuller_url: NBGitpullerURL,
     screenshot_name: str,
-):
-    print(f"visiting {server.server_url}")
-    start_time = datetime.now()
+) -> TimedResult[None]:
+    start_time = time.perf_counter()
 
     context = await browser.new_context(
         extra_http_headers={"Authorization": f"token {token}"}
     )
     page = await context.new_page()
-    await page.goto(str(nbgitpuller_url.make_fullpath(server.server_url, secrets.token_hex(8))))
-    await page.wait_for_url(nbgitpuller_url.expected_final_url, timeout=120 * 10 * 1000)
+    targetpath = secrets.token_hex(8)
+    going_to = nbgitpuller_url.make_fullpath(server.server_url, targetpath)
+    await page.goto(str(going_to))
+    expected_final_full_url = str(nbgitpuller_url.make_expectedpath(server.server_url, targetpath))
+    await page.wait_for_url(expected_final_full_url, timeout=120 * 10 * 1000)
     await page.wait_for_load_state("networkidle")
-    await page.screenshot(path=screenshot_name)
-    duration = datetime.now() - start_time
-    print(f"{server.server_url} completed test in {duration}")
-
+    await page.screenshot(path=screenshot_name, timeout=5 * 60 * 1000)
+    return TimedResult(time.perf_counter() - start_time, None)
 
 async def start_named_server(
-    session: aiohttp.ClientSession, server: Server, profile_options: dict[str, str] | None = None
-) -> RunningServer | None:
+    session: aiohttp.ClientSession, server: Server, profile_options: dict[str, str] | None = None,
+) -> TimedResult[RunningServer | None]:
     """
     Try to start a named server as defined
 
     """
+    start_time = time.perf_counter()
     headers = {"Authorization": f"token {server.hub_access.token}"}
     server_api_url = (
         server.hub_access.url
@@ -119,12 +123,10 @@ async def start_named_server(
     )
     events = []
     async with session.post(server_api_url, headers=headers, json=profile_options) as resp:
-        start_time = datetime.now()
         if resp.status == 202:
             # we are awaiting start, let's look for events
-            print(f"server {server.servername} waiting to start")
             async with session.get(
-                server_api_url / "progress", headers=headers
+                server_api_url / "progress", headers=headers, timeout=aiohttp.ClientTimeout(10 * 60)
             ) as progress_resp:
                 async for line in progress_resp.content:
                     if line.decode().strip() == "":
@@ -133,17 +135,17 @@ async def start_named_server(
                     progress_event = json.loads(line.decode().strip()[len("data: ") :])
                     events.append(progress_event)
                     if progress_event.get("ready") == True:
-                        print(progress_event)
-                        return RunningServer(
-                            servername=server.servername,
-                            username=server.username,
-                            hub_access=server.hub_access,
-                            start_request_time=start_time,
-                            start_completion_time=datetime.now(),
-                            startup_events=events,
-                            server_url=URL(
-                                server.hub_access.url / progress_event["url"][1:]
-                            ),  # Trim leading slashG
+                        return TimedResult(
+                            time.perf_counter() - start_time,
+                            RunningServer(
+                                servername=server.servername,
+                                username=server.username,
+                                hub_access=server.hub_access,
+                                startup_events=events,
+                                server_url=URL(
+                                    server.hub_access.url.joinpath(progress_event["url"].lstrip("/"), encoded=True)
+                                ),
+                            )
                         )
         elif resp.status == 201:
             # Means the server is immediately ready, and i don't want to deal with that yet
@@ -161,18 +163,29 @@ async def payload(
     profile_options: dict[str, str] | None,
     server: Server,
 ):
-    started_server = await start_named_server(session, server, profile_options)
-    match started_server:
-        case RunningServer():
-            await load_nbgitpuller_url(
-                browser,
-                started_server,
-                auth_token,
-                nbgitpuller_url,
-                server.servername + ".png",
-            )
-        case _:
-            print("Server startup failed")
+    timing_info = {}
+    print(f"Starting {server.servername}")
+    start_server_result = await start_named_server(session, server, profile_options)
+    match start_server_result:
+        case TimedResult(server_startup_duration, started_server):
+            timing_info["server_startup"] = server_startup_duration
+            print(f"Started {server.servername} in {server_startup_duration:0.2f}s")
+            match started_server:
+                case RunningServer():
+                    print(f"Starting nbgitpuller for {server.servername}")
+                    result = await load_nbgitpuller_url(
+                        browser,
+                        started_server,
+                        auth_token,
+                        nbgitpuller_url,
+                        server.servername + ".png",
+                    )
+                    timing_info["nbgitpuller"] = result.duration
+                    print(f"nbgitpuller completed for {server.servername} in {result.duration:0.2f}s")
+                case None:
+                    print("Server startup failed")
+
+    print(f"{server.servername}: {timing_info}")
 
 
 async def main():
@@ -181,10 +194,11 @@ async def main():
     argparser.add_argument("server_prefix", help="Prefix used for named servers started in this run")
     argparser.add_argument("username", help="Name of the user")
     argparser.add_argument("servers_count", type=int, help="Number of servers to start")
+    # FIXME: This shouldn't be here.
     argparser.add_argument(
         "--max-concurrency",
         type=int,
-        default=30,
+        default=25,
         help="Max Numbers of Servers to start at the same time",
     )
     argparser.add_argument(