CI test failure: Connection handshake was canceled due to the configured timeout

[jkotas]

    System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates [FAIL]
      Assert.Throws() Failure: Exception type was not an exact match
      Expected: typeof(System.Security.Authentication.AuthenticationException)
      Actual:   typeof(System.Net.Quic.QuicException)
      ---- System.Net.Quic.QuicException : Connection handshake was canceled due to the configured timeout of 00:00:10 seconds elapsing.
      -------- System.OperationCanceledException : The operation was canceled.
      Stack Trace:
        /_/src/libraries/System.Net.Quic/tests/FunctionalTests/MsQuicTests.cs(390,0): at System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates()
        /_/src/libraries/System.Net.Quic/tests/FunctionalTests/MsQuicTests.cs(397,0): at System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates()
        --- End of stack trace from previous location ---
        ----- Inner Stack Trace -----
        /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs(294,0): at System.Net.Quic.QuicListener.StartConnectionHandshake(QuicConnection connection, SslClientHelloInfo clientHello)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs(264,0): at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
        /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncTaskMethodBuilderT.cs(372,0): at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs(913,0): at System.Threading.ThreadPoolWorkQueue.Dispatch()
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.NonBrowser.cs(102,0): at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
        --- End of stack trace from previous location ---
        /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs(186,0): at System.Net.Quic.QuicListener.AcceptConnectionAsync(CancellationToken cancellationToken)
        /_/src/libraries/System.Net.Quic/tests/FunctionalTests/MsQuicTests.cs(390,0): at System.Net.Quic.Tests.MsQuicTests.<>c__DisplayClass8_0.<<CertificateCallbackThrowPropagates>b__2>d.MoveNext()
        --- End of stack trace from previous location ---
        ----- Inner Stack Trace -----
        /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs(119,0): at System.Net.Quic.ValueTaskSource.TryComplete(Exception exception)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs(1203,0): at System.Threading.CancellationTokenSource.CallbackNode.ExecuteCallback()
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs(810,0): at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs(696,0): at System.Threading.CancellationTokenSource.NotifyCancellation(Boolean throwOnFirstException)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/Timer.cs(683,0): at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/Timer.cs(331,0): at System.Threading.TimerQueue.FireNextTimers()
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs(913,0): at System.Threading.ThreadPoolWorkQueue.Dispatch()
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.NonBrowser.cs(102,0): at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
        --- End of stack trace from previous location ---
        /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs(176,0): at System.Net.Quic.ValueTaskSource.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
        /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs(241,0): at System.Net.Quic.QuicListener.StartConnectionHandshake(QuicConnection connection, SslClientHelloInfo clientHello)
      Output:
        System.Net.Quic.QuicException: User configured callback failed.
         ---> System.ArithmeticException: foobar
           at System.Net.Quic.Tests.MsQuicTests.<>c__DisplayClass8_0.<CertificateCallbackThrowPropagates>b__1(Object sender, X509Certificate cert, X509Chain chain, SslPolicyErrors errors) in /_/src/libraries/System.Net.Quic/tests/FunctionalTests/MsQuicTests.cs:line 383
           at System.Net.Quic.QuicConnection.SslConnectionOptions.ValidateCertificate(X509Certificate2 certificate, Span`1 certData, Span`1 chainData) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.SslConnectionOptions.cs:line 225
           --- End of inner exception stack trace ---
           at System.Net.Quic.QuicConnection.SslConnectionOptions.ValidateCertificate(X509Certificate2 certificate, Span`1 certData, Span`1 chainData) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.SslConnectionOptions.cs:line 252
           at System.Net.Quic.QuicConnection.SslConnectionOptions.ValidateCertificate(X509Certificate2 certificate, Span`1 certData, Span`1 chainData) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.SslConnectionOptions.cs:line 225
           at System.Net.Quic.QuicConnection.SslConnectionOptions.StartAsyncCertificateValidation(IntPtr certificatePtr, IntPtr chainPtr)
           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 365
           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 79
           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 94
           at System.Net.Quic.Tests.MsQuicTests.<>c__DisplayClass8_0.<<CertificateCallbackThrowPropagates>b__3>d.MoveNext() in /_/src/libraries/System.Net.Quic/tests/FunctionalTests/MsQuicTests.cs:line 388
        --- End of stack trace from previous location ---
           at Xunit.Assert.RecordExceptionAsync(Func`1 testCode) in /_/src/Microsoft.DotNet.XUnitAssert/src/Record.cs:line 105
MsQuic Counters:
    CONN_CREATED 1577
    CONN_HANDSHAKE_FAIL 25
    CONN_APP_REJECT 8
    CONN_LOAD_REJECT 0

Build Information

Build: https://dev.azure.com/dnceng-public/cbb18261-c48f-4abb-8651-8cdcb5474649/_build/results?buildId=583082
Build error leg or test failing: System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates
Pull request: #99033

Error Message

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

{
  "ErrorMessage": "System.Net.Quic.QuicException : Connection handshake was canceled due to the configured timeout of 00:00:10 seconds elapsing.",
  "ErrorPattern": "",
  "BuildRetry": false,
  "ExcludeConsoleLog": false
}

Known issue validation

Build: 🔎 https://dev.azure.com/dnceng-public/public/_build/results?buildId=583082
Error message validated: [System.Net.Quic.QuicException : Connection handshake was canceled due to the configured timeout of 00:00:10 seconds elapsing.]
Result validation: ✅ Known issue matched with the provided build.
Validation performed at: 2/28/2024 7:50:19 PM UTC

Report

Build	Definition	Test	Pull Request
584197	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99019
584189	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99048
583901	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#97529
583884	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#98908
583812	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#95565
583795	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99094
583790	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99092
583448	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#98117
583418	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99076
583402	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99073
583430	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates
583376	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#98958
583380	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#98958
583295	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99059
583262	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99025
583200	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99024
583183	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99058
583154	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99042
583106	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#96941
583082	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99033
583094	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99053
583054	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99049
583031	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#99051
583028	dotnet/runtime	System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates	#98986

Summary

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

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.MsQuicTests.CertificateCallbackThrowPropagates [FAIL]
      Assert.Throws() Failure: Exception type was not an exact match
      Expected: typeof(System.Security.Authentication.AuthenticationException)
      Actual:   typeof(System.Net.Quic.QuicException)
      ---- System.Net.Quic.QuicException : Connection handshake was canceled due to the configured timeout of 00:00:10 seconds elapsing.
      -------- System.OperationCanceledException : The operation was canceled.
      Stack Trace:
        /_/src/libraries/System.Net.Quic/tests/FunctionalTests/MsQuicTests.cs(390,0): at System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates()
        /_/src/libraries/System.Net.Quic/tests/FunctionalTests/MsQuicTests.cs(397,0): at System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates()
        --- End of stack trace from previous location ---
        ----- Inner Stack Trace -----
        /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs(294,0): at System.Net.Quic.QuicListener.StartConnectionHandshake(QuicConnection connection, SslClientHelloInfo clientHello)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs(264,0): at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
        /_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/AsyncTaskMethodBuilderT.cs(372,0): at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs(913,0): at System.Threading.ThreadPoolWorkQueue.Dispatch()
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.NonBrowser.cs(102,0): at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
        --- End of stack trace from previous location ---
        /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs(186,0): at System.Net.Quic.QuicListener.AcceptConnectionAsync(CancellationToken cancellationToken)
        /_/src/libraries/System.Net.Quic/tests/FunctionalTests/MsQuicTests.cs(390,0): at System.Net.Quic.Tests.MsQuicTests.<>c__DisplayClass8_0.<<CertificateCallbackThrowPropagates>b__2>d.MoveNext()
        --- End of stack trace from previous location ---
        ----- Inner Stack Trace -----
        /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs(119,0): at System.Net.Quic.ValueTaskSource.TryComplete(Exception exception)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs(1203,0): at System.Threading.CancellationTokenSource.CallbackNode.ExecuteCallback()
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs(810,0): at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/CancellationTokenSource.cs(696,0): at System.Threading.CancellationTokenSource.NotifyCancellation(Boolean throwOnFirstException)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/Timer.cs(683,0): at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/Timer.cs(331,0): at System.Threading.TimerQueue.FireNextTimers()
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs(913,0): at System.Threading.ThreadPoolWorkQueue.Dispatch()
        /_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.NonBrowser.cs(102,0): at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
        --- End of stack trace from previous location ---
        /_/src/libraries/System.Net.Quic/src/System/Net/Quic/Internal/ValueTaskSource.cs(176,0): at System.Net.Quic.ValueTaskSource.System.Threading.Tasks.Sources.IValueTaskSource.GetResult(Int16 token)
        /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicListener.cs(241,0): at System.Net.Quic.QuicListener.StartConnectionHandshake(QuicConnection connection, SslClientHelloInfo clientHello)
      Output:
        System.Net.Quic.QuicException: User configured callback failed.
         ---> System.ArithmeticException: foobar
           at System.Net.Quic.Tests.MsQuicTests.<>c__DisplayClass8_0.<CertificateCallbackThrowPropagates>b__1(Object sender, X509Certificate cert, X509Chain chain, SslPolicyErrors errors) in /_/src/libraries/System.Net.Quic/tests/FunctionalTests/MsQuicTests.cs:line 383
           at System.Net.Quic.QuicConnection.SslConnectionOptions.ValidateCertificate(X509Certificate2 certificate, Span`1 certData, Span`1 chainData) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.SslConnectionOptions.cs:line 225
           --- End of inner exception stack trace ---
           at System.Net.Quic.QuicConnection.SslConnectionOptions.ValidateCertificate(X509Certificate2 certificate, Span`1 certData, Span`1 chainData) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.SslConnectionOptions.cs:line 252
           at System.Net.Quic.QuicConnection.SslConnectionOptions.ValidateCertificate(X509Certificate2 certificate, Span`1 certData, Span`1 chainData) in /_/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.SslConnectionOptions.cs:line 225
           at System.Net.Quic.QuicConnection.SslConnectionOptions.StartAsyncCertificateValidation(IntPtr certificatePtr, IntPtr chainPtr)
           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 365
           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 79
           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 94
           at System.Net.Quic.Tests.MsQuicTests.<>c__DisplayClass8_0.<<CertificateCallbackThrowPropagates>b__3>d.MoveNext() in /_/src/libraries/System.Net.Quic/tests/FunctionalTests/MsQuicTests.cs:line 388
        --- End of stack trace from previous location ---
           at Xunit.Assert.RecordExceptionAsync(Func`1 testCode) in /_/src/Microsoft.DotNet.XUnitAssert/src/Record.cs:line 105
