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

Test Failure System.Net.Http.Functional.Tests.TelemetryTest_Http20.EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue #46073

Closed
ManickaP opened this issue Dec 15, 2020 · 9 comments · Fixed by #50226 or #55729
Closed

Test Failure System.Net.Http.Functional.Tests.TelemetryTest_Http20.EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue #46073

ManickaP opened this issue Dec 15, 2020 · 9 comments · Fixed by #50226 or #55729
Assignees
@alnikola
Labels
area-System.Net.Http test-bug Problem in test source code (most likely) test-run-core Test failures in .NET Core test runs
Milestone
6.0.0

Comments

@ManickaP
Copy link
Member

failed again in job: runtime-libraries-coreclr outerloop 20201214.1

failed test: System.Net.Http.Functional.Tests.TelemetryTest_Http20.EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue

net6.0-OSX-Release-x64-CoreCLR_release-OSX.1014.Amd64.Open

Error message

Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Remote process failed with an unhandled exception.


Stack trace

Child exception:
  Xunit.Sdk.EqualException: Assert.Equal() Failure
Expected: 0
Actual:   154.1219
   at System.Net.Http.Functional.Tests.TelemetryTest.VerifyEventCounters(ConcurrentQueue`1 events, Int32 requestCount, Boolean shouldHaveFailures, Int32 requestsLeftQueueVersion) in /_/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs:line 537
   at System.Net.Http.Functional.Tests.TelemetryTest.<>c.<<EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue>b__10_0>d.MoveNext() in /_/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs:line 641
--- End of stack trace from previous location ---
   at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 65

Child process:
  System.Net.Http.Functional.Tests, Version=6.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51 System.Net.Http.Functional.Tests.TelemetryTest+<>c System.Threading.Tasks.Task <EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue>b__10_0(System.String)

Child arguments:
  2.0

Originally posted by @v-haren in #41723 (comment)
@Dotnet-GitSync-Bot Dotnet-GitSync-Bot added area-System.Net.Http untriaged New issue has not been triaged by the area owner labels Dec 15, 2020
@ghost
Copy link

ghost commented Dec 15, 2020

Tagging subscribers to this area: @dotnet/ncl
See info in area-owners.md if you want to be subscribed.

Issue Details

failed again in job: runtime-libraries-coreclr outerloop 20201214.1

failed test: System.Net.Http.Functional.Tests.TelemetryTest_Http20.EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue

net6.0-OSX-Release-x64-CoreCLR_release-OSX.1014.Amd64.Open

Error message

Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Remote process failed with an unhandled exception.


Stack trace

Child exception:
  Xunit.Sdk.EqualException: Assert.Equal() Failure
Expected: 0
Actual:   154.1219
   at System.Net.Http.Functional.Tests.TelemetryTest.VerifyEventCounters(ConcurrentQueue`1 events, Int32 requestCount, Boolean shouldHaveFailures, Int32 requestsLeftQueueVersion) in /_/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs:line 537
   at System.Net.Http.Functional.Tests.TelemetryTest.<>c.<<EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue>b__10_0>d.MoveNext() in /_/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs:line 641
--- End of stack trace from previous location ---
   at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 65

Child process:
  System.Net.Http.Functional.Tests, Version=6.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51 System.Net.Http.Functional.Tests.TelemetryTest+<>c System.Threading.Tasks.Task <EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue>b__10_0(System.String)

Child arguments:
  2.0

Originally posted by @v-haren in #41723 (comment)

Author: ManickaP
Assignees: -
Labels:

area-System.Net.Http, untriaged
Milestone: -

@MihaZupan MihaZupan added the test-bug Problem in test source code (most likely) label Dec 15, 2020
@MihaZupan MihaZupan added this to the 6.0.0 milestone Dec 15, 2020
@MihaZupan MihaZupan removed the untriaged New issue has not been triaged by the area owner label Dec 15, 2020
@VincentBu
Copy link
Contributor

Failed again in run runtime-libraries-coreclr outerloop 20210209.3

Failed test:

