[Bug]: WaitForURLAsync can lose the event it is waiting for — its check-then-subscribe races with the thread that delivers events

Version

1.62.0

Steps to reproduce

A self-contained console program; no web server is needed, both pages are fulfilled from a route. Page A sends itself to page B a few milliseconds after it has loaded. The program opens A and at once calls WaitForURLAsync("**/b").

nav-race-repro.csproj

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFrameworks>net8.0;net10.0</TargetFrameworks>
    <Nullable>enable</Nullable>
    <ImplicitUsings>enable</ImplicitUsings>
  </PropertyGroup>
  <ItemGroup>
    <PackageReference Include="Microsoft.Playwright" Version="1.62.0" />
  </ItemGroup>
</Project>

Program.cs

using System.Diagnostics;
using Microsoft.Playwright;

var delayMs = args.Length > 0 ? int.Parse(args[0]) : 20;
var laterAttempts = args.Length > 1 ? int.Parse(args[1]) : 30;

using var playwright = await Playwright.CreateAsync();
await using var browser = await playwright.Chromium.LaunchAsync();
var page = await browser.NewPageAsync();

// Both pages are served from here, so the repro needs no web server.
await page.RouteAsync("**/*", async route =>
{
    if (new Uri(route.Request.Url).AbsolutePath == "/a")
    {
        await route.FulfillAsync(new()
        {
            ContentType = "text/html",
            Body = "<p>a</p><script>addEventListener('load', () => setTimeout(() => location.href = '/b', "
                + delayMs + "))</script>"
        });
    }
    else
    {
        await route.FulfillAsync(new() { ContentType = "text/html", Body = "<h1>b</h1>" });
    }
});

var clock = Stopwatch.StartNew();
long arrivedAt = -1;

// Raised from Frame.OnNavigated, right after it has set Frame.Url and invoked Navigated.
page.FrameNavigated += (_, frame) =>
{
    if (frame.Url.EndsWith("/b", StringComparison.Ordinal)) Volatile.Write(ref arrivedAt, clock.ElapsedMilliseconds);
};

// Warm-up: the same round, waited for without WaitForURLAsync or WaitForNavigationAsync.
for (var round = 0; round < 5; round++)
{
    await page.GotoAsync("http://repro.test/a");
    await page.Locator("h1").WaitForAsync();
}

var firstTimedOut = false;
var laterTimedOut = 0;

for (var attempt = 1; attempt <= 1 + laterAttempts; attempt++)
{
    await page.GotoAsync("http://repro.test/a");
    Volatile.Write(ref arrivedAt, -1);

    var calledAt = clock.ElapsedMilliseconds;
    var label = attempt == 1 ? "first call in the process" : $"call {attempt}";

    try
    {
        await page.WaitForURLAsync("**/b", new() { Timeout = 3000 });

        if (attempt == 1)
        {
            await Task.Delay(100);

            Console.WriteLine(
                $"{label}: ok, `navigated` was delivered {Volatile.Read(ref arrivedAt) - calledAt} ms after WaitForURLAsync was called");
        }
    }
    catch (TimeoutException timeout)
    {
        Console.WriteLine(
            $"{label}: TIMED OUT after 3000 ms waiting for **/b, although `navigated` was delivered "
            + $"{Volatile.Read(ref arrivedAt) - calledAt} ms after WaitForURLAsync was called "
            + $"and page.Url is {page.Url}");

        Console.WriteLine(timeout.Message);

        if (attempt == 1) firstTimedOut = true; else laterTimedOut++;
    }
}

if (laterAttempts > 0)
{
    Console.WriteLine(
        $"calls 2..{1 + laterAttempts} (same process, warm): "
        + $"{laterAttempts - laterTimedOut} ok, {laterTimedOut} timed out");
}

return firstTimedOut ? 1 : 0;

dotnet build -c Release
for i in $(seq 1 10); do dotnet bin/Release/net8.0/nav-race-repro.dll 5; done

Each run is a new process, and that matters: it is a process's first call that is exposed (see below). The argument is how long after its load page A navigates.

Expected behavior

WaitForURLAsync("**/b") returns once B has loaded, on every call:

first call in the process: ok, `navigated` was delivered … ms after WaitForURLAsync was called
calls 2..31 (same process, warm): 30 ok, 0 timed out

Actual behavior

The first call times out waiting for a URL that page.Url already shows:

first call in the process: TIMED OUT after 3000 ms waiting for **/b, although `navigated` was delivered 11 ms after WaitForURLAsync was called and page.Url is http://repro.test/b
Timeout 3000ms exceeded.
=========================== logs ===========================
waiting for navigation to "**/b" until "Load"
============================================================
calls 2..31 (same process, warm): 30 ok, 0 timed out

Measured in fresh processes, ten per cell; the middle column is when navigated reached the client, counted from the call:

Counting every run made at the 5 ms delay, 32 of 33 fresh processes lost the first call; the one that did not had navigated arrive 12 ms after the call, early enough to be seen by the check itself. So on this machine a navigation that commits within about 25 ms of a process's first WaitForURLAsync is almost always lost, and the wait then runs to its timeout — 30 seconds by default.

