[Test Failure] System.Net.Http.WinHttpHandlerFunctional.Tests.WinHttpHandlerTest.SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException

[rzikm]

Build Information

Build: https://dev.azure.com/dnceng-public/public/_build/results?buildId=715461
Build error leg or test failing: System.Net.Http.WinHttpHandlerFunctional.Tests.WinHttpHandlerTest.SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException

Error Message

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

{
  "ErrorMessage": [ "System.Net.Http.WinHttpHandlerFunctional.Tests.WinHttpHandlerTest.SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException [FAIL]", "Error 12152 calling WINHTTP_CALLBACK_STATUS_REQUEST_ERROR"],
  "BuildRetry": false,
  "ExcludeConsoleLog": false
}

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=715461
Error message validated: [System.Net.Http.WinHttpHandlerFunctional.Tests.WinHttpHandlerTest.SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException [FAIL] Error 12152 calling WINHTTP_CALLBACK_STATUS_REQUEST_ERROR]
Result validation: ✅ Known issue matched with the provided build.
Validation performed at: 6/25/2024 3:32:56 PM UTC

Report

Build	Definition	Test	Pull Request
715461	dotnet/runtime	System.Net.Http.WinHttpHandlerFunctional.Tests.WinHttpHandlerTest.SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException

Summary

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

[ghost]

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

Issue Details

---

Build Information

Build: https://dev.azure.com/dnceng-public/public/_build/results?buildId=510958
Build error leg or test failing: System.Net.Http.WinHttpHandlerFunctional.Tests.WinHttpHandlerTest.SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException

Error Message

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

{
  "ErrorMessage": "System.Net.Http.WinHttpHandlerFunctional.Tests.WinHttpHandlerTest.SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException [FAIL]",
  "BuildRetry": false,
  "ExcludeConsoleLog": false
}

Author:	rzikm
Assignees:	-
Labels:	area-System.Net.Http, blocking-clean-ci, untriaged, Known Build Error
Milestone:	-

[rzikm]

The known issue does not seem to get matched, but it should IMO.

The failure log can be found via

https://dev.azure.com/dnceng-public/public/_build/results?buildId=511527&view=logs&j=2686528b-6bb9-52cf-c87c-9a2bbdff7996&t=5c32730d-9d2b-5d94-bfff-01026160003a

Sent Helix Job; see work items at https://helix.dot.net/api/jobs/cfed76aa-4fff-41c4-bd4c-e2fff1898339/workitems?api-version=2019-06-17

    {
        "DetailsUrl": "https://helix.dot.net/api/jobs/cfed76aa-4fff-41c4-bd4c-e2fff1898339/workitems/System.Net.Http.WinHttpHandler.Functional.Tests?api-version=2019-06-17",
        "Job": "cfed76aa-4fff-41c4-bd4c-e2fff1898339",
        "Name": "System.Net.Http.WinHttpHandler.Functional.Tests",
        "State": "Finished"
    },

In the DetailsUrl, there is

"ConsoleOutputUri": "https://helixre107v0xdcypoyl9e7f.blob.core.windows.net/dotnet-runtime-refs-heads-main-cfed76aa4fff41c4bd/System.Net.Http.WinHttpHandler.Functional.Tests/3/console.2f0f7f31.log?helixlogtype=result",

which contains the failure.

@dotnet/dnceng does the Known Issues infrastructure fall under your team? Can you please take a look? If not, do you know who maintains the Known Issues?

[ilyas1974]

@AlitzelMendez can you take a look at this, please?

[AlitzelMendez]

Hi @rzikm,
Could you please share with me to which test is that log entitled?

For context, for known issues we review two things:

• the build logs
• the tests reported to azdo (including the helix logs of those tests)

the first link that you shared for the build doesn't have the error: https://dev.azure.com/dnceng-public/public/_build/results?buildId=511527&view=logs&j=2686528b-6bb9-52cf-c87c-9a2bbdff7996&t=5c32730d-9d2b-5d94-bfff-01026160003a

and the second link doesn't seem to be entitled to any test reported to azdo, when I mention test I am referring to the ones in this tab: https://dev.azure.com/dnceng-public/public/_build/results?buildId=511527&view=ms.vss-test-web.build-test-results-tab

Additionally if your link is just mentioned in the build log or any log, we don't parse that log looking for links pointing to other logs, we just analyze the log as a text comparing it with the error message.

[rzikm]

Hi @rzikm, Could you please share with me to which test is that log entitled?