net6.0-OSX-Release-x64-CoreCLR_release-OSX.1015.Amd64.Open
 -System.Net.Http.Functional.Tests.TelemetryTest_Http20.EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue

Error message:

Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Remote process failed with an unhandled exception.


Stack trace

Child exception:
  Xunit.Sdk.EqualException: Assert.Equal() Failure
Expected: 0
Actual:   103.9025
   at System.Net.Http.Functional.Tests.TelemetryTest.VerifyEventCounters(ConcurrentQueue`1 events, Int32 requestCount, Boolean shouldHaveFailures, Int32 requestsLeftQueueVersion) in /_/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs:line 537
   at System.Net.Http.Functional.Tests.TelemetryTest.<>c.<<EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue>b__10_0>d.MoveNext() in /_/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs:line 641
--- End of stack trace from previous location ---
   at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 65

Child process:
  System.Net.Http.Functional.Tests, Version=6.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51 System.Net.Http.Functional.Tests.TelemetryTest+<>c System.Threading.Tasks.Task <EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue>b__10_0(System.String)

Child arguments:
  2.0

@VincentBu
Copy link
Contributor

Failed again in runtime-libraries-coreclr outerloop 20210324.3

Failed test:

net6.0-OSX-Release-arm64-CoreCLR_release-OSX.1100.ARM64.Open
 -System.Net.Http.Functional.Tests.TelemetryTest_Http20.EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue

Error message:

Microsoft.DotNet.RemoteExecutor.RemoteExecutionException : Remote process failed with an unhandled exception.


Stack trace

Child exception:
  Xunit.Sdk.EqualException: Assert.Equal() Failure
Expected: 0
Actual:   174.9862
   at System.Net.Http.Functional.Tests.TelemetryTest.VerifyEventCounters(ConcurrentQueue`1 events, Int32 requestCount, Boolean shouldHaveFailures, Int32 requestsLeftQueueVersion) in /_/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs:line 537
   at System.Net.Http.Functional.Tests.TelemetryTest.<>c.<<EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue>b__10_0>d.MoveNext() in /_/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs:line 641
--- End of stack trace from previous location ---
   at Microsoft.DotNet.RemoteExecutor.Program.Main(String[] args) in /_/src/Microsoft.DotNet.RemoteExecutor/src/Program.cs:line 65

Child process:
  System.Net.Http.Functional.Tests, Version=6.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51 System.Net.Http.Functional.Tests.TelemetryTest+<>c System.Threading.Tasks.Task <EventSource_ConnectionPoolAtMaxConnections_LogsRequestLeftQueue>b__10_0(System.String)

Child arguments:
  2.0

This was referenced Mar 25, 2021
Closed
Merged
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Mar 25, 2021
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Apr 6, 2021
@VincentBu

This comment has been minimized.

Sign in to view
@VincentBu

This comment has been minimized.

Sign in to view
@karelz karelz mentioned this issue May 10, 2021
Closed
@karelz
Copy link
Member

karelz commented May 10, 2021 •
edited
Loading

This issue is still happening after PR #50226 (merged on 4/6), but only in PRs (during 3/11-4/6 the failures were in official builds only).
Note that a new test failure started after the PR was merged: #52530

Failures 4/7-6/25 (incl. PRs):

Date Build / PR HTTP OS
4/8 PR #48758 Http11 OSX.1015.Amd64.Open
4/13 PR #48758 Http20 OSX.1014.Amd64.Open
4/16 PR #51205 Http11 Ubuntu.1804.Amd64.Open
4/18 PR #51213 Http11 OSX.1014.Amd64.Open
4/18 PR #51212 Http11 OSX.1100.ARM64.Open
4/18 PR #51454 Http11 OSX.1100.ARM64.Open
5/3 PR #52178 Http11 OSX.1014.Amd64.Open
5/7 PR #52178 Http20 OSX.1014.Amd64.Open
5/7 PR #52178 Http20 OSX.1014.Amd64.Open
5/7 PR #52178 Http11 OSX.1014.Amd64.Open
5/7 PR #52178 Http20 OSX.1014.Amd64.Open
5/7 PR #52240 Http11 OSX.1014.Amd64.Open
5/7 PR #52240 Http20 Alpine.312.Amd64.Open
5/9 Official run Http11 Debian.9.Arm32.Open
5/10 Official run Http20 Alpine.312.Arm64.Open
5/10 Official run Http20 Ubuntu.1804.ArmArch.Open
5/15 PR #52797 Http11 OSX.1014.Amd64.Open
5/15 Official run Http20 Ubuntu.1910.Amd64.Open
5/17 PR #51094 Http20 OSX.1015.Amd64.Open
5/25 PR #51440 Http20 OSX.1100.ARM64.Open
6/8 PR #52202 Http11 OSX.1015.Amd64.Open

