Flaky test CanFocusDuringOnAfterRenderAsyncWithFocusInEvent

[BrennanConroy]

Error Message

OpenQA.Selenium.BrowserAssertFailedException : Xunit.Sdk.EqualException: Assert.Equal() Failure
Expected: True
Actual:   False
   at Xunit.Assert.Equal[T](T expected, T actual, IEqualityComparer1 comparer) in C:\\Dev\\xunit\\xunit\\src\\xunit.assert\\Asserts\\EqualityAsserts.cs:line 40
 at Microsoft.AspNetCore.E2ETesting.WaitAssert.<>c__DisplayClass17_0.<WaitAssertCore>b__0() in /_/src/Shared/E2ETesting/WaitAssert.cs:line 83
 at Microsoft.AspNetCore.E2ETesting.WaitAssert.<>c__DisplayClass18_01.<WaitAssertCore>b__0(IWebDriver ) in //src/Shared/E2ETesting/WaitAssert.cs:line 109
Screen shot captured at 'D:\workspace\_work\1\s\artifacts\TestResults\Release\Microsoft.AspNetCore.Components.E2ETests\6a01e6d8b47742229c6224e58c9eb967.png'
Encountered browser errors
[2021-05-20T17:43:11Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:11.634Z] Information: Normalizing '_blazor' to 'http://127.0.0.1:53740/subdir/_blazor'."
[2021-05-20T17:43:11Z] [Info] http://127.0.0.1:53740/subdir 45:16 "Blazor server-side"
[2021-05-20T17:43:11Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:11.653Z] Information: WebSocket connected to ws://127.0.0.1:53740/subdir/_blazor?id=nVaSqzMOtc4g7KKLvU6-Zw."
[2021-05-20T17:43:11Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:11.847Z] Information: Normalizing '_blazor' to 'http://127.0.0.1:53740/subdir/_blazor'."
[2021-05-20T17:43:11Z] [Info] http://127.0.0.1:53740/subdir 45:16 "Blazor server-side"
[2021-05-20T17:43:11Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:11.858Z] Information: WebSocket connected to ws://127.0.0.1:53740/subdir/_blazor?id=lGKaJXRkxbehTH-OHuXjuA."
[2021-05-20T17:43:12Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:12.550Z] Information: Normalizing '_blazor' to 'http://127.0.0.1:53740/subdir/_blazor'."
[2021-05-20T17:43:12Z] [Info] http://127.0.0.1:53740/subdir 45:16 "Blazor server-side"
[2021-05-20T17:43:12Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:12.555Z] Information: WebSocket connected to ws://127.0.0.1:53740/subdir/_blazor?id=0A8RrUTGcimbtnyTEXjGxg."
[2021-05-20T17:43:13Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:13.875Z] Information: Normalizing '_blazor' to 'http://127.0.0.1:53740/subdir/_blazor'."
[2021-05-20T17:43:13Z] [Info] http://127.0.0.1:53740/subdir 45:16 "Blazor server-side"
[2021-05-20T17:43:13Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:13.886Z] Information: WebSocket connected to ws://127.0.0.1:53740/subdir/_blazor?id=_wtlovhaiFrfnUB4giTE-A."
[2021-05-20T17:43:14Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:14.162Z] Information: Normalizing '_blazor' to 'http://127.0.0.1:53740/subdir/_blazor'."
[2021-05-20T17:43:14Z] [Info] http://127.0.0.1:53740/subdir 45:16 "Blazor server-side"
[2021-05-20T17:43:14Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:14.166Z] Information: WebSocket connected to ws://127.0.0.1:53740/subdir/_blazor?id=fdxizvQi8rQc1D1lpKNbWw."
[2021-05-20T17:43:14Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:14.563Z] Information: Normalizing '_blazor' to 'http://127.0.0.1:53740/subdir/_blazor'."
[2021-05-20T17:43:14Z] [Info] http://127.0.0.1:53740/subdir 45:16 "Blazor server-side"
[2021-05-20T17:43:14Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:14.570Z] Information: WebSocket connected to ws://127.0.0.1:53740/subdir/_blazor?id=iMUk08KjLcMjf0WiRVc5SQ."
[2021-05-20T17:43:14Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:14.814Z] Information: Normalizing '_blazor' to 'http://127.0.0.1:53740/subdir/_blazor'."
[2021-05-20T17:43:14Z] [Info] http://127.0.0.1:53740/subdir 45:16 "Blazor server-side"
[2021-05-20T17:43:14Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:14.820Z] Information: WebSocket connected to ws://127.0.0.1:53740/subdir/_blazor?id=im1X5FxplpuPRokZW8jQ3A."
[2021-05-20T17:43:15Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:15.032Z] Information: Normalizing '_blazor' to 'http://127.0.0.1:53740/subdir/_blazor'."
[2021-05-20T17:43:15Z] [Info] http://127.0.0.1:53740/subdir 45:16 "Blazor server-side"
[2021-05-20T17:43:15Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:15.036Z] Information: WebSocket connected to ws://127.0.0.1:53740/subdir/_blazor?id=3n2qxpO5481CpjAp0CEt8Q."
[2021-05-20T17:43:15Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:15.233Z] Information: Normalizing '_blazor' to 'http://127.0.0.1:53740/subdir/_blazor'."
[2021-05-20T17:43:15Z] [Info] http://127.0.0.1:53740/subdir 45:16 "Blazor server-side"
[2021-05-20T17:43:15Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:15.239Z] Information: WebSocket connected to ws://127.0.0.1:53740/subdir/_blazor?id=Yl9XCrAcbLuWA5PnXiSzDg."
[2021-05-20T17:43:15Z] [Severe] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:105474 "[2021-05-20T17:43:15.449Z] Error: There was an unhandled exception on the current circuit, so this circuit will be terminated. For more details turn on detailed exceptions by setting 'DetailedErrors: true' in 'appSettings.Development.json' or set 'CircuitOptions.DetailedErrors'. "
[2021-05-20T17:43:15Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "[2021-05-20T17:43:15.450Z] Information: Connection disconnected."Page content:
<head>
    <meta charset="utf-8">
    <title>Basic test app</title>
    <base href="/subdir/">
    <link href="style.css" rel="stylesheet">
    <link rel="icon" href="data:,">

    
    <link href="_content/TestContentPackage/styles.css" rel="stylesheet">
    <link href="Components.TestServer.styles.css" rel="stylesheet">
</head>
<body>
    <root><div id="test-selector">
    Select test:
    <select id="test-selector-select"><option value="none">Choose...
        <option value="BasicTestApp.AfterRenderInteropComponent">After-render interop component
        <option value="BasicTestApp.AuthTest.AuthRouter">Auth cases
        <option value="BasicTestApp.BindCasesComponent">bind cases
        <option value="BasicTestApp.ComponentRefComponent">Component ref component
        <option value="BasicTestApp.ConfigurationComponent">Configuration
        <option value="BasicTestApp.CounterComponent">Counter
        <option value="BasicTestApp.CounterComponentWrapper">Counter wrapped in parent
        <option value="BasicTestApp.DataDashComponent">data-* attribute rendering
        <option value="BasicTestApp.DuplicateAttributesComponent">Duplicate attributes
        <option value="BasicTestApp.ElementFocusComponent">Element focus component
        <option value="BasicTestApp.ErrorComponent">Error throwing
        <option value="BasicTestApp.EventBubblingComponent">Event bubbling
        <option value="BasicTestApp.EventCustomArgsComponent">Event custom arguments
        <option value="BasicTestApp.EventDuringBatchRendering">Event during batch rendering
        <option value="BasicTestApp.ExternalContentPackage">External content package
        <option value="BasicTestApp.FormsTest.InputFocusComponent">Input Focus
        <option value="BasicTestApp.FormsTest.SimpleValidationComponent">Simple validation
        <option value="BasicTestApp.FormsTest.TypicalValidationComponent">Typical validation
        <option value="BasicTestApp.FormsTest.InputFileComponent">Input file
        <option value="BasicTestApp.GlobalizationBindCases">Globalization Bind Cases
        <option value="BasicTestApp.HierarchicalImportsTest.Subdir.ComponentUsingImports">Imports statement
        <option value="BasicTestApp.HtmlEncodedChildContent">ChildContent HTML Encoded Block
        <option value="BasicTestApp.HttpClientTest.BinaryHttpRequestsComponent">Binary HttpClient tester
        <option value="BasicTestApp.HttpClientTest.HttpRequestsComponent">HttpClient tester
        <option value="BasicTestApp.InteropComponent">Interop component
        <option value="BasicTestApp.JsonSerializationCases">JSON serialization
        <option value="BasicTestApp.KeyPressEventComponent">Key press event
        <option value="BasicTestApp.LimitCounterComponent">Limit counter component
        <option value="BasicTestApp.LogicalElementInsertionCases">Logical element insertion cases
        <option value="BasicTestApp.LongRunningInterop">Long running interop
        <option value="BasicTestApp.MouseEventComponent">Mouse events
        <option value="BasicTestApp.MultipleChildContent">Multiple child content
        <option value="BasicTestApp.ParentChildComponent">Parent component with child
        <option value="Components.TestServer.ProtectedBrowserStorageUsageComponent, Components.TestServer, Version=42.42.42.42, Culture=neutral, PublicKeyToken=adb9793829ddae60">Protected browser storage usage
        <option value="BasicTestApp.RazorTemplates">Razor Templates
        <option value="BasicTestApp.RedTextComponent">Red text
        <option value="BasicTestApp.RenderFragmentToggler">Render fragment renderer
        <option value="BasicTestApp.ReorderingFocusComponent">Reordering focus retention
        <option value="BasicTestApp.RouterTest.TestRouter">Router
        <option value="BasicTestApp.RouterTest.TestRouterWithLazyAssembly">Router with dynamic assembly
        <option value="BasicTestApp.SelectVariantsComponent">Select with component options
        <option value="BasicTestApp.StringComparisonComponent">StringComparison
        <option value="BasicTestApp.TextOnlyComponent">Plain text
        <option value="BasicTestApp.TouchEventComponent">Touch events
        <option value="BasicTestApp.VirtualizationDataChanges">Virtualization data changes

Stacktrace

   at Microsoft.AspNetCore.E2ETesting.WaitAssert.WaitAssertCore[TResult](IWebDriver driver, Func`1 assertion, TimeSpan timeout) in /_/src/Shared/E2ETesting/WaitAssert.cs:line 129
   at Microsoft.AspNetCore.E2ETesting.WaitAssert.WaitAssertCore(IWebDriver driver, Action assertion, TimeSpan timeout) in /_/src/Shared/E2ETesting/WaitAssert.cs:line 84
   at Microsoft.AspNetCore.E2ETesting.WaitAssert.Equal[T](IWebDriver driver, T expected, Func`1 actual) in /_/src/Shared/E2ETesting/WaitAssert.cs:line 27
   at Microsoft.AspNetCore.Components.E2ETest.Tests.ComponentRenderingTest.CanFocusDuringOnAfterRenderAsyncWithFocusInEvent(String triggerButton) in /_/src/Components/test/E2ETest/Tests/ComponentRenderingTest.cs:line 461
----- Inner Stack Trace -----
   at Microsoft.AspNetCore.E2ETesting.WaitAssert.<>c__DisplayClass17_0.<WaitAssertCore>b__0() in /_/src/Shared/E2ETesting/WaitAssert.cs:line 83
   at Microsoft.AspNetCore.E2ETesting.WaitAssert.<>c__DisplayClass18_0`1.<WaitAssertCore>b__0(IWebDriver _) in /_/src/Shared/E2ETesting/WaitAssert.cs:line 109

Build

https://dev.azure.com/dnceng/public/_build/results?buildId=1148028&view=ms.vss-test-web.build-test-results-tab&runId=34741418&resultId=100506&paneView=debug

[SteveSandersonMS]

I was going to try to diagnose this but the info we capture is very limited:

[2021-05-20T17:43:15Z] [Severe] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:105474 "
[2021-05-20T17:43:15.449Z] Error: There was an unhandled exception on the current circuit, so this circuit will be terminated. For more details turn on detailed exceptions by setting 'DetailedErrors: true' in 'appSettings.Development.json' or set 'CircuitOptions.DetailedErrors'. "\r\n
[2021-05-20T17:43:15Z] [Info] http://127.0.0.1:53740/subdir/_framework/blazor.server.js 0:31762 "
[2021-05-20T17:43:15.450Z] Information: Connection disconnected

@HaoK Do you know of any reason why we'd deliberately not want to have detailed errors for the E2E tests in CI? I'll try to enable that if you think it's a good idea (or if you already know how to do that, feel free :) ).

[HaoK]

There's only some danger of making the logs super cluttered and impossible to read, which was some of the issues with the playwright debug:api logs that we currently see. Especially if the logs all get dumped into the console.

The ideal situation would be if each test dumped its logs into its own file, and then we can have super detailed logging enabled.

You could try rebasing the E2E tests against LoggedTest like the new PW test assembly does (https://github.com/dotnet/aspnetcore/blob/main/src/Components/test/E2ETestMigration/Infrastructure/PlaywrightTestBase.cs#L21), this would get the E2E tests the per file logging

[HaoK]

The logged test also should get you the server output logged which might be a 'free' perk that gets you more detailed logs

Thanks for contacting us.

We're moving this issue to the Next sprint planning milestone for future evaluation / consideration. We would like to keep this around to collect more feedback, which can help us with prioritizing this work. We will re-evaluate this issue, during our next planning meeting(s).
If we later determine, that the issue has no community involvement, or it's very rare and low-impact issue, we will close it - so that the team can focus on more important and high impact issues.
To learn more about what to expect next and how this issue will be handled you can read more about our triage process here.