The test is System.Net.Http.WinHttpHandlerFunctional.Tests.WinHttpHandlerTest.SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException

For context, for known issues we review two things:

• the build logs
• the tests reported to azdo (including the helix logs of those tests)

the first link that you shared for the build doesn't have the error: https://dev.azure.com/dnceng-public/public/_build/results?buildId=511527&view=logs&j=2686528b-6bb9-52cf-c87c-9a2bbdff7996&t=5c32730d-9d2b-5d94-bfff-01026160003a

and the second link doesn't seem to be entitled to any test reported to azdo, when I mention test I am referring to the ones in this tab: https://dev.azure.com/dnceng-public/public/_build/results?buildId=511527&view=ms.vss-test-web.build-test-results-tab

Additionally if your link is just mentioned in the build log or any log, we don't parse that log looking for links pointing to other logs, we just analyze the log as a text comparing it with the error message.

Let's have a look at it from a different perspective. I am monitoring frequently failing tests using the cluster('engsrvprod.kusto.windows.net').database('engineeringdata').AzureDevOpsTests table. Following query

Kusto Query

cluster('engsrvprod.kusto.windows.net').database('engineeringdata').AzureDevOpsTests
    | where TestName has 'SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException'
    | where Outcome == 'Failed' // or Outcome == 'PassedOnRerun'
    | distinct JobId, WorkItemId, Message, StackTrace, TestName, Arguments, Outcome
    | join kind=inner (cluster('engsrvprod.kusto.windows.net').database('engineeringdata').Jobs
        | where Finished > now(-14d)
        | extend TargetBranch = extractjson("$.['System.PullRequest.TargetBranch']", Properties)
        | where (Branch == 'refs/heads/main') or (Source startswith "pr/" and TargetBranch == 'main')
        | summarize arg_max(JobName=Name, Finished, Properties, Type, Branch, Source, Started, QueueName, Attempt, Build, TargetBranch) by JobId
    | project-rename JobType = Type) on JobId
    | extend PropertiesJson = parse_json(Properties)
    | extend OS = replace_regex(tostring(PropertiesJson.operatingSystem), @'\((.*)\).*|([^\(].*)', @'\1\2')
    | extend Runtime = iif(PropertiesJson.runtimeFlavor == "mono", "Mono", iif(PropertiesJson.DefinitionName contains "coreclr", "CoreCLR", "")) 
    | extend Architecture = PropertiesJson.architecture
    | extend DefinitionName = PropertiesJson.DefinitionName
    | project-away JobId
    | extend BuildId = extractjson("$.['BuildId']", Properties)
    | join kind=inner (cluster('engsrvprod.kusto.windows.net').database('engineeringdata').WorkItems
        | project-keep ConsoleUri, WorkItemId) on WorkItemId
    | project-away PropertiesJson
    | project-reorder Started, TestName, ConsoleUri, BuildId, JobName, OS, Architecture, DefinitionName, Branch, TargetBranch, Attempt, Build//, * 
;

The query returns, among others, failures occuring connected to build 511527

The associated Console output link is https://helixre107v0xdcypoyl9e7f.blob.core.windows.net/dotnet-runtime-refs-heads-main-cfed76aa4fff41c4bd/System.Net.Http.WinHttpHandler.Functional.Tests/3/console.2f0f7f31.log?helixlogtype=result and the associated failure is indeed mentioned in the output

System.Net.Http.WinHttpHandlerFunctional.Tests.WinHttpHandlerTest.SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException [FAIL]
      Assert.IsType() Failure: Value is not the exact type
      Expected: typeof(System.IO.IOException)
      Actual:   typeof(System.Net.Http.WinHttpException)

So my assumption is that if I file a Known Build error against this build and test, it should match correctly. Or am I missing something?

[CarnaViire]

