[QUIC] Intermittent hangs in CI

[ManickaP]

Sporadic hangs of System.Net.Quic.Functional.Tests.

Since yesterday we're seeing that sometime the work item fails with "timeout" meaning a test hang and subsequent kill by the helix agent.
The potential culprit that might have caused this is #55505. Firstly, because the time when it started occurring correlates with the time of its merge. Secondly, the changes come from #52929 and there's been multiple test hangs historically.

Unique tests picked from the console logs:

[Long Running Test] 'System.Net.Quic.Tests.MsQuicQuicStreamConformanceTests.ReadWrite_Success', Elapsed: 00:14:04
[Long Running Test] 'System.Net.Quic.Tests.QuicStreamTests_MsQuicProvider.ReadWrite_Random_Success', Elapsed: 00:14:00
[Long Running Test] 'System.Net.Quic.Tests.QuicStreamTests_MsQuicProvider.LargeDataSentAndReceived', Elapsed: 00:14:04
[Long Running Test] 'System.Net.Quic.Tests.MsQuicQuicStreamConformanceTests.ReadWrite_MessagesSmallerThanReadBuffer_Success', Elapsed: 00:14:05
[Long Running Test] 'System.Net.Quic.Tests.MsQuicTests.ByteMixingOrNativeAVE_MinimalFailingTest', Elapsed: 00:14:33

Kusto queries to get the data

Failing work items (9 records):

WorkItems
| where FriendlyName == "System.Net.Quic.Functional.Tests" and Status != "Pass" and ExitCode == -3
| join kind=inner Jobs on JobId
| where DockerTag == "mcr.microsoft.com/dotnet-buildtools/prereqs:fedora-32-helix-20210710031120-870c408"
| order by Queued desc

Success for comparison (465 total, 135 since the first failure):

WorkItems
| where FriendlyName == "System.Net.Quic.Functional.Tests" and Status == "Pass"
| join kind=inner Jobs on JobId
| where DockerTag == "mcr.microsoft.com/dotnet-buildtools/prereqs:fedora-32-helix-20210710031120-870c408"
| order by Queued desc

cc: @CarnaViire @karelz

Build	Kind	Start Time
1236570	PR 55594	2021-14-07

[ghost]

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

Issue Details

---

Sporadic hangs of System.Net.Quic.Functional.Tests.

Since yesterday we're seeing that sometime the work item fails with "timeout" meaning a test hang and subsequent kill by the helix agent.
The potential culprit that might have caused this is #55505. Firstly, because the time when it started occurring correlates with the time of its merge. Secondly, the changes come from #52929 and there's been multiple test hangs historically.

Unique tests picked from the console logs:

[Long Running Test] 'System.Net.Quic.Tests.MsQuicQuicStreamConformanceTests.ReadWrite_Success', Elapsed: 00:14:04
[Long Running Test] 'System.Net.Quic.Tests.QuicStreamTests_MsQuicProvider.ReadWrite_Random_Success', Elapsed: 00:14:00
[Long Running Test] 'System.Net.Quic.Tests.QuicStreamTests_MsQuicProvider.LargeDataSentAndReceived', Elapsed: 00:14:04
[Long Running Test] 'System.Net.Quic.Tests.MsQuicQuicStreamConformanceTests.ReadWrite_MessagesSmallerThanReadBuffer_Success', Elapsed: 00:14:05
[Long Running Test] 'System.Net.Quic.Tests.MsQuicTests.ByteMixingOrNativeAVE_MinimalFailingTest', Elapsed: 00:14:33

Kusto queries to get the data

Failing work items (9 records):

WorkItems
| where FriendlyName == "System.Net.Quic.Functional.Tests" and Status != "Pass" and ExitCode == -3
| join kind=inner Jobs on JobId
| where DockerTag == "mcr.microsoft.com/dotnet-buildtools/prereqs:fedora-32-helix-20210710031120-870c408"
| order by Queued desc

Success for comparison (465 total, 135 since the first failure):