MsQuic Counters:
    CONN_CREATED 1577
    CONN_HANDSHAKE_FAIL 25
    CONN_APP_REJECT 8
    CONN_LOAD_REJECT 0

Build Information

Build: https://dev.azure.com/dnceng-public/cbb18261-c48f-4abb-8651-8cdcb5474649/_build/results?buildId=583082
Build error leg or test failing: System.Net.Quic.Tests.MsQuicTests.CertificateCallbackThrowPropagates
Pull request: #99033

Error Message

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

{
  "ErrorMessage": "System.Net.Quic.QuicException : Connection handshake was canceled due to the configured timeout of 00:00:10 seconds elapsing.",
  "ErrorPattern": "",
  "BuildRetry": false,
  "ExcludeConsoleLog": false
}

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

[ManickaP]

@rzikm do you think this might be related to your recent change in cert validation?

[rzikm]

It is possible let me have a look

[rzikm]

Investigation notes:
The failures seem to be concentrated on Alpine images which have MsQuic built from main, according to the commit hash of the libversion, the msquic library version should contain all the necessary changes for the feature to work.

Still curious why this failure didn't show up on the original PR

[ManickaP]

Still curious why this failure didn't show up on the original PR

It's likely it didn't run on that set up at all. From our perspective, successful run of the test vs didn't run at all is really almost impossible to distinguish.

