System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows test failure

[jkotas]

   System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows [FAIL]
      System.AggregateException : One or more errors occurred. (Assert.Throws() Failure
      Expected: typeof(System.Net.Quic.QuicException)
      Actual:   (No exception was thrown)) (Assert.Throws() Failure
      Expected: typeof(System.Net.Quic.QuicException)
      Actual:   (No exception was thrown))
      ---- Assert.Throws() Failure
      Expected: typeof(System.Net.Quic.QuicException)
      Actual:   (No exception was thrown)
      ---- Assert.Throws() Failure
      Expected: typeof(System.Net.Quic.QuicException)
      Actual:   (No exception was thrown)
      Stack Trace:
        /_/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(92,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)
        /_/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(55,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks, Int32 millisecondsTimeout)
        /_/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(303,0): at System.Net.Quic.Tests.QuicTestBase.RunClientServer(Func`2 clientFunction, Func`2 serverFunction, Int32 iterations, Int32 millisecondsTimeout, QuicListenerOptions listenerOptions)
        /_/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(303,0): at System.Net.Quic.Tests.QuicTestBase.RunClientServer(Func`2 clientFunction, Func`2 serverFunction, Int32 

Failed in #76768. Full log: https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-76768-merge-80851214628f4109bd/System.Net.Quic.Functional.Tests/1/console.21da1d39.log?helixlogtype=result

{
  "ErrorMessage": "System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows",
  "BuildRetry": false
}

Report

Build	Definition	Step Name	Console log	Pull Request
392518	dotnet/runtime	Send to Helix	Log
388991	dotnet/runtime	Send to Helix	Log
384892	dotnet/runtime	Send to Helix	Log

Build	Definition	Test	Pull Request
411093	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.ReadWrite_Random_Success
410091	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows
408592	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.ReadWrite_Random_Success
408334	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows
407850	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows
406522	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows
406371	dotnet/runtime	System.Net.Quic.Tests.QuicStreamConformanceTests.ReadWrite_Success	#92026
401264	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows
401214	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows
397203	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows	#91683
396223	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows	#91140
393529	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows
393353	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows	#91468
393144	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows	#91413
392801	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows	#91451
392687	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows
389670	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows
388225	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows	#91224
387254	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows	#91166
386741	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows
381472	dotnet/runtime	System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows	#90794

Summary

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

Known issue validation

Build: 🔎
Result validation: ⚠️ Validation could not be done without an Azure DevOps build URL on the issue. Please add it to the "Build: 🔎" line.

[ghost]

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

Issue Details

---

   System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows [FAIL]
      System.AggregateException : One or more errors occurred. (Assert.Throws() Failure
      Expected: typeof(System.Net.Quic.QuicException)
      Actual:   (No exception was thrown)) (Assert.Throws() Failure
      Expected: typeof(System.Net.Quic.QuicException)
      Actual:   (No exception was thrown))
      ---- Assert.Throws() Failure
      Expected: typeof(System.Net.Quic.QuicException)
      Actual:   (No exception was thrown)
      ---- Assert.Throws() Failure
      Expected: typeof(System.Net.Quic.QuicException)
      Actual:   (No exception was thrown)
      Stack Trace:
        /_/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(92,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)
        /_/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(55,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks, Int32 millisecondsTimeout)
        /_/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(303,0): at System.Net.Quic.Tests.QuicTestBase.RunClientServer(Func`2 clientFunction, Func`2 serverFunction, Int32 iterations, Int32 millisecondsTimeout, QuicListenerOptions listenerOptions)
        /_/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(303,0): at System.Net.Quic.Tests.QuicTestBase.RunClientServer(Func`2 clientFunction, Func`2 serverFunction, Int32 

Failed in #76768. Full log: https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-76768-merge-80851214628f4109bd/System.Net.Quic.Functional.Tests/1/console.21da1d39.log?helixlogtype=result

{
  "ErrorMessage": "System.Net.Quic.Tests.QuicStreamTests.WriteCanceled_NextWriteThrows",
  "BuildRetry": false
}

Author:	jkotas
Assignees:	-
Labels:	area-System.Net.Quic, Known Build Error
Milestone:	-

[rzikm]

The test is flaky and the failure happens on regular runs as well (but usually succeeds on reruns)

The case seems to be when the cancellation happens to occur before the call to WriteAsync (and we call it with pre-cancelled token).

runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicStreamTests.cs

Lines 591 to 606 in 844702d

	CancellationTokenSource cts = new CancellationTokenSource(500);
	async Task WriteUntilCanceled()
	{
	var buffer = new byte[64 * 1024];
	while (true)
	{
	await stream.WriteAsync(buffer, cancellationToken: cts.Token);
	}
	}
	// a write would eventually be canceled
	await Assert.ThrowsAsync<OperationCanceledException>(() => WriteUntilCanceled().WaitAsync(TimeSpan.FromSeconds(3)));
	// next write would also throw
	await AssertThrowsQuicExceptionAsync(QuicError.OperationAborted, () => stream.WriteAsync(new byte[1]).AsTask());

We should have a look someday.

[rzikm]

Okay, my original thought was wrong, we handle precancelled tokens correctly, there is actually very slim chance to repro this because many things have to align properly.

the issue can be artificially enforced reproduced by adding sleep in

• Abort (into if (abortDirection.HasFlag(QuicAbortDirection.Write)) branch)
• WriteAsync (after if (!_sendTcs.TryGetValueTask(out ValueTask valueTask, this, cancellationToken))) or by making huge writes (e.g. 1 GB) to ensure that CancellationTokenSource fires while send is in progress

What happens is that cancellation token sets Write state to cancelled and unblocks the Test task to progress, and it completes the clientFunction and Disposes the client QuicStream (i.e. completing the write direction gracefully), before the cancellation-registered action (which runs on a different thread) manages to finish the Abort call.

In other words, if cancellation token fires while send is in progress, we may end up gracefully closing the write side :/

[rzikm]

fixed by #90253