Triage: this is an Outerloop test that fails quite regularly for Windows.Nano.1809.Amd64.Open (I've also seen one occurrence for Windows.Amd64.Server2022.Open on 2023-10-11).

17 failures in the past 30 days (2023-12-06 to 2024-01-05).
First occurrence on 2023-10-07.

We need to investigate in 9.0.

[AlitzelMendez]

could you please share with me a link to the test in AzDO?

as I mentioned it needs to be a test that appears on the AzDO tab, we don't parse the log, so if it is just mentioned and not reported back to AzDO we will not review it

we don't pull the test (helix work items) for our kusto tables, we ask AzDO to return all the tests ran in that build, AzDO returns all the test that are on https://dev.azure.com/dnceng-public/public/_build/results?buildId=511527&view=ms.vss-test-web.build-test-results-tab and we analyze those tests, if the test is not in there we won't analyze that log

[rzikm]

I see, AzDO seems to report entire work items as failed and not individual failed tests. I think we have recently run into this similar issue in #95898 (comment). @carlossanlop Could this be the same problem?

[rzikm]

@AlitzelMendez, I have taken another look and it seems to me that the test failure is actually reported in AzDO

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

Can you please take a look? I am also seeing the same in #96689

[AlitzelMendez]

Hi @rzikm,
I apologize for not noticing this before, but the problems is that your build has a lot of test failures , we have some limitation about this numbers as it would be too expensive for analyze builds with so many failures, you can look into this in our doc: https://github.com/dotnet/arcade/blob/8ee200d3932bf770a6a5b6a76ee630c8e559530d/Documentation/Projects/Build%20Analysis/KnownIssues.md?plain=1#L88

[jeffschwMSFT]

removing blocking-clean-ci due to not failing for 30 days

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

[rzikm]

The actual exception seems to be

 ex: System.Net.Http.HttpRequestException: An error occurred while sending the request.
         ---> System.Net.Http.WinHttpException (80072F78, 12152): Error 12152 calling WINHTTP_CALLBACK_STATUS_REQUEST_ERROR, 'The server returned an invalid or unrecognized response'.
           at System.Net.Http.WinHttpHandler.StartRequestAsync(WinHttpRequestState state) in /_/src/libraries/System.Net.Http.WinHttpHandler/src/System/Net/Http/WinHttpHandler.cs:line 942
           --- End of inner exception stack trace ---
           at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs:line 530
           at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs:line 550
           at System.Net.Http.WinHttpHandlerFunctional.Tests.WinHttpHandlerTest.<>c__DisplayClass6_1.<<SendAsync_SlowServerRespondsAfterDefaultReceiveTimeout_ThrowsHttpRequestException>b__2>d.MoveNext() in /_/src/libraries/System.Net.Http.WinHttpHandler/tests/FunctionalTests/WinHttpHandlerTest.cs:line 123
        --- End of stack trace from previous location ---
           at Xunit.Assert.RecordExceptionAsync(Func`1 testCode) in /_/src/Microsoft.DotNet.XUnitAssert/src/Record.cs:line 105

[am11]

Similar error with different reason and error code:

    System.Net.Http.Functional.Tests.PlatformHandler_HttpClientHandler_Proxy_Test.ProxyTunnelRequest_PortSpecified_NotStrippedOffInUri(host: "nosuchhost.invalid") [PASS]
      Output:
        Ignored exception:
        System.Net.Http.HttpRequestException: An error occurred while sending the request.
         ---> System.Net.Http.WinHttpException (80072EFF, 12030): Error 12030 calling WINHTTP_CALLBACK_STATUS_REQUEST_ERROR, 'The connection with the server was terminated abnormally'.
           at System.Net.Http.WinHttpHandler.StartRequestAsync(WinHttpRequestState state) in /_/src/libraries/System.Net.Http.WinHttpHandler/src/System/Net/Http/WinHttpHandler.cs:line 950
           --- End of inner exception stack trace ---
           at System.Net.Http.HttpClient.<SendAsync>g__Core|83_0(HttpRequestMessage request, HttpCompletionOption completionOption, CancellationTokenSource cts, Boolean disposeCts, CancellationTokenSource pendingRequestsCts, CancellationToken originalCancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/HttpClient.cs:line 530
           at System.Net.Http.Functional.Tests.HttpClientHandler_Proxy_Test.<>c__DisplayClass24_0.<<ProxyTunnelRequest_PortSpecified_NotStrippedOffInUri>b__0>d.MoveNext() in /_/src/libraries/Common/tests/System/Net/Http/HttpClientHandlerTest.Proxy.cs:line 652

https://helixre107v0xdcypoyl9e7f.blob.core.windows.net/dotnet-runtime-refs-heads-main-35324ac26e5c43ddb7/System.Net.Http.WinHttpHandler.Functional.Tests/3/console.270ed323.log?helixlogtype=result

[ManickaP]

@am11 what you're linking is a harmless log message, see "Ignored exception:" and "[PASS]". Recently, the logging of XUnit test has changed and all the log messages (even of passing tests) are being printed, see #103445

[liveans]

I will watch this issue in CI (main) for a while, and if it happens again, I'll re-open.