WorkItems
| where FriendlyName == "System.Net.Quic.Functional.Tests" and Status == "Pass"
| join kind=inner Jobs on JobId
| where DockerTag == "mcr.microsoft.com/dotnet-buildtools/prereqs:fedora-32-helix-20210710031120-870c408"
| order by Queued desc

cc: @CarnaViire @karelz

Author:	ManickaP
Assignees:	-
Labels:	area-System.Net.Quic
Milestone:	6.0.0

[ManickaP]

If we decide to punt this, we should be sure this is not a product bug.

[wfurt]

I can reproduce locally. Definitely seems like regression.

[geoffkizer]

We should not punt this.

[wfurt]

We seems to always hang in synchronous Read or Write. We are generally in ConnectionClose state.
I'll continue tomorrow to see why we are not continuing/failing as we should

[wfurt]

It seems like we have problem with completing the tasks.
The underlying task completion is set as finished and that should wake the chained WriteAsync we call from Write via

WriteAsync(buffer.ToArray()).AsTask().GetAwaiter().GetResult();

The continuation hangs on thread-pool without being completed.
At this point #53471 is main suspect for the regression @kouvel.
Full dump is posted https://microsoft-my.sharepoint.com/:u:/p/toweinfu/Ed_HLuTVJFJIvA1g5ZhgT8YBBV-h7GXMOWzr73pNosiA7g?e=O93P6L and it would be great if you can take a look why thread pool is not running the tasks.
I look at it with @stephentoub and it seems like the old code should work but it does not. Changes from #55985 should not make difference but they do. I don't know if contributing factor is fact that my VM is 2-core system. I'de be happy to test it with more (or less) cores.

also note that other tasks get stuck too at this point. I added

  using CancellationTokenSource cts = new CancellationTokenSource();
  cts.CancelAfter(_readTimeout);

and the cancellation would not expire either at this point.

[ghost]

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

Issue Details

---

Sporadic hangs of System.Net.Quic.Functional.Tests.

Since yesterday we're seeing that sometime the work item fails with "timeout" meaning a test hang and subsequent kill by the helix agent.
The potential culprit that might have caused this is #55505. Firstly, because the time when it started occurring correlates with the time of its merge. Secondly, the changes come from #52929 and there's been multiple test hangs historically.

Unique tests picked from the console logs:

[Long Running Test] 'System.Net.Quic.Tests.MsQuicQuicStreamConformanceTests.ReadWrite_Success', Elapsed: 00:14:04
[Long Running Test] 'System.Net.Quic.Tests.QuicStreamTests_MsQuicProvider.ReadWrite_Random_Success', Elapsed: 00:14:00
[Long Running Test] 'System.Net.Quic.Tests.QuicStreamTests_MsQuicProvider.LargeDataSentAndReceived', Elapsed: 00:14:04
[Long Running Test] 'System.Net.Quic.Tests.MsQuicQuicStreamConformanceTests.ReadWrite_MessagesSmallerThanReadBuffer_Success', Elapsed: 00:14:05
[Long Running Test] 'System.Net.Quic.Tests.MsQuicTests.ByteMixingOrNativeAVE_MinimalFailingTest', Elapsed: 00:14:33

Kusto queries to get the data

Failing work items (9 records):

WorkItems
| where FriendlyName == "System.Net.Quic.Functional.Tests" and Status != "Pass" and ExitCode == -3
| join kind=inner Jobs on JobId
| where DockerTag == "mcr.microsoft.com/dotnet-buildtools/prereqs:fedora-32-helix-20210710031120-870c408"
| order by Queued desc

Success for comparison (465 total, 135 since the first failure):

WorkItems
| where FriendlyName == "System.Net.Quic.Functional.Tests" and Status == "Pass"
| join kind=inner Jobs on JobId
| where DockerTag == "mcr.microsoft.com/dotnet-buildtools/prereqs:fedora-32-helix-20210710031120-870c408"
| order by Queued desc

cc: @CarnaViire @karelz

Build	Kind	Start Time
1236570	PR 55594	2021-14-07

Author:	ManickaP
Assignees:	wfurt
Labels:	area-System.Threading, bug
Milestone:	6.0.0