timeout in ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream

[danmoseley]

net7.0-windows-Debug-x64-CoreCLR_release-Windows.11.Amd64.ClientPre.Open
System.Net.Http.Functional.Tests.Http1SingleChunkResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream

It seems it didn't fail before, but on this PR it failed the same way on retry.

    System.Net.Http.Functional.Tests.Http1SingleChunkResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream(readMode: AsyncArray, useSsl: False) [FAIL]
      System.TimeoutException : The operation has timed out.
      Stack Trace:
        /_/src/libraries/System.Net.Http/tests/FunctionalTests/ResponseStreamZeroByteReadTests.cs(125,0): at System.Net.Http.Functional.Tests.Http1ResponseStreamZeroByteReadTestBase.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream(ReadWriteMode readMode, Boolean useSsl)
        --- End of stack trace from previous location ---
    System.Net.Http.Functional.Tests.Http1MultiChunkResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream(readMode: AsyncArray, useSsl: False) [FAIL]
      System.TimeoutException : The operation has timed out.
      Stack Trace:
        /_/src/libraries/System.Net.Http/tests/FunctionalTests/ResponseStreamZeroByteReadTests.cs(125,0): at System.Net.Http.Functional.Tests.Http1ResponseStreamZeroByteReadTestBase.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream(ReadWriteMode readMode, Boolean useSsl)
        --- End of stack trace from previous location ---
StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Connection: Close
  Date: Sun, 03 Apr 2022 15:31:27 GMT
  Content-Length: 0
}
StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Connection: Close
  Date: Sun, 03 Apr 2022 15:31:28 GMT
  Content-Length: 0
}

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-67501-merge-02ca4a1af08348f886/System.Net.Http.Functional.Tests/2/console.90326a9a.log?sv=2019-07-07&se=2022-04-23T15%3A22%3A39Z&sr=c&sp=rl&sig=Be2A%2BVQDtQ4O4chxwstI9n7OON59LfehcbqYbl1ebeg%3D

[ghost]

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

Issue Details

---

net7.0-windows-Debug-x64-CoreCLR_release-Windows.11.Amd64.ClientPre.Open
System.Net.Http.Functional.Tests.Http1SingleChunkResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream

It seems it didn't fail before, but on this PR it failed the same way on retry.

    System.Net.Http.Functional.Tests.Http1SingleChunkResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream(readMode: AsyncArray, useSsl: False) [FAIL]
      System.TimeoutException : The operation has timed out.
      Stack Trace:
        /_/src/libraries/System.Net.Http/tests/FunctionalTests/ResponseStreamZeroByteReadTests.cs(125,0): at System.Net.Http.Functional.Tests.Http1ResponseStreamZeroByteReadTestBase.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream(ReadWriteMode readMode, Boolean useSsl)
        --- End of stack trace from previous location ---
    System.Net.Http.Functional.Tests.Http1MultiChunkResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream(readMode: AsyncArray, useSsl: False) [FAIL]
      System.TimeoutException : The operation has timed out.
      Stack Trace:
        /_/src/libraries/System.Net.Http/tests/FunctionalTests/ResponseStreamZeroByteReadTests.cs(125,0): at System.Net.Http.Functional.Tests.Http1ResponseStreamZeroByteReadTestBase.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream(ReadWriteMode readMode, Boolean useSsl)
        --- End of stack trace from previous location ---
StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Connection: Close
  Date: Sun, 03 Apr 2022 15:31:27 GMT
  Content-Length: 0
}
StatusCode: 200, ReasonPhrase: 'OK', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Connection: Close
  Date: Sun, 03 Apr 2022 15:31:28 GMT
  Content-Length: 0
}

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-67501-merge-02ca4a1af08348f886/System.Net.Http.Functional.Tests/2/console.90326a9a.log?sv=2019-07-07&se=2022-04-23T15%3A22%3A39Z&sr=c&sp=rl&sig=Be2A%2BVQDtQ4O4chxwstI9n7OON59LfehcbqYbl1ebeg%3D

Author:	danmoseley
Assignees:	-
Labels:	area-System.Net.Http, untriaged
Milestone:	-

[rzikm]

Strangely enough, I can't find this failure in the AzureDevOpsTests table (nor any other failures, for that matter), but this test seems to frequently require retry in order to pass.

[rzikm]

Still no records in the DB, I suggest we close this until it resurfaces

[wfurt]

I think we don't keep passes in database any longer.I check that t the test is not disabled so I think it would be OK to close.

[karelz]