[rzikm]

Looks like microsoft/msquic#4145 was not enough, We will have to disable the test for now, as this will take some time to fix.

[rzikm]

I think I figured out what is happening, and it's more complicated than I thought. According to the traces and packet captures I collected, following happens around the certificate validation

• We yield validation procedure to threadpool, freeing MsQuic worker thread
• MsQuic proceeds to send Handshake Acks, and waits for us to finish validation
• Custom certificate validation callback throws, we catch the exception and set it to _connectedTcs
  

  runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.SslConnectionOptions.cs

  Lines 138 to 141 in 56af107

  	catch (Exception ex)
  	{
  	certificate?.Dispose();
  	_connection._connectedTcs.TrySetException(ex);

• Then we proceed to set the validation result in MsQuic
  

  runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.SslConnectionOptions.cs

  Lines 159 to 162 in 56af107

  	int status = MsQuicApi.Api.ConnectionCertificateValidationComplete(
  	_connection._handle,
  	result == QUIC_TLS_ALERT_CODES.SUCCESS ? (byte)1 : (byte)0,
  	result);

• The above call, unfortunately, just queues the operation to a queue to be served by MsQuic worker.
• Moving on, .NET Threadpool then proceeds to process the continuation in ConnectAsync, this ValueTask was completed via _connectedTcs.
  

  runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs

  Line 79 in 56af107

  await connection.FinishConnectAsync(options, linkedCts.Token).ConfigureAwait(false);

• Since the await rethrows the exception, control goes to catch block where the connection is disposed via DisposeAsync, which in turn calls MsQuicConnectionShutdown, which queues the shutdown to the front of the queue
• Eventually, MsQuic Worker will process the shutdown and prepares the connection for application layer shutdown with the DefaultConnectionCloseErrorCode specified by user.
• Since the application layer shutdown was processed first, connection close from rejecting the certificate gets ignored, and the logic I added in Don't send client CONNECTION_CLOSE on 1-RTT before handshake completion. microsoft/msquic#4145 does not trigger (it covered only transport layer shutdown).