[QUIC]: failing to sometimes create MsQuic configuration

[wfurt]

Sometimes when running QUIC tests, the test run fails as (originally reported in #52742)

 Starting:    System.Net.Quic.Functional.Tests (parallel test collections = on, max threads = 2)
      System.Net.Quic.QuicException : ConfigurationOpen failed. Error Code: INVALID_PARAMETER
      Stack Trace:
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Internal/QuicExceptionHelpers.cs(12,0): at System.Net.Quic.Implementations.MsQuic.Internal.QuicExceptionHelpers.ThrowIfFailed(UInt32 status, String message, Exception innerException)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/SafeMsQuicConfigurationHandle.cs(117,0): at System.Net.Quic.Implementations.MsQuic.Internal.SafeMsQuicConfigurationHandle.Create(QuicOptions options, QUIC_CREDENTIAL_FLAGS flags, X509Certificate certificate, List`1 alpnProtocols)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/SafeMsQuicConfigurationHandle.cs(34,0): at System.Net.Quic.Implementations.MsQuic.Internal.SafeMsQuicConfigurationHandle.Create(QuicClientConnectionOptions options)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicConnection.cs(111,0): at System.Net.Quic.Implementations.MsQuic.MsQuicConnection..ctor(QuicClientConnectionOptions options)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicImplementationProvider.cs(19,0): at System.Net.Quic.Implementations.MsQuic.MsQuicImplementationProvider.CreateConnection(QuicClientConnectionOptions options)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs(44,0): at System.Net.Quic.QuicConnection..ctor(QuicImplementationProvider implementationProvider, QuicClientConnectionOptions options)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs(37,0): at System.Net.Quic.QuicConnection..ctor(QuicImplementationProvider implementationProvider, EndPoint remoteEndPoint, SslClientAuthenticationOptions sslClientAuthenticationOptions, IPEndPoint localEndPoint)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(53,0): at System.Net.Quic.Tests.QuicTestBase`1.CreateQuicConnection(IPEndPoint endpoint)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(90,0): at System.Net.Quic.Tests.QuicTestBase`1.<>c__DisplayClass16_0.<<RunClientServer>b__1>d.MoveNext()
        --- End of stack trace from previous location ---
        /home/furt/github/wfurt-runtime/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(55,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)
        /home/furt/github/wfurt-runtime/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(82,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)
        /home/furt/github/wfurt-runtime/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(49,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks, Int32 millisecondsTimeout)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(78,0): at System.Net.Quic.Tests.QuicTestBase`1.RunClientServer(Func`2 clientFunction, Func`2 serverFunction, Int32 iterations, Int32 millisecondsTimeout)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicStreamTests.cs(22,0): at System.Net.Quic.Tests.QuicStreamTests`1.BasicTest()
        --- End of stack trace from previous location ---
  Finished:    System.Net.Quic.Functional.Tests

msquic native logs on Linux only show

[1][221e5.2221a][11:29:18.205790][ api] Enter 5 (0x55653138f970).
[1][221e5.2221a][11:29:18.205922][ api] Exit 22

(22 == EINVAL on Linux)

This is coming from this
https://github.com/microsoft/msquic/blob/bde86efb0712f9a1d726c31a9378560e7a9cbdb2/src/core/configuration.c#L62-L69

and length looks like garbage so this is likely another .NET pinning problem.

Few more thoughts on the log:

• In my case the test run will produce LARGE log file. It is pretty difficult to find the relevant entires. It would be nice if the error cases cases there is clear error log in addition to the entry/exit
• The enum value will change between platforms. That makes it more difficult IMHO to write guide or know what to look for.
• on the .NET side I'm wondering if we should show (or log) the handle so it easier to correlate to the native logs.

cc: @nibanks @ThadHouse

The issue is probably pinning of outer buffers with ALPN:

This looks to just take the address of QuicBuffers assuming theyre pinned, but MsQuicAlpnHelper.Prepare doesn't pin the outer buffers, just the inner buffers.

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

Issue Details

---

Sometimes when running QUIC tests, the test run fails as (originally reported in #52742)

 Starting:    System.Net.Quic.Functional.Tests (parallel test collections = on, max threads = 2)
      System.Net.Quic.QuicException : ConfigurationOpen failed. Error Code: INVALID_PARAMETER
      Stack Trace:
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Internal/QuicExceptionHelpers.cs(12,0): at System.Net.Quic.Implementations.MsQuic.Internal.QuicExceptionHelpers.ThrowIfFailed(UInt32 status, String message, Exception innerException)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/SafeMsQuicConfigurationHandle.cs(117,0): at System.Net.Quic.Implementations.MsQuic.Internal.SafeMsQuicConfigurationHandle.Create(QuicOptions options, QUIC_CREDENTIAL_FLAGS flags, X509Certificate certificate, List`1 alpnProtocols)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/SafeMsQuicConfigurationHandle.cs(34,0): at System.Net.Quic.Implementations.MsQuic.Internal.SafeMsQuicConfigurationHandle.Create(QuicClientConnectionOptions options)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicConnection.cs(111,0): at System.Net.Quic.Implementations.MsQuic.MsQuicConnection..ctor(QuicClientConnectionOptions options)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicImplementationProvider.cs(19,0): at System.Net.Quic.Implementations.MsQuic.MsQuicImplementationProvider.CreateConnection(QuicClientConnectionOptions options)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs(44,0): at System.Net.Quic.QuicConnection..ctor(QuicImplementationProvider implementationProvider, QuicClientConnectionOptions options)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs(37,0): at System.Net.Quic.QuicConnection..ctor(QuicImplementationProvider implementationProvider, EndPoint remoteEndPoint, SslClientAuthenticationOptions sslClientAuthenticationOptions, IPEndPoint localEndPoint)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(53,0): at System.Net.Quic.Tests.QuicTestBase`1.CreateQuicConnection(IPEndPoint endpoint)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(90,0): at System.Net.Quic.Tests.QuicTestBase`1.<>c__DisplayClass16_0.<<RunClientServer>b__1>d.MoveNext()
        --- End of stack trace from previous location ---
        /home/furt/github/wfurt-runtime/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(55,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)
        /home/furt/github/wfurt-runtime/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(82,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)
        /home/furt/github/wfurt-runtime/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(49,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks, Int32 millisecondsTimeout)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(78,0): at System.Net.Quic.Tests.QuicTestBase`1.RunClientServer(Func`2 clientFunction, Func`2 serverFunction, Int32 iterations, Int32 millisecondsTimeout)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicStreamTests.cs(22,0): at System.Net.Quic.Tests.QuicStreamTests`1.BasicTest()
        --- End of stack trace from previous location ---
  Finished:    System.Net.Quic.Functional.Tests

msquic native logs on Linux only show

[1][221e5.2221a][11:29:18.205790][ api] Enter 5 (0x55653138f970).
[1][221e5.2221a][11:29:18.205922][ api] Exit 22

(22 == EINVAL on Linux)

This is coming from this
https://github.com/microsoft/msquic/blob/bde86efb0712f9a1d726c31a9378560e7a9cbdb2/src/core/configuration.c#L62-L69

and length looks like garbage so this is likely another .NET pinning problem.

Few more thoughts on the log:

• In my case the test run will produce LARGE log file. It is pretty difficult to find the relevant entires. It would be nice if the error cases cases there is clear error log in addition to the entry/exit
• The enum value will change between platforms. That makes it more difficult IMHO to write guide or know what to look for.
• on the .NET side I'm wondering if we should show (or log) the handle so it easier to correlate to the native logs.

cc: @nibanks @ThadHouse

Author:	wfurt
Assignees:	-
Labels:	area-System.Net.Quic
Milestone:	-

[ManickaP]

Triage: all bugs with memory and pinning must be fixed for 6.0, those are serious.

👍 for logging the handle. We already track a generic issue for logging #51177, so I suggest to add this there.

[nibanks]

Few more thoughts on the log:

• In my case the test run will produce LARGE log file. It is pretty difficult to find the relevant entires. It would be nice if the error cases cases there is clear error log in addition to the entry/exit
• The enum value will change between platforms. That makes it more difficult IMHO to write guide or know what to look for.

We could add a specific ApiExitStatusFailure event instead of just ApiExitStatus, requiring another branch for every API call though. But, it shouldn't be that hard to come up with a filter to find just failed API calls though. Something like (+ for add filter, - for exclude):

+ "[ api] Exit " (extra space is important)
- "[ api] Exit 0"
- "[ api] Exit 4294967295" (Posix QUIC_STATUS_CONTINUE)
- "[ api] Exit 4294967294" (Posix QUIC_STATUS_PENDING)
- "[ api] Exit 459998" (Windows QUIC_STATUS_CONTINUE)
- "[ api] Exit 459749" (Windows QUIC_STATUS_PENDING)

(you'd have to double check my numeric values though).

I could perhaps update the MsQuic TSG with this and even add a new TAT filter file just for failed API calls. I would prefer a post-processing solution like this over additional code at runtime. Thoughts?

[ThadHouse]

Looking at the code, I definitely suspect a pinning issue.

https://github.com/dotnet/runtime/blob/main/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Interop/SafeMsQuicConfigurationHandle.cs#L110

This looks to just take the address of QuicBuffers assuming theyre pinned, but MsQuicAlpnHelper.Prepare doesn't pin the outer buffers, just the inner buffers.

[nibanks]

FYI, I created the TAT filter: microsoft/msquic#1639

[ManickaP]

Triage: we haven't seen this in a while. @wfurt please check if you're still seeing this, otherwise please close it.

[wfurt]

Saw something similar on stream today

  System.Net.Quic.Tests.MockQuicStreamConformanceTests.ReadWrite_Success(mode: SyncSpan, writeSize: 1, startWithFlush: True) [STARTING]
      System.AggregateException : One or more errors occurred. (One or more errors occurred. (Operation aborted.)) (One or more errors occurred. (Failed to open stream to peer. Error Code: INVALID_STATE))
      ---- System.AggregateException : One or more errors occurred. (Operation aborted.)
      -------- System.Net.Quic.QuicOperationAbortedException : Operation aborted.
      ---- System.AggregateException : One or more errors occurred. (Failed to open stream to peer. Error Code: INVALID_STATE)
      -------- System.Net.Quic.QuicException : Failed to open stream to peer. Error Code: INVALID_STATE
      Stack Trace:
        /home/furt/github/wfurt-runtime/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(80,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)
        /home/furt/github/wfurt-runtime/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(49,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks, Int32 millisecondsTimeout)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(132,0): at System.Net.Quic.Tests.QuicTestBase`1.RunClientServer(Func`2 clientFunction, Func`2 serverFunction, Int32 iterations, Int32 millisecondsTimeout, QuicListenerOptions listenerOptions)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicConnectionTests.cs(136,0): at System.Net.Quic.Tests.QuicConnectionTests`1.Dispose_WithOpenLocalStream_LocalStreamFailsWithQuicOperationAbortedException(Int32 writesBeforeClose)
        --- End of stack trace from previous location ---
        ----- Inner Stack Trace #1 (System.AggregateException) -----

        ----- Inner Stack Trace -----
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicConnection.cs(455,0): at System.Net.Quic.Implementations.MsQuic.MsQuicConnection.AcceptStreamAsync(CancellationToken cancellationToken)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs(98,0): at System.Net.Quic.QuicConnection.AcceptStreamAsync(CancellationToken cancellationToken)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicConnectionTests.cs(152,0): at System.Net.Quic.Tests.QuicConnectionTests`1.<>c__DisplayClass6_0.<<Dispose_WithOpenLocalStream_LocalStreamFailsWithQuicOperationAbortedException>b__1>d.MoveNext()
        --- End of stack trace from previous location ---
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(137,0): at System.Net.Quic.Tests.QuicTestBase`1.<>c__DisplayClass22_0.<<RunClientServer>b__0>d.MoveNext()
        --- End of stack trace from previous location ---
        /home/furt/github/wfurt-runtime/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(63,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)
        ----- Inner Stack Trace #2 (System.AggregateException) -----

        ----- Inner Stack Trace -----
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/Internal/QuicExceptionHelpers.cs(12,0): at System.Net.Quic.Implementations.MsQuic.Internal.QuicExceptionHelpers.ThrowIfFailed(UInt32 status, String message, Exception innerException)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs(163,0): at System.Net.Quic.Implementations.MsQuic.MsQuicStream..ctor(State connectionState, QUIC_STREAM_OPEN_FLAGS flags)
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicConnection.cs(528,0): at System.Net.Quic.Implementations.MsQuic.MsQuicConnection.OpenBidirectionalStream()
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/QuicConnection.cs(92,0): at System.Net.Quic.QuicConnection.OpenBidirectionalStream()
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicConnectionTests.cs(139,0): at System.Net.Quic.Tests.QuicConnectionTests`1.<>c__DisplayClass6_0.<<Dispose_WithOpenLocalStream_LocalStreamFailsWithQuicOperationAbortedException>b__0>d.MoveNext()
        --- End of stack trace from previous location ---
        /home/furt/github/wfurt-runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/QuicTestBase.cs(147,0): at System.Net.Quic.Tests.QuicTestBase`1.<>c__DisplayClass22_0.<<RunClientServer>b__1>d.MoveNext()
        --- End of stack trace from previous location ---
        /home/furt/github/wfurt-runtime/src/libraries/Common/tests/System/Threading/Tasks/TaskTimeoutExtensions.cs(55,0): at System.Threading.Tasks.TaskTimeoutExtensions.WhenAllOrAnyFailed(Task[] tasks)

[ManickaP]

@wfurt this is something different, that means that you're trying to open a stream on which the connection doesn't have any free stream limit. Since you're seeing in quic tests (not HTTP/3) in just means that we have somehow somewhere screwed up setting of stream limit in our test.

But looking at the code, it hasn't change. The problem is probably still there.