System.Net.Http.Functional.Tests.HttpMetricsTest_Http20.AllSocketsHttpHandlerCounters_Success_Recorded item comparison failure

[MichalStrehovsky]

 System.Net.Http.Functional.Tests.HttpMetricsTest_Http20.AllSocketsHttpHandlerCounters_Success_Recorded [FAIL]
 Assert.Collection() Failure: Item comparison failure
 ↓ (pos 9)
 Collection: [···, http.client.active_requests=-1 [url.scheme=https, server.address=127.0.0.1, server.port=39899, http.request.method=GET], http.client.request.duration=0.0346855 [url.scheme=https, server.address=127.0.0.1, server.port=39899, http.request.method=GET, http.response.status_code=200, network.protocol.version=2], http.client.open_connections=-1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=idle], http.client.open_connections=1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=active], http.client.open_connections=-1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=active], ···]
 Error: Assert.Equal() Failure: Strings differ
 ↓ (pos 12)
 Expected: "http.client.connection.duration"
 Actual: "http.client.open_connections"
 ↑ (pos 12)
 Stack Trace:
 /_/src/libraries/System.Net.Http/tests/FunctionalTests/MetricsTest.cs(624,0): at System.Net.Http.Functional.Tests.HttpMetricsTest.<>c__DisplayClass19_0.<<AllSocketsHttpHandlerCounters_Success_Recorded>b__0>d.MoveNext()
 --- End of stack trace from previous location ---
 /_/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(120,0): at System.Threading.Tasks.TaskTimeoutExtensions.GetRealException(Task task)
 --- End of stack trace from previous location ---
 /_/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(90,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)
 /_/src/libraries/Common/tests/System/Net/Http/GenericLoopbackServer.cs(44,0): at System.Net.Test.Common.LoopbackServerFactory.<>c__DisplayClass6_0.<<CreateClientAndServerAsync>b__0>d.MoveNext()
 --- End of stack trace from previous location ---
 /_/src/libraries/Common/tests/System/Net/Http/Http2LoopbackServer.cs(235,0): at System.Net.Test.Common.Http2LoopbackServerFactory.CreateServerAsync(Func`3 funcAsync, Int32 millisecondsTimeout, GenericLoopbackOptions options)
 /_/src/libraries/System.Net.Http/tests/FunctionalTests/MetricsTest.cs(581,0): at System.Net.Http.Functional.Tests.HttpMetricsTest.AllSocketsHttpHandlerCounters_Success_Recorded()
 --- End of stack trace from previous location ---
 Output:
 http.client.active_requests=1 [url.scheme=https, server.address=127.0.0.1, server.port=39899, http.request.method=GET]
 http.client.open_connections=1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=idle]
 http.client.open_connections=-1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=idle]
 http.client.open_connections=1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=active]
 http.client.request.time_in_queue=0.0337241 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, http.request.method=GET]
 http.client.open_connections=-1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=active]
 http.client.open_connections=1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=idle]
 http.client.active_requests=-1 [url.scheme=https, server.address=127.0.0.1, server.port=39899, http.request.method=GET]
 http.client.request.duration=0.0346855 [url.scheme=https, server.address=127.0.0.1, server.port=39899, http.request.method=GET, http.response.status_code=200, network.protocol.version=2]
 http.client.open_connections=-1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=idle]
 http.client.open_connections=1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=active]
 http.client.open_connections=-1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=active]
 http.client.open_connections=1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=idle]
 http.client.connection.duration=0.016 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1]
 http.client.open_connections=-1 [network.protocol.version=2, url.scheme=https, server.address=127.0.0.1, server.port=39899, network.peer.address=::ffff:127.0.0.1, http.connection.state=idle]

Build Information

Build: https://dev.azure.com/dnceng-public/public/_build/results?buildId=726853
Build error leg or test failing: Build / Libraries Test Run release coreclr linux x64 Debug / Send to Helix
Pull request: #101229

Error Message

Fill the error message using step by step known issues guidance.

{
 "ErrorMessage": "",
 "ErrorPattern": "Expected:.*http.client.connection.duration",
 "BuildRetry": false,
 "ExcludeConsoleLog": false
}

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=649095
Error message validated: [Expected:.*http.client.connection.duration]
Result validation: ❌ Known issue did not match with the provided build.
Validation performed at: 4/19/2024 11:22:20 AM UTC

Report

Build	Definition	Test	Pull Request
763965	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http20.AllSocketsHttpHandlerCounters_Success_Recorded	#105866
731726	dotnet/runtime	System.Net.Http.Functional.Tests.SyncHttpHandler_DiagnosticsTest.SendAsync_Success_ConnectionActivityRecordedWithChildren	#103922

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
1	1	2

[dotnet-policy-service]

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

[liveans]

My inital guess related to this is:

runtime/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs

Lines 304 to 306 in 72d00a8

	// Can be called by the HttpConnectionPool after TryReserveStream if the stream doesn't end up being used.
	// Otherwise, will be called when the request is complete and stream is closed.
	public void ReleaseStream()

First comment is happening, just before Shutdown. I'm not sure if this is expected behavior but looks like this is happening when we're trying to return Http2Connection to the pool. If this is expected in some cases, fix should be straightforward for the test.

/cc @MihaZupan

[MihaZupan]

You're right about the cause here being the TryReserve/Release as part of returning the connection.

But IMO this is a product issue that we're emitting not idle + idle as part of connection pooling even though there are no requests. We should likely change our logic here to behave closer to H3, where we emit non-idle only as part of SendAsync instead of TryReserveStream:

runtime/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http3Connection.cs

Lines 262 to 265 in e60db07

	if (_activeRequests.Count == 0)
	{
	MarkConnectionAsNotIdle();
	}