[Android][Test Failure] System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded

[simonrozsival]

The test System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded which was introduced in #88893 is failing on Android.

Build Information

Build: https://dev.azure.com/dnceng-public/cbb18261-c48f-4abb-8651-8cdcb5474649/_build/results?buildId=346125
Build error leg or test failing: System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
Pull request: #89232

Error Message

Assert.Collection() Failure
Collection: [RecordedCounter { InstrumentName = http-client-current-requests, Value = 1, Tags = System.Collections.Generic.KeyValuePair`2[System.String,System.Object][] }, RecordedCounter { InstrumentName = http-client-current-requests, Value = -1, Tags = System.Collections.Generic.KeyValuePair`2[System.String,System.Object][] }, RecordedCounter { InstrumentName = http-client-request-duration, Value = 0.0130253, Tags = System.Collections.Generic.KeyValuePair`2[System.String,System.Object][] }]
Expected item count: 11
Actual item count:   3

Known Issue Error Message

{
  "ErrorMessage": "Assert.Collection() Failure",
  "BuildRetry": false,
  "ExcludeConsoleLog": false
}

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=346125
Error message validated: Assert.Collection() Failure
Result validation: ✅ Known issue matched with the provided build.
Validation performed at: 7/20/2023 1:42:43 PM UTC

Report

Build	Definition	Test	Pull Request
369565	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90304
369870	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89712
369604	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90150
369496	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
369466	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
369471	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90280
369160	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90199
368974	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90119
368875	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
368379	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90242
368237	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90234
368230	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90184
368204	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90225
367894	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90150
367870	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
367380	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
367235	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90119
366678	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89997
366629	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#87108
366404	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
366380	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
365849	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
365448	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89933
365200	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90023
365172	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
364964	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89548
364942	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
364831	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
364732	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
364492	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
364028	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
363818	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#87108
363584	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89997
363568	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#90023
363283	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
363106	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89994
362933	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89969
362691	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
362632	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89966
362411	dotnet/runtime	Workloads-NoWebcil-Wasm.Build.Tests.TestAppScenarios.LibraryInitializerTests.WorkItemExecution	#89857
362128	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89813
361928	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89922
361625	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89869
359419	dotnet/runtime	System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpRequestErrorTest_Http30.NameResolutionError	#89260
359097	dotnet/runtime	System.Net.Http.Functional.Tests.SocketsHttpHandler_HttpRequestErrorTest_Http11.NameResolutionError	#89260
356559	dotnet/runtime	Workloads-Wasm.Build.Tests.TestAppScenarios.SatelliteLoadingTests.WorkItemExecution	#89687
346125	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded	#89232
351937	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
351723	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
350271	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded
350226	dotnet/runtime	System.Net.Http.Functional.Tests.HttpMetricsTest_Http30.RequestDuration_EnrichmentHandler_Success_Recorded	#89397

Summary

24-Hour Hit Count	7-Day Hit Count	1-Month Count
0	0	51

[ghost]

Tagging subscribers to 'arch-android': @steveisok, @akoeplinger
See info in area-owners.md if you want to be subscribed.

Issue Details

---

The System.Net.Http.Functional.Tests.HttpMetricsTest_Http11_Async.AllSocketsHttpHandlerCounters_Success_Recorded test which was introduced in #88893 is failing on Android:

Assert.Collection() Failure
Collection: [RecordedCounter { InstrumentName = http-client-current-requests, Value = 1, Tags = System.Collections.Generic.KeyValuePair`2[System.String,System.Object][] }, RecordedCounter { InstrumentName = http-client-current-requests, Value = -1, Tags = System.Collections.Generic.KeyValuePair`2[System.String,System.Object][] }, RecordedCounter { InstrumentName = http-client-request-duration, Value = 0.0130253, Tags = System.Collections.Generic.KeyValuePair`2[System.String,System.Object][] }]
Expected item count: 11
Actual item count:   3

Example of a failed run in CI: https://dev.azure.com/dnceng-public/public/_build/results?buildId=346125&view=results

Author:	simonrozsival
Assignees:	-
Labels:	blocking-clean-ci, os-android
Milestone:	-

[antonfirsov]

The test can be disabled on Mobile, since SocketsHttpHandler.IsSupported doesn't mean it will be actually utilized by HttpClientHandler, and without that the failure is expected.

Alternatively, if we good SocketsHttpHandler test coverage on mobile around stuff like Metrics and Telemetry is something we care about, we can change the test to enforce the usage of SocketsHttpHandler, but I think we have a significant gap in that area anyways, eg. I assume everything in TelemetryTest is excluded from Mobile runs either because of OuterLoop or RemoteExecutor, otherwise the runs would fail. If we do care, maybe we should track this gap in a separate issue after disabling this particular test on mobile?

[mdh1418]

I ran the test locally on an Android arm64 emulator and device and it passed. I'm not able to reproduce the problem locally.

---

Metrics for failing instance

http.client.active_requests=1 [url.scheme=http, server.address=127.0.0.1, server.port=40663, http.request.method=GET],
http.client.active_requests=-1 [url.scheme=http, server.address=127.0.0.1, server.port=40663, http.request.method=GET],
http.client.request.duration=0.0156722 [url.scheme=http, server.address=127.0.0.1, server.port=40663, http.request.method=GET, http.response.status_code=200, network.protocol.version=1.1]

Metrics for passing instance locally

http.client.active_requests=1 [url.scheme=http, server.address=127.0.0.1, server.port=41781, http.request.method=GET]
http.client.open_connections=1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=idle]
http.client.request.time_in_queue=0.0914242 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, http.request.method=GET]
http.client.open_connections=-1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=idle]
http.client.open_connections=1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=active]
http.client.open_connections=-1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=active]
http.client.open_connections=1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=idle]
http.client.active_requests=-1 [url.scheme=http, server.address=127.0.0.1, server.port=41781, http.request.method=GET]
http.client.request.duration=0.2533807 [url.scheme=http, server.address=127.0.0.1, server.port=41781, http.request.method=GET, http.response.status_code=200, network.protocol.version=1.1]
http.client.connection.duration=0.148 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1]
http.client.open_connections=-1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=idle]

---

It looks like the failing instance doesn't have the following

http.client.open_connections=1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=idle]
http.client.request.time_in_queue=0.0914242 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, http.request.method=GET]
http.client.open_connections=-1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=idle]
http.client.open_connections=1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=active]
http.client.open_connections=-1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=active]
http.client.open_connections=1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=idle]
http.client.connection.duration=0.148 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1]
http.client.open_connections=-1 [network.protocol.version=1.1, url.scheme=http, server.address=127.0.0.1, server.port=41781, server.socket.address=::ffff:127.0.0.1, http.connection.state=idle]

Maybe its sometimes failing to establish a connection?
Wondering if this is flakey on CI or is it happening for all PRs that run the runtime-android lane

[simonrozsival]

This might have been fixed in #90298

[akoeplinger]

7-Day Hit Count is 0 now so assuming it was fixed by #90298