Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Quarantine VerifyCountersFireWithCorrectValues and EventCountersAndMetricsValues #57259

Open
halter73 opened this issue Aug 10, 2024 · 9 comments
Open

Quarantine VerifyCountersFireWithCorrectValues and EventCountersAndMetricsValues #57259

halter73 opened this issue Aug 10, 2024 · 9 comments
Labels
area-hosting Includes Hosting test-failure test-fixed
Milestone
.NET 10 Planning

Comments

@halter73
Copy link
Member

Failing Test(s)

  • Microsoft.AspNetCore.Hosting.Tests.HostingApplicationDiagnosticsTests.EventCountersAndMetricsValues
  • Microsoft.AspNetCore.Hosting.HostingEventSourceTests.VerifyCountersFireWithCorrectValues

Error Message

System.Threading.Tasks.TaskCanceledException : A task was canceled.

Stacktrace

   at System.Threading.Channels.ChannelReader`1.ReadAllAsync(CancellationToken cancellationToken)+MoveNext()
   at System.Threading.Channels.ChannelReader`1.ReadAllAsync(CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
   at System.Collections.Generic.AsyncEnumerableExtensions.FirstOrDefault[T](IAsyncEnumerator`1 values, Func`2 filter) in /_/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs:line 10
   at Microsoft.AspNetCore.Hosting.Tests.HostingApplicationDiagnosticsTests.EventCountersAndMetricsValues() in /_/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs:line 68
--- End of stack trace from previous location ---

   at System.Threading.Channels.ChannelReader`1.ReadAllAsync(CancellationToken cancellationToken)+MoveNext()
   at System.Threading.Channels.ChannelReader`1.ReadAllAsync(CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
   at System.Collections.Generic.AsyncEnumerableExtensions.FirstOrDefault[T](IAsyncEnumerator`1 values, Func`2 filter) in /_/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs:line 10
   at Microsoft.AspNetCore.Hosting.HostingEventSourceTests.VerifyCountersFireWithCorrectValues() in /_/src/Hosting/Hosting/test/Internal/HostingEventSourceTests.cs:line 207
--- End of stack trace from previous location ---

Logs

Build

https://dev.azure.com/dnceng-public/public/_build/results?buildId=771079&view=ms.vss-test-web.build-test-results-tab
https://dev.azure.com/dnceng-public/public/_build/results?buildId=771156&view=ms.vss-test-web.build-test-results-tab
https://dev.azure.com/dnceng-public/public/_build/results?buildId=771449&view=ms.vss-test-web.build-test-results-tab
https://dev.azure.com/dnceng-public/public/_build/results?buildId=769803&view=ms.vss-test-web.build-test-results-tab
@dotnet-issue-labeler dotnet-issue-labeler bot added the needs-area-label Used by the dotnet-issue-labeler to label those issues which couldn't be triaged automatically label Aug 10, 2024
@halter73
Copy link
Member Author

@JamesNK Do you know of any changes that might have affected Hosting's "requests-per-second", "total-requests", "current-requests", and/or "failed-requests" counters? Both of these tests verify those counters using the TestCounterListener.

@halter73 halter73 mentioned this issue Aug 10, 2024
Merged
@JamesNK
Copy link
Member

JamesNK commented Aug 11, 2024

No, I don't. There have been SignalR telemetry changes, but they're isolated to SignalR. And the Kestrel metrics connection improvement was merged a month ago.

It looks like errors started a few days ago:
image

There was a runtime update on that day. Related? #57060

@JamesNK JamesNK mentioned this issue Aug 11, 2024
Merged
@JamesNK
Copy link
Member

JamesNK commented Aug 11, 2024 •
edited
Loading

I looked at what VerifyCountersFireWithCorrectValues does and I'm sure the problem must be lower down. That test just verifies that HostingEventSource writes some event counters. That's it. And the code there hasn't changed in a year.

@tarekgh @noahfalk Have there been any changes in event counters recently?

@gfoidl gfoidl added area-hosting Includes Hosting and removed needs-area-label Used by the dotnet-issue-labeler to label those issues which couldn't be triaged automatically labels Aug 11, 2024
@tarekgh
Copy link
Member

tarekgh commented Aug 11, 2024

I am not touching event counters at all and not aware of any changes there. @noahfalk should know better here.

@noahfalk
Copy link
Member

This change merged recently and might be related - dotnet/runtime#105548

I suspect what happened is the test is making assumptions that both requests will land in the same measurement interval so that some counter event will get reported where Increment=2. Such an assumption has always been relying on a race condition and not guaranteed to be true, but prior to 105548 it was probably very likely. The requests just needed to finish in less than 1 second so that they wouldn't miss the first measurement interval. After change 105548 the start of the first measurement interval is also asynchronous so its now possible for the requests to run fast enough that they complete before the first measurement interval starts.

If that is the issue, a couple things that could make the test more timing resillient:

  • After enabling the events you could wait to receive at least one measurement event before running the requests you are trying to measure. This ensures they can't run prior to the first measurement interval.
  • Rather than looking for a single measurement with value 2, you could also accept any sequence of measurements that adds to 2. This allows the test to pass even if the requests happen to land in different measurement intervals.

@JamesNK
Copy link
Member

JamesNK commented Aug 11, 2024

That sounds like it. We can refactor the test to track increments across events.

This could affect more people. Although I doubt many people take the time to unit test counters.

@JamesNK
Copy link
Member

JamesNK commented Aug 12, 2024

PR with improvements: #57269

@noahfalk
Copy link
Member

This could affect more people. Although I doubt many people take the time to unit test counters.

Yeah, its a risk but I think a worthwhile one in order to fix the bug. I'm not aware of a good option that preserves the fix without also disrupting tests that were making implicit assumptions about the 1st callback being synchronous.

@noahfalk noahfalk mentioned this issue Aug 12, 2024
Closed
@MackinnonBuck MackinnonBuck added this to the .NET 10 Planning milestone Aug 13, 2024
halter73 added a commit that referenced this issue Sep 20, 2024
@halter73
Unquarantine #57259
efbbf3b
@halter73 halter73 mentioned this issue Sep 20, 2024
Merged
halter73 added a commit that referenced this issue Sep 20, 2024
@halter73
Revert "Unquarantine #57259"
bb76b9b 
This reverts commit efbbf3b.
@halter73
Copy link
Member Author

halter73 commented Sep 20, 2024 •
edited
Loading

It looks like this is still failing, but with a different error.

Failing Test(s)

  • Microsoft.AspNetCore.Hosting.Tests.HostingApplicationDiagnosticsTests.EventCountersAndMetricsValues
  • Microsoft.AspNetCore.Hosting.HostingEventSourceTests.VerifyCountersFireWithCorrectValues

Error Message

System.InvalidOperationException : Results ended with final value of 0. Expected value of 2.
---- System.OperationCanceledException : The operation was canceled.

Stacktrace

   at System.Collections.Generic.AsyncEnumerableExtensions.WaitForValueAsync[T](IAsyncEnumerator`1 values, T expectedValue) in /_/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs:line 28
   at Microsoft.AspNetCore.Hosting.Tests.HostingApplicationDiagnosticsTests.EventCountersAndMetricsValues() in /_/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs:line 70
--- End of stack trace from previous location ---
----- Inner Stack Trace -----
   at System.Threading.Channels.AsyncOperation`1.GetResult(Int16 token)
   at System.Threading.Channels.ChannelReader`1.ReadAllAsync(CancellationToken cancellationToken)+MoveNext()
   at System.Threading.Channels.ChannelReader`1.ReadAllAsync(CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
   at System.Collections.Generic.AsyncEnumerableExtensions.WaitForValueAsync[T](IAsyncEnumerator`1 values, T expectedValue) in /_/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs:line 15

Logs

| [0.001s] TestLifetime Information: Starting test EventCountersAndMetricsValues at 2024-09-20T02:04:10
| [0.090s] Microsoft.AspNetCore.Hosting.HostingApplication Information: Request starting   :// - - -
| [0.133s] Microsoft.AspNetCore.Hosting.HostingApplication Information: Request starting   :// - - -
| [1.045s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 1.
| [1.047s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [1.048s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [1.048s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [2.041s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [2.041s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [2.041s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [2.041s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [3.039s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [3.103s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [3.103s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [3.103s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [4.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [4.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [4.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [4.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [5.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [5.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [5.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [5.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [6.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [6.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [6.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [6.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [7.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [7.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [7.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [7.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [8.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [8.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [8.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [8.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [9.043s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [9.044s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [9.044s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [9.044s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [10.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [10.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [10.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [10.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [11.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [11.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [11.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [11.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [12.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [12.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [12.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [12.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [13.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [13.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [13.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [13.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [14.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [14.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [14.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [14.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [15.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [15.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [15.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [15.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [16.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [16.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [16.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [16.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [17.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [17.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [17.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [17.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [18.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [18.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [18.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [18.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [19.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [19.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [19.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [19.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [20.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [20.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [20.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [20.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [21.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [21.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [21.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [21.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [22.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [22.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [22.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [22.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [23.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [23.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [23.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [23.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [24.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [24.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [24.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [24.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [25.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [25.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [25.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [25.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [26.038s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [26.049s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [26.049s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [26.049s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [27.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [27.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [27.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [27.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [28.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [28.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [28.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [28.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [29.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter requests-per-second on event source d0363820-dca7-4224-a2fc-0239c0655101 has increment value 0.
| [29.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter total-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [29.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter current-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 2.
| [29.037s] Microsoft.AspNetCore.Internal.TestCounterListener Debug: Counter failed-requests on event source d0363820-dca7-4224-a2fc-0239c0655101 has mean value 0.
| [30.017s] Microsoft.AspNetCore.Hosting.Tests.HostingApplicationDiagnosticsTests Error: Timeout while waiting for counter value.
| [30.032s] Microsoft.AspNetCore.Hosting.Tests.HostingApplicationDiagnosticsTests Error: Test threw an exception.
| System.InvalidOperationException: Results ended with final value of 0. Expected value of 2.
|  ---> System.OperationCanceledException: The operation was canceled.
|    at System.Threading.Channels.AsyncOperation`1.GetResult(Int16 token)
|    at System.Threading.Channels.ChannelReader`1.ReadAllAsync(CancellationToken cancellationToken)+MoveNext()
|    at System.Threading.Channels.ChannelReader`1.ReadAllAsync(CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
|    at System.Collections.Generic.AsyncEnumerableExtensions.WaitForValueAsync[T](IAsyncEnumerator`1 values, T expectedValue) in /_/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs:line 15
|    --- End of inner exception stack trace ---
|    at System.Collections.Generic.AsyncEnumerableExtensions.WaitForValueAsync[T](IAsyncEnumerator`1 values, T expectedValue) in /_/src/Hosting/Hosting/test/Internal/AsyncEnumerableExtensions.cs:line 28
|    at Microsoft.AspNetCore.Hosting.Tests.HostingApplicationDiagnosticsTests.EventCountersAndMetricsValues() in /_/src/Hosting/Hosting/test/HostingApplicationDiagnosticsTests.cs:line 70
|    at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass46_0.<<InvokeTestMethodAsync>b__1>d.MoveNext() in /_/src/xunit.execution/Sdk/Frameworks/Runners/TestInvoker.cs:line 253
| --- End of stack trace from previous location ---
|    at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in /_/src/xunit.execution/Sdk/Frameworks/ExecutionTimer.cs:line 48
|    at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in /_/src/xunit.core/Sdk/ExceptionAggregator.cs:line 90
| [30.033s] TestLifetime Information: Finished test EventCountersAndMetricsValues in 30.0326479s

Build

https://dev.azure.com/dnceng-public/public/_build/results?buildId=813688&view=ms.vss-test-web.build-test-results-tab&runId=21083514&resultId=105563&paneView=attachments

@JamesNK JamesNK mentioned this issue Dec 10, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area-hosting Includes Hosting test-failure test-fixed
Projects
None yet
Milestone
.NET 10 Planning
Development

No branches or pull requests
6 participants
@halter73 @JamesNK @gfoidl @noahfalk @MackinnonBuck @tarekgh