Triage: We need to track down why the failures are missing from test results DB @dotnet/dncenghot can you please help?

[ChadNedzlek]

I'll take a peek at the table and logs to see why this guy is missing.

[ChadNedzlek]

I see 5 tests for this workitem in the DB, I believe the first one is the test in question? The names are pretty long and hard to keep in memory, so I might have misread:

Name	Outcome
System.Net.Http.Functional.Tests.Http1SingleChunkResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream	Failed
System.Net.Http.Functional.Tests.Http1CloseResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream	PassedOnRerun
System.Net.Http.Functional.Tests.Http1ContentLengthResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream	PassedOnRerun
System.Net.Http.Functional.Tests.Http1MultiChunkResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream	PassedOnRerun
System.Net.Http.Functional.Tests.Http1RawResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream	PassedOnRerun

[rzikm]

I see, all of the records for main say 'PassedOnRerun', there are actually no hard failures in the DB on main. There are actually a few failures on PRs (about 6 PRs were affected)

[karelz]

How often does it fail in PRs?

[rzikm]

14 failures in the last month across 7 PRs

[markwilkie]

Is this something that's worth setting up and known issue for and tracking more over time? https://github.com/dotnet/arcade/blob/main/Documentation/Projects/Build%20Analysis/KnownIssues.md

cc/ @ulisesh @AlitzelMendez

[wfurt]

I think we should try to reproduce it locally. Is it always new Windows or do se see other OSes as well @rzikm?
At least the original reports is with useSsl: False so it shield be only good old socket. There is 10s timeout that should be enough IMHO but we may try to bump it up.

[rzikm]

It's a mix of Centos.7.Amd64.Open, Windows.10.Amd64.Server2022.ES.Open, Windows.11.Amd64.ClientPre.Open, Alpine.314.Amd64.Open, Windows.81.Amd64.Open,

The failures are there both with useSsl and without it.

Query

cluster('engsrvprod.kusto.windows.net').database('engineeringdata').AzureDevOpsTests
    | where TestName startswith "System.Net"
        and Outcome == 'Failed' //or Outcome == 'PassedOnRerun'
    | extend i = indexof_regex(TestName, @"[^.]+$")
    | extend Method = substring(TestName, i)
    | extend Type = substring(TestName, 0, i - 1)
    | project-away i//, TestName
    | where Method startswith 'ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream'
    //| where TestName == 'System.Net.Http.Functional.Tests.Http1SingleChunkResponseStreamZeroByteReadTest.ZeroByteRead_IssuesZeroByteReadOnUnderlyingStream'
    | distinct JobId, WorkItemId, Message, StackTrace, Method, Type, Arguments, Outcome
    | join kind=inner (cluster('engsrvprod.kusto.windows.net').database('engineeringdata').Jobs
        | where Finished > now(-30d)
        | where (Branch == 'refs/heads/main') or (Source startswith "pr/")
        | where Type startswith "test/functional/cli/"
            and not(Properties contains "runtime-staging")
        | summarize arg_max(Finished, Properties, Type, Branch, Source, Started, QueueName, Attempt, Build) 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 TargetBranch = extractjson("$.['System.PullRequest.TargetBranch']", Properties)
    | extend Architecture = PropertiesJson.architecture
    | extend DefinitionName = PropertiesJson.DefinitionName
    | project-away JobId
    | extend JobId = extractjson("$.['System.JobId']", Properties)
    //| where JobId == '913fd104-6683-4129-8fd6-02f22466d821'
    //| where Architecture == 'arm64'
    //| where OS == 'Windows.10.Arm64v8.Open'
    | join kind=inner (cluster('engsrvprod.kusto.windows.net').database('engineeringdata').WorkItems
        | project-keep ConsoleUri, WorkItemId) on WorkItemId
    | project-away PropertiesJson
    | project-reorder Started, Type, Method, Arguments, StackTrace, ConsoleUri, OS, Architecture, DefinitionName, Branch, Attempt, Build, * 
;

[karelz]

Triage: We should likely address it in 7.0. Not super urgent.
Note: It is not related to SSL.

[wfurt]

It failed for me few times on my local Windows 11 machine while investigating some other failures. I'll try to collect dump and I'll investigate as time permits.

[rzikm]

Right now, there are only 3 hits on main in the last 3 months and all of them are in a run where lots of other tests have failed as well so it may be unrelated. @wfurt did you manage to collect the dump? Otherwise I am inclined to close this.

[wfurt]

It was happening to me locally. I increased some timeouts and I did not see it since. I'm still running test sets and if I don't see it today I'll post PR with updated timeouts.