@MihaZupan should we reopen it or open a new issue, or do you think the PRs caused the failures?

@antonfirsov
Copy link
Member

antonfirsov commented May 17, 2021 •
edited by karelz
Loading

Hit in PR #51094

@MihaZupan
Copy link
Member

This specific issue is only appearing on OSX (non OSX failures are on release/preview branches that do not have changes from #50226).

We can disable the test on OSX, though I don't see a reason as to why it would be failing in this manner.

@MihaZupan MihaZupan reopened this May 18, 2021
@karelz
Copy link
Member

karelz commented May 18, 2021

@MihaZupan one of the failures in the table is on Ubuntu ...

@karelz karelz added the test-run-core Test failures in .NET Core test runs label Jun 25, 2021
@alnikola alnikola self-assigned this Jul 13, 2021
alnikola added a commit that referenced this issue Jul 15, 2021
@alnikola
Mitigate race condition in EventSource_ConnectionPoolAtMaxConnections…
2700b1c 
…_LogsRequestLeftQueue test

There is a unavoidable race condition between updating event counters and reading their values in WaitForEventCountersAsync. It waits for at least 2 sets of EventCounter event groups to ensure the last group is captured after any actual work (tests check that counters reset back to 0 if there is nothing happening).
Since it looks for `requests-started` which occurs before `http11-requests-queue-duration` event, what it may see is only the tail of the last group and the start of the second, without waiting for a fresh `http11-requests-queue-duration`. In this, the assert `Assert.Equal(0, http11requestQueueDurations[^1])` on the line 549 will see a non-zero counter value and fail.

This PR changes the condition to `< 3`  to guarantee there is at least one full group of events in the window.

Co-authored by @MihaZupan 

Fixes #46073
@alnikola alnikola mentioned this issue Jul 15, 2021
Merged
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Jul 15, 2021
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Jul 16, 2021
alnikola added a commit that referenced this issue Jul 16, 2021
@alnikola
Mitigate race condition in EventSource_ConnectionPoolAtMaxConnections…
3cdc4dd 
…_LogsRequestLeftQueue test (#55729)

There is a unavoidable race condition between updating event counters and reading their values in WaitForEventCountersAsync. It waits for at least 2 sets of EventCounter event groups to ensure the last group is captured after any actual work (tests check that counters reset back to 0 if there is nothing happening).
Since it looks for `requests-started` which occurs before `http11-requests-queue-duration` event, what it may see is only the tail of the last group and the start of the second, without waiting for a fresh `http11-requests-queue-duration`. In this, the assert `Assert.Equal(0, http11requestQueueDurations[^1])` on the line 549 will see a non-zero counter value and fail.

This PR changes the condition to `< 3`  to guarantee there is at least one full group of events in the window.

Co-authored by @MihaZupan 

Fixes #46073
@MihaZupan MihaZupan mentioned this issue Jul 19, 2021
Closed
@ghost ghost locked as resolved and limited conversation to collaborators Aug 15, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@alnikola alnikola

Labels
area-System.Net.Http test-bug Problem in test source code (most likely) test-run-core Test failures in .NET Core test runs
Projects
None yet
Milestone
6.0.0
7 participants
@karelz @antonfirsov @ManickaP @MihaZupan @VincentBu @Dotnet-GitSync-Bot @alnikola