Additional context

The cause is the same pattern at both of the method's checks: the caller's thread checks and then subscribes, while the transport's read loop (StdIOTransport.GetResponseAsync → Connection.Dispatch → Frame.OnMessage) updates and then raises, and nothing orders the two.

// Frame.WaitForURLAsync -- caller's thread
if (urlMatch.Match(Url)) return WaitForLoadStateAsync(...);   // check
return WaitForNavigationAsync(...);                            // ...subscribes to Navigated, later

// Frame.OnNavigated -- transport's thread
Url = e.Url;
Navigated?.Invoke(this, e);                                    // nobody listening yet: lost

A navigated delivered between the check and the subscription has already moved Frame.Url, so nothing will ever raise it again, and the waiter's log never gets its navigated to line. That is the program above.

One step later the same thing happens to the load state:

// Frame.WaitForLoadStateAsync -- caller's thread
if (_loadStates.Contains(loadState)) { ... return; }          // check
await waiter.WaitForEventAsync(this, "LoadState", ...);       // subscribe

// Frame.OnLoadState -- transport's thread
_loadStates.Add(add.Value);
LoadState?.Invoke(this, add.Value);                            // nobody listening yet: lost

_loadStates is also a plain List<T> read on one thread while another adds to and removes from it. WaitForNavigationInternalAsync has the same pair of lines after its Navigated wait; it usually runs as a continuation on the delivering thread, which hides it, though nothing guarantees that.

The JavaScript client has the same shape in waitForURL and waitForLoadState, where it is safe: the check and the subscription run in one turn of a single-threaded event loop, and events are delivered in other turns. The .NET port kept the shape and delivers events from another thread.

Why the first call. Between the URL check and its subscription sit SetupNavigationWaiter and Waiter.GetWaitForEventTask<T> — a generic method instantiated over a new type argument, a reflection GetEvent and a reflection AddEventHandler. Between the load-state check and its subscription sits the latter alone, which is why that window is the narrower one. Warm, that is microseconds; on the first call in a process none of it is compiled and it is tens of milliseconds, wide enough to catch an event reliably. The hole is still there when warm, only narrow — which would fit the earlier reports below, where it needed CPU contention to show.

The load-state window is how this was found, in a suite of browser tests, on Windows and on a GitHub-hosted ubuntu-latest runner, as one failure in six to eight runs of whichever test called WaitForURLAsync first. The test clicks a link and then calls WaitForURLAsync. ClickAsync returns once the navigation it started has committed, so the URL already matches and the call is a wait for load; the page is small and its assets cached, so load arrives about 20 ms later, inside the cold window. The documentation recommends exactly this call in place of WaitForNavigationAsync, which it describes as inherently racy.

A second stand-alone program reproduces that window: open A, click a link to B, call WaitForURLAsync("**/b"), where B holds an image answered a few milliseconds late. That window is narrower, so it is hit less often — 8 first calls lost in 213 fresh processes here, across delays from 0 to 80 ms — but the capture is unambiguous. The client's own record of the frame, read by reflection after the timeout, holds Load, while the wait for Load has just timed out having heard only networkidle — and the same wait asked again returns at once:

first call in the process: TIMED OUT after 3000 ms, although page.Load was raised 15 ms after ClickAsync returned and document.readyState is "complete"
Frame._loadStates: Commit, DOMContentLoaded, Load, NetworkIdle
Timeout 3000ms exceeded.
=========================== logs ===========================
  "NetworkIdle" event fired
============================================================
a second WaitForLoadStateAsync(Load) returned after 2 ms

using System.Diagnostics;
using Microsoft.Playwright;

var delayMs = args.Length > 0 ? int.Parse(args[0]) : 20;
var laterAttempts = args.Length > 1 ? int.Parse(args[1]) : 30;

using var playwright = await Playwright.CreateAsync();
await using var browser = await playwright.Chromium.LaunchAsync();
var page = await browser.NewPageAsync();

// Both pages are served from here, so the repro needs no web server.
await page.RouteAsync("**/*", async route =>
{
    switch (new Uri(route.Request.Url).AbsolutePath)
    {
        case "/a":
            await route.FulfillAsync(new() { ContentType = "text/html", Body = "<a href='/b'>to b</a>" });
            break;

        case "/b":
            await route.FulfillAsync(new() { ContentType = "text/html", Body = "<h1>b</h1><img src='/held.png'>" });
            break;

        default:
            // Holds `load` back: the document is not loaded until its image has an answer. Spun on
            // another thread rather than Task.Delay, whose 15 ms granularity on Windows is coarser
            // than the window being aimed at, and not on this one, which delivers the messages.
            await Task.Run(() =>
            {
                var held = Stopwatch.StartNew();
                SpinWait.SpinUntil(() => held.Elapsed.TotalMilliseconds >= delayMs);
            });
            await route.FulfillAsync(new() { Status = 404 });
            break;
    }
});

var clock = Stopwatch.StartNew();
long loadedAt = -1;

// Raised by the same Frame.OnLoadState call that adds Load to _loadStates and invokes LoadState,
// so this is when the client had the event in hand.
page.Load += (_, _) => Volatile.Write(ref loadedAt, clock.ElapsedMilliseconds);

// Warm-up: the same round, waited for without WaitForURLAsync or WaitForLoadStateAsync.
for (var round = 0; round < 5; round++)
{
    await page.GotoAsync("http://repro.test/a");
    await page.ClickAsync("a");
    await page.Locator("h1").WaitForAsync();
    await page.WaitForFunctionAsync("document.readyState === 'complete'");
}

var firstTimedOut = false;
var laterTimedOut = 0;

for (var attempt = 1; attempt <= 1 + laterAttempts; attempt++)
{
    await page.GotoAsync("http://repro.test/a");
    Volatile.Write(ref loadedAt, -1);

    await page.ClickAsync("a");
    var clickedAt = clock.ElapsedMilliseconds;

    var label = attempt == 1 ? "first call in the process" : $"call {attempt}";

    try
    {
        await page.WaitForURLAsync("**/b", new() { Timeout = 3000 });

        if (attempt == 1)
        {
            // The waiter completes this await from inside Frame.OnLoadState, before that method goes
            // on to raise page.Load -- so give it a moment before reading when Load was raised.
            await Task.Delay(100);

            Console.WriteLine(
                $"{label}: ok, page.Load was raised {Volatile.Read(ref loadedAt) - clickedAt} ms after ClickAsync returned");
        }
    }
    catch (TimeoutException timeout)
    {
        var readyState = await page.EvaluateAsync<string>("document.readyState");

        Console.WriteLine(
            $"{label}: TIMED OUT after 3000 ms, although page.Load was raised "
            + $"{Volatile.Read(ref loadedAt) - clickedAt} ms after ClickAsync returned "
            + $"and document.readyState is \"{readyState}\"");

        // The client's own record of the frame, read by reflection: `Load` is in it, while the wait
        // for `Load` has just timed out. And the waiter's log: what it heard in the meantime.
        if (Environment.GetEnvironmentVariable("REPRO_VERBOSE") == "1")
        {
            var recorded = (System.Collections.IEnumerable)page.MainFrame.GetType()
                .GetField("_loadStates", System.Reflection.BindingFlags.NonPublic | System.Reflection.BindingFlags.Instance)!
                .GetValue(page.MainFrame)!;

            Console.WriteLine($"Frame._loadStates: {string.Join(", ", recorded.Cast<object>())}");
            Console.WriteLine(timeout.Message);

            // And the same wait, asked again: the state is recorded, so the check finds it.
            var again = Stopwatch.StartNew();
            await page.WaitForLoadStateAsync(LoadState.Load, new() { Timeout = 3000 });
            Console.WriteLine($"a second WaitForLoadStateAsync(Load) returned after {again.ElapsedMilliseconds} ms");
        }

        if (attempt == 1) firstTimedOut = true; else laterTimedOut++;
    }
}

if (laterAttempts > 0)
{
    Console.WriteLine(
        $"calls 2..{1 + laterAttempts} (same process, warm): "
        + $"{laterAttempts - laterTimedOut} ok, {laterTimedOut} timed out");
}

return firstTimedOut ? 1 : 0;

Earlier reports. #2897 and #2898 ("Intermittent timeouts when calling WaitForURLAsync", 1.41.2) show the first program's log exactly — waiting for navigation to "…" until "Load" and nothing after it — and were closed because they could not be reproduced. The reporter's note there that it only happened with two or more containers on one node fits: contention widens the gap between the check and the subscription even when everything is compiled.

A possible fix is to subscribe before checking at each of the three sites — an event heard twice is harmless, an event never heard is a timeout — or to take one lock around check-and-subscribe on the caller's side and around update-and-raise on the delivering side.

A workaround, for anyone who meets this first: assert the address with Expect(page).ToHaveURLAsync(...), which is one request the server polls and answers, so there is no client-side event to lose. Where a load state itself is wanted, call WaitForLoadStateAsync with a short timeout in a loop — a missed state is still recorded, so the next call finds it at the check and returns at once, as the capture above shows.

Environment

- OS: Windows 11 (10.0.26200), x64; the load-state window was also met on a GitHub-hosted `ubuntu-latest` runner
- .NET SDK 10.0.400; run on Microsoft.NETCore.App 8.0.1 and 10.0.11
- Microsoft.Playwright 1.62.0 from nuget.org
- Browser: Chromium 151.0.7922.34 (Playwright build 1234), headless

Start with Frame.WaitForURLAsync, Frame.WaitForLoadStateAsync, Frame.OnNavigated, and Frame.OnLoadState, then trace SetupNavigationWaiter and Waiter.GetWaitForEventTask. Run the supplied console repro to observe the first-call timeout. Done means navigation and load-state events are not lost between the initial check and subscription, with the repro completing reliably.