[HttpStress] massive cancellation errors in HTTP/3

[ManickaP]

Sometime around merging #84793, we started to see cancellations of QUIC connection attempts. They are in high number, e.g.:19 995, 19 803. They tend to occur around the same timestamp, the operation duration is very fast and mostly not cancelled:

Timestamps: 14:52:23.1258894, Duration: 00:00:00.0004714, Cancelled: False

They started occuring around the time I merged #84793 with the msquic hack, but they are still there after it's removal in #87926, which makes me believe it's not the causation but correlation.

This is offshoot from #77126, which I believe was wrongly re-opened, as this seemed to be a new error.

Whole exception stack:

 System.Net.Http.HttpRequestException: Requesting HTTP version 3.0 with version policy RequestVersionExact while unable to establish HTTP/3 connection.
  ---> System.Net.Http.HttpRequestException: The operation was canceled. (server:5001)
  ---> System.OperationCanceledException: The operation was canceled.
    at System.Net.Quic.ValueTaskSource.TryComplete(Exception exception) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 119
    at System.Net.Quic.ValueTaskSource.TrySetException(Exception exception) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 166
    at System.Net.Quic.ValueTaskSource.<>c.<TryInitialize>b__10_0(Object obj, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 70
    at System.Threading.CancellationTokenSource.Invoke(Delegate d, Object state, CancellationTokenSource source) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 981
    at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 806
    at System.Threading.CancellationTokenSource.Invoke(Delegate d, Object state, CancellationTokenSource source) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 977
    at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 806
    at HttpStress.RequestContext.SendAsync(HttpRequestMessage request, HttpCompletionOption httpCompletion, Nullable`1 token) in /app/ClientOperations.cs:line 89
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.RequestContext.SendAsync(HttpRequestMessage request, HttpCompletionOption httpCompletion, Nullable`1 token)
    at HttpStress.ClientOperations.<>c.<<get_Operations>b__1_0>d.MoveNext() in /app/ClientOperations.cs:line 193
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.ClientOperations.<>c.<get_Operations>b__1_0(RequestContext ctx)
    at HttpStress.StressClient.<>c__DisplayClass17_0.<<StartCore>g__RunWorker|0>d.MoveNext() in /app/StressClient.cs:line 204
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.StressClient.<>c__DisplayClass17_0.<StartCore>g__RunWorker|0(Int32 taskNum)
    at System.Linq.Enumerable.SelectRangeIterator`1.Fill(Span`1 results, Int32 start, Func`2 func) in /_/src/libraries/System.Linq/src/System/Linq/Select.SpeedOpt.cs:line 227
    at System.Linq.Enumerable.SelectRangeIterator`1.ToArray() in /_/src/libraries/System.Linq/src/System/Linq/Select.SpeedOpt.cs:line 210
    at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source) in /_/src/libraries/System.Linq/src/System/Linq/ToCollection.cs:line 17
    at HttpStress.StressClient.StartCore() in /app/StressClient.cs:line 184
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.StressClient.StartCore()
    at HttpStress.StressClient.Start() in /app/StressClient.cs:line 92
    at HttpStress.Program.Run(Configuration config) in /app/Program.cs:line 205
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.Program.Run(Configuration config)
    at HttpStress.Program.Main(String[] args) in /app/Program.cs:line 39
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.Program.Main(String[] args)
    at HttpStress.Program.<Main>(String[] args)
 --- End of stack trace from previous location ---
    at System.Net.Quic.ValueTaskSource.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 176
    at System.Net.Quic.QuicConnection.FinishConnectAsync(QuicClientConnectionOptions options, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs:line 328
    at System.Net.Quic.QuicConnection.<ConnectAsync>g__StartConnectAsync|2_0(QuicClientConnectionOptions options, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs:line 72
    at System.Net.Quic.QuicConnection.<ConnectAsync>g__StartConnectAsync|2_0(QuicClientConnectionOptions options, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs:line 77
    at System.Net.Http.ConnectHelper.ConnectQuicAsync(HttpRequestMessage request, DnsEndPoint endPoint, TimeSpan idleTimeout, SslClientAuthenticationOptions clientAuthenticationOptions, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectHelper.cs:line 120
    --- End of inner exception stack trace ---
    at System.Net.Http.ConnectHelper.ConnectQuicAsync(HttpRequestMessage request, DnsEndPoint endPoint, TimeSpan idleTimeout, SslClientAuthenticationOptions clientAuthenticationOptions, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectHelper.cs:line 133
    at System.Net.Http.HttpConnectionPool.GetHttp3ConnectionAsync(HttpRequestMessage request, HttpAuthority authority, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs:line 926
    at System.Net.Http.HttpConnectionPool.TrySendUsingHttp3Async(HttpRequestMessage request, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs:line 1000
    at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs:line 1056
    at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RedirectHandler.cs:line 30
    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
    --- End of inner exception stack trace ---
    at System.Net.Http.HttpConnectionPool.TrySendUsingHttp3Async(HttpRequestMessage request, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs:line 987
    at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs:line 1056
    at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RedirectHandler.cs:line 30
    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 HttpStress.RequestContext.SendAsync(HttpRequestMessage request, HttpCompletionOption httpCompletion, Nullable`1 token) in /app/ClientOperations.cs:line 95
    at HttpStress.ClientOperations.<>c.<<get_Operations>b__1_4>d.MoveNext() in /app/ClientOperations.cs:line 288
 --- End of stack trace from previous location ---
    at HttpStress.StressClient.<>c__DisplayClass17_0.<<StartCore>g__RunWorker|0>d.MoveNext() in /app/StressClient.cs:line 204

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

Issue Details

---

Sometime around merging #84793, we started to see cancellations of QUIC connection attempts. They are in high number, e.g.:19 995, 19 803. They tend to occur around the same timestamp, the operation duration is very fast and mostly not cancelled:

Timestamps: 14:52:23.1258894, Duration: 00:00:00.0004714, Cancelled: False

They started occuring around the time I merged #84793 with the msquic hack, but they are still there after it's removal in #87926, which makes me believe it's not the causation but correlation.

This is offshoot from #77126, which I believe was wrongly re-opened, as this seemed to be a new error.

Whole exception stack:

 System.Net.Http.HttpRequestException: Requesting HTTP version 3.0 with version policy RequestVersionExact while unable to establish HTTP/3 connection.
  ---> System.Net.Http.HttpRequestException: The operation was canceled. (server:5001)
  ---> System.OperationCanceledException: The operation was canceled.
    at System.Net.Quic.ValueTaskSource.TryComplete(Exception exception) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 119
    at System.Net.Quic.ValueTaskSource.TrySetException(Exception exception) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 166
    at System.Net.Quic.ValueTaskSource.<>c.<TryInitialize>b__10_0(Object obj, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 70
    at System.Threading.CancellationTokenSource.Invoke(Delegate d, Object state, CancellationTokenSource source) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 981
    at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 806
    at System.Threading.CancellationTokenSource.Invoke(Delegate d, Object state, CancellationTokenSource source) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 977
    at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs:line 806
    at HttpStress.RequestContext.SendAsync(HttpRequestMessage request, HttpCompletionOption httpCompletion, Nullable`1 token) in /app/ClientOperations.cs:line 89
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.RequestContext.SendAsync(HttpRequestMessage request, HttpCompletionOption httpCompletion, Nullable`1 token)
    at HttpStress.ClientOperations.<>c.<<get_Operations>b__1_0>d.MoveNext() in /app/ClientOperations.cs:line 193
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.ClientOperations.<>c.<get_Operations>b__1_0(RequestContext ctx)
    at HttpStress.StressClient.<>c__DisplayClass17_0.<<StartCore>g__RunWorker|0>d.MoveNext() in /app/StressClient.cs:line 204
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.StressClient.<>c__DisplayClass17_0.<StartCore>g__RunWorker|0(Int32 taskNum)
    at System.Linq.Enumerable.SelectRangeIterator`1.Fill(Span`1 results, Int32 start, Func`2 func) in /_/src/libraries/System.Linq/src/System/Linq/Select.SpeedOpt.cs:line 227
    at System.Linq.Enumerable.SelectRangeIterator`1.ToArray() in /_/src/libraries/System.Linq/src/System/Linq/Select.SpeedOpt.cs:line 210
    at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source) in /_/src/libraries/System.Linq/src/System/Linq/ToCollection.cs:line 17
    at HttpStress.StressClient.StartCore() in /app/StressClient.cs:line 184
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.StressClient.StartCore()
    at HttpStress.StressClient.Start() in /app/StressClient.cs:line 92
    at HttpStress.Program.Run(Configuration config) in /app/Program.cs:line 205
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.Program.Run(Configuration config)
    at HttpStress.Program.Main(String[] args) in /app/Program.cs:line 39
    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncMethodBuilderCore.cs:line 38
    at HttpStress.Program.Main(String[] args)
    at HttpStress.Program.<Main>(String[] args)
 --- End of stack trace from previous location ---
    at System.Net.Quic.ValueTaskSource.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs:line 176
    at System.Net.Quic.QuicConnection.FinishConnectAsync(QuicClientConnectionOptions options, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs:line 328
    at System.Net.Quic.QuicConnection.<ConnectAsync>g__StartConnectAsync|2_0(QuicClientConnectionOptions options, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs:line 72
    at System.Net.Quic.QuicConnection.<ConnectAsync>g__StartConnectAsync|2_0(QuicClientConnectionOptions options, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs:line 77
    at System.Net.Http.ConnectHelper.ConnectQuicAsync(HttpRequestMessage request, DnsEndPoint endPoint, TimeSpan idleTimeout, SslClientAuthenticationOptions clientAuthenticationOptions, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectHelper.cs:line 120
    --- End of inner exception stack trace ---
    at System.Net.Http.ConnectHelper.ConnectQuicAsync(HttpRequestMessage request, DnsEndPoint endPoint, TimeSpan idleTimeout, SslClientAuthenticationOptions clientAuthenticationOptions, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectHelper.cs:line 133
    at System.Net.Http.HttpConnectionPool.GetHttp3ConnectionAsync(HttpRequestMessage request, HttpAuthority authority, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs:line 926
    at System.Net.Http.HttpConnectionPool.TrySendUsingHttp3Async(HttpRequestMessage request, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs:line 1000
    at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs:line 1056
    at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RedirectHandler.cs:line 30
    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
    --- End of inner exception stack trace ---
    at System.Net.Http.HttpConnectionPool.TrySendUsingHttp3Async(HttpRequestMessage request, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs:line 987
    at System.Net.Http.HttpConnectionPool.SendWithVersionDetectionAndRetryAsync(HttpRequestMessage request, Boolean async, Boolean doRequestAuth, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs:line 1056
    at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, Boolean async, CancellationToken cancellationToken) in /_/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RedirectHandler.cs:line 30
    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 HttpStress.RequestContext.SendAsync(HttpRequestMessage request, HttpCompletionOption httpCompletion, Nullable`1 token) in /app/ClientOperations.cs:line 95
    at HttpStress.ClientOperations.<>c.<<get_Operations>b__1_4>d.MoveNext() in /app/ClientOperations.cs:line 288
 --- End of stack trace from previous location ---
    at HttpStress.StressClient.<>c__DisplayClass17_0.<<StartCore>g__RunWorker|0>d.MoveNext() in /app/StressClient.cs:line 204

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

[ManickaP]

I see the problem here and it was there before the hack.

When we fail to create a new QuicConnection, we blocklist the authority:

runtime/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs

Lines 917 to 928 in ce953d0

	try
	{
	quicConnection = await ConnectHelper.ConnectQuicAsync(request, new DnsEndPoint(authority.IdnHost, authority.Port), _poolManager.Settings._pooledConnectionIdleTimeout, _sslOptionsHttp3!, cancellationToken).ConfigureAwait(false);
	}
	catch (Exception e)
	{
	if (NetEventSource.Log.IsEnabled()) Trace($"QUIC connection failed: {e}");
	// Disables HTTP/3 until server announces it can handle it via Alt-Svc.
	BlocklistAuthority(authority, e);
	throw;
	}

Then, for a while, new connection to that authority is not allowed and the same exception is reported back.

What happens with stress is that we have random cancellation and if that cancellation ends up right in the middle of connection establishment, we'll blocklist the server.

The fix should be to not to blocklist in case of cancellation.