Skip to content

HTTP/3: InvalidOperationException with many streams on a connection #55249

Closed
Closed
HTTP/3: InvalidOperationException with many streams on a connection#55249
Labels
area-System.Net.Quicbugtenet-reliabilityReliability/stability related issue (stress, load problems, etc.)
Milestone
7.0.0

Description

@JamesNK
JamesNK
opened on Jul 7, 2021

I have a test that:

  1. Client is starting a QUIC connection. The server accepts it.
  2. Client is starting 101 concurrent bidirectional streams simultaneously on the connection.
  3. Each client stream is sending about 20 bytes to the server then finishing.
  4. The server is reading the data and then waiting.
  5. Once all 101 streams are open and the server has read data from each stream then the server then completes the open streams gracefully (I think, still getting my head around what that means with QUIC).

I saw this error:

[xUnit.net 00:00:00.51]   Starting:    Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests (parallel test collections = on, max threads = unlimited)
The active test run was aborted. Reason: Test host process crashed : Unhandled exception. System.InvalidOperationException: Operation is not valid due to the current state of the object.
   at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1.OnCompleted(Action`1 continuation, Object state, Int16 token, ValueTaskSourceOnCompletedFlags flags) in System.Private.CoreLib.dll:token 0x6003034+0x97
   at System.Net.Quic.Implementations.MsQuic.Internal.ResettableCompletionSource`1.OnCompleted(Action`1 continuation, Object state, Int16 token, ValueTaskSourceOnCompletedFlags flags) in System.Net.Quic.dll:token 0x6000198+0x0
   at System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1.ConfiguredValueTaskAwaiter.System.Runtime.CompilerServices.IStateMachineBoxAwareAwaiter.AwaitUnsafeOnCompleted(IAsyncStateMachineBox box) in System.Private.CoreLib.dll:token 0x6004ae4+0x2c
   at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AwaitUnsafeOnCompleted[TAwaiter](TAwaiter& awaiter, IAsyncStateMachineBox box) in System.Private.CoreLib.dll:token 0x6004a5b+0x0
--- End of stack trace from previous location ---
   at System.Threading.Tasks.Task.<>c.<ThrowAsync>b__140_1(Object state) in System.Private.CoreLib.dll:token 0x6002ea3+0x0
   at System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute() in System.Private.CoreLib.dll:token 0x6002bac+0x14
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in System.Private.CoreLib.dll:token 0x6002b86+0xa0
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in System.Private.CoreLib.dll:token 0x6002c80+0x67
   at System.Threading.Thread.StartCallback() in System.Private.CoreLib.dll:token 0x6002819+0xe

I'm not sure at what point or why the error happens as it is raised from the thread pool and crashes the test.

Activity

  1. JamesNK
    added
    area-System.Net.Quic
    on Jul 7, 2021
  3. ghost added
    untriagedNew issue has not been triaged by the area owner
    on Jul 7, 2021

  4. JamesNK commented on Jul 7, 2021

    @JamesNK
    JamesNK
    on Jul 7, 2021
    MemberAuthor

    More details: This error isn't consistent. With the same test, this similar error was thrown:

        | [0.209s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA0VEUNHHRH:24" unexpected error.
    | System.InvalidOperationException: Operation is not valid due to the current state of the object.
    |    at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1.ValidateToken(Int16 token) in System.Private.CoreLib.dll:token 0x6003035+0x9
    |    at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1.GetStatus(Int16 token) in System.Private.CoreLib.dll:token 0x6003032+0x0
    |    at System.Net.Quic.Implementations.MsQuic.Internal.ResettableCompletionSource`1.GetStatus(Int16 token) in System.Net.Quic.dll:token 0x6000197+0x0
    |    at System.Net.Quic.Implementations.MsQuic.MsQuicStream.ReadAsync(Memory`1 destination, CancellationToken cancellationToken) in System.Net.Quic.dll:token 0x6000133+0x1aa
    |    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.ProcessReceives() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 206
    |    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.DoReceive() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 174

    That one looks like it coming from the QuicStream on the server when reading incoming data.

  5. JamesNK commented on Jul 7, 2021

    @JamesNK
    JamesNK
    on Jul 7, 2021
    MemberAuthor

    Repo is in dotnet/aspnetcore#34075. Test is called StreamPool_ManyConcurrentStreams_StreamPoolFull.

    Remove the Task.Delay to get bad behavior:

                const int StreamsSent = 101;
            for (var i = 0; i < StreamsSent; i++)
            {
                // TODO: Race condition in QUIC library.
                // Delay between sending streams to avoid
                // https://github.com/dotnet/runtime/issues/55249
                await Task.Delay(50);
                streamTasks.Add(SendStream(requestState));
            }
  6. ManickaP
    removed
    untriagedNew issue has not been triaged by the area owner
    on Jul 7, 2021
  7. ManickaP
    added this to the 6.0.0 milestone on Jul 7, 2021

  8. CarnaViire commented on Jul 15, 2021

    @CarnaViire
    CarnaViire
    on Jul 15, 2021
    Member

    @JamesNK could you please check if this still reproduces after #55505?

  9. JamesNK commented on Jul 17, 2021

    @JamesNK
    JamesNK
    on Jul 17, 2021
    MemberAuthor

    Still fails. Logs below.

    It is complaining about multiple reads on a stream but the way ASP.NET Core uses QuicStream should ensure there will never be multiple reads.

    Details ```  Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull  Source: QuicConnectionContextTests.cs line 378  Duration: 5.2 sec

    Message: 
    System.TimeoutException : The operation has timed out.

    Stack Trace: 
    TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) line 125
    QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() line 411
    QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() line 418
    QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() line 418
    --- End of stack trace from previous location ---

    Standard Output: 
    | [0.008s] TestLifetime Information: Starting test StreamPool_ManyConcurrentStreams_StreamPoolFull at 2021-07-17T00:14:22
    | [0.131s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Connection id "0HMA8MVA4V7N0" accepted.
    | [0.166s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:12" type Bidirectional accepted.
    | [0.166s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:0" type Bidirectional accepted.
    | [0.167s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:16" type Bidirectional accepted.
    | [0.166s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:4" type Bidirectional accepted.
    | [0.167s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:0" type Bidirectional accepted.
    | [0.167s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:8" type Bidirectional accepted.
    | [0.182s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:20" type Bidirectional accepted.
    | [0.182s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:20" type Bidirectional accepted.
    | [0.182s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:20" type Bidirectional accepted.
    | [0.182s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:20" type Bidirectional accepted.
    | [0.183s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:32" type Bidirectional accepted.
    | [0.183s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:28" type Bidirectional accepted.
    | [0.183s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:36" type Bidirectional accepted.
    | [0.183s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:24" type Bidirectional accepted.
    | [0.183s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:40" type Bidirectional accepted.
    | [0.183s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:44" type Bidirectional accepted.
    | [0.183s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:48" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:64" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:60" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:52" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:56" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:68" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:72" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:76" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:80" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:84" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:88" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:92" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:96" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:100" type Bidirectional accepted.
    | [0.184s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:104" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:112" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:108" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:116" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:120" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:124" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:128" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:132" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:136" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:140" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:144" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:148" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:152" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:156" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:160" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:164" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:168" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:172" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:176" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:180" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:184" type Bidirectional accepted.
    | [0.185s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:188" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:192" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:196" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:200" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:204" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:208" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:212" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:216" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:220" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:224" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:228" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:232" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:236" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:240" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:244" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:248" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:252" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:256" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:260" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:268" type Bidirectional accepted.
    | [0.186s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:264" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:272" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:276" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:280" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:284" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:288" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:292" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:296" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:300" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:304" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:308" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:312" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:316" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:320" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:324" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:328" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:332" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:336" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:340" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:344" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:348" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:352" type Bidirectional accepted.
    | [0.187s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:356" type Bidirectional accepted.
    | [0.188s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:360" type Bidirectional accepted.
    | [0.188s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:364" type Bidirectional accepted.
    | [0.188s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:368" type Bidirectional accepted.
    | [0.188s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:372" type Bidirectional accepted.
    | [0.188s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:376" type Bidirectional accepted.
    | [0.188s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:380" type Bidirectional accepted.
    | [0.213s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:64" unexpected error.
    | System.InvalidOperationException: Only one read is supported at a time.
    | at System.Net.Quic.Implementations.MsQuic.MsQuicStream.ReadAsync(Memory1 destination, CancellationToken cancellationToken) in System.Net.Quic.dll:token 0x6000136+0x211 | at System.Net.Quic.QuicStream.ReadAsync(Memory1 buffer, CancellationToken cancellationToken) in System.Net.Quic.dll:token 0x60000a9+0x0
    | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.ProcessReceives() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 220
    | at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in System.Private.CoreLib.dll:token 0x6004ee7+0x28
    | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.ProcessReceives() in Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.dll:token 0x6000100+0x1f
    | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.DoReceive() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 178
    | at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in System.Private.CoreLib.dll:token 0x6004ee7+0x28
    | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.DoReceive() in Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.dll:token 0x60000ff+0x1f
    | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.StartAsync() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 149
    | at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in System.Private.CoreLib.dll:token 0x6004ee7+0x28
    | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.StartAsync() in Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.dll:token 0x60000fe+0x1f
    | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.Start() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 135
    | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicConnectionContext.AcceptAsync(CancellationToken cancellationToken) in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicConnectionContext.cs:line 99
    | at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in System.Private.CoreLib.dll:token 0x6004ee7+0x28
    | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicConnectionContext.AcceptAsync(CancellationToken cancellationToken) in Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.dll:token 0x60000df+0x26
    | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.<StreamPool_ManyConcurrentStreams_StreamPoolFull>g__SendStream|8_0(RequestState requestState) in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\test\QuicConnectionContextTests.cs:line 424
    | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.ExecutionContextCallback(Object s) in System.Private.CoreLib.dll:token 0x6004f12+0x0
    | at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in System.Private.CoreLib.dll:token 0x6002ead+0x40
    | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.MoveNext(Thread threadPoolThread) in System.Private.CoreLib.dll:token 0x6004f16+0x3f
    | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.MoveNext() in System.Private.CoreLib.dll:token 0x6004f15+0x0
    | at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in System.Private.CoreLib.dll:token 0x6003389+0x3b
    | at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in System.Private.CoreLib.dll:token 0x600329b+0x65
    | at System.Threading.Tasks.Task.FinishContinuations() in System.Private.CoreLib.dll:token 0x600329a+0x14
    | at System.Threading.Tasks.Task1.TrySetResult(TResult result) in System.Private.CoreLib.dll:token 0x6003179+0x4b | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.SetExistingTaskResult(Task1 task, TResult result) in System.Private.CoreLib.dll:token 0x6004f0a+0x0 | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetResult() in System.Private.CoreLib.dll:token 0x6004ef8+0x14 | at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) in C:\Development\Source\AspNetCore\src\Shared\TaskExtensions.cs:line 143 | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.ExecutionContextCallback(Object s) in System.Private.CoreLib.dll:token 0x6004f12+0x0 | at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in System.Private.CoreLib.dll:token 0x6002ead+0x40 | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.MoveNext(Thread threadPoolThread) in System.Private.CoreLib.dll:token 0x6004f16+0x3f | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.MoveNext() in System.Private.CoreLib.dll:token 0x6004f15+0x0 | at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in System.Private.CoreLib.dll:token 0x6003389+0x3b | at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in System.Private.CoreLib.dll:token 0x600329b+0x65 | at System.Threading.Tasks.Task.FinishContinuations() in System.Private.CoreLib.dll:token 0x600329a+0x14 | at System.Threading.Tasks.Task1.TrySetResult(TResult result) in System.Private.CoreLib.dll:token 0x6003179+0x4b
    | at System.Threading.Tasks.Task.CancellationPromise1.System.Threading.Tasks.ITaskCompletionAction.Invoke(Task completingTask) in System.Private.CoreLib.dll:token 0x60032f7+0x3c | at System.Threading.Tasks.Task.RunOrQueueCompletionAction(ITaskCompletionAction completionAction, Boolean allowInlining) in System.Private.CoreLib.dll:token 0x600329c+0x0 | at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in System.Private.CoreLib.dll:token 0x600329b+0x90 | at System.Threading.Tasks.Task.FinishContinuations() in System.Private.CoreLib.dll:token 0x600329a+0x14 | at System.Threading.Tasks.Task1.TrySetResult(TResult result) in System.Private.CoreLib.dll:token 0x6003179+0x4b
    | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.SetExistingTaskResult(Task1 task, TResult result) in System.Private.CoreLib.dll:token 0x6004f0a+0x0
    | at System.Runtime.CompilerServices.AsyncValueTaskMethodBuilder.SetResult() in System.Private.CoreLib.dll:token 0x6004f1e+0x14
    | at System.Net.Quic.Implementations.MsQuic.MsQuicStream.WriteAsync(ReadOnlyMemory1 buffer, Boolean endStream, CancellationToken cancellationToken) in System.Net.Quic.dll:token 0x6000132+0xfe | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.ExecutionContextCallback(Object s) in System.Private.CoreLib.dll:token 0x6004f12+0x0 | at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state) in System.Private.CoreLib.dll:token 0x6002eb0+0x15 | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.MoveNext(Thread threadPoolThread) in System.Private.CoreLib.dll:token 0x6004f16+0x4d | at System.Runtime.CompilerServices.AsyncTaskMethodBuilder1.AsyncStateMachineBox1.ExecuteFromThreadPool(Thread threadPoolThread) in System.Private.CoreLib.dll:token 0x6004f14+0x0 | at System.Threading.ThreadPoolWorkQueue.Dispatch() in System.Private.CoreLib.dll:token 0x6002fff+0x0 | at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in System.Private.CoreLib.dll:token 0x60030f9+0x67 | at System.Threading.Thread.StartCallback() in System.Private.CoreLib.dll:token 0x6002c91+0xe | --- End of stack trace from previous location --- | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.ProcessReceives() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 220 | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.DoReceive() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 178 | [0.218s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMA8MVA4V7N0:64" type Bidirectional accepted. | [5.179s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests Error: Test threw an exception. | System.TimeoutException: The operation has timed out. | at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) in C:\Development\Source\AspNetCore\src\Shared\TaskExtensions.cs:line 125 | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\test\QuicConnectionContextTests.cs:line 411 | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\test\QuicConnectionContextTests.cs:line 418 | at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\test\QuicConnectionContextTests.cs:line 418 | at Xunit.Sdk.TestInvoker1.<>c__DisplayClass48_1.<b__1>d.MoveNext() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\Runners\TestInvoker.cs:line 264
    | --- End of stack trace from previous location ---
    | at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func1 asyncAction) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\ExecutionTimer.cs:line 48 | at Xunit.Sdk.ExceptionAggregator.RunAsync(Func1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 90
    | [5.220s] TestLifetime Information: Finished test StreamPool_ManyConcurrentStreams_StreamPoolFull in 5.2171434s

    
</details>

  10. wegylexy commented on Jul 20, 2021

    @wegylexy
    wegylexy
    on Jul 20, 2021
    Contributor

    It also happens to me, with only 2 QUIC streams per connection, only a couple of connections, not using HTTP/3, just purely QUIC. The stack trace is not consistent, but the top is always

    System.InvalidOperationException: Operation is not valid due to the current state of the object.
   at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1.OnCompleted(Action`1 continuation, Object state, Int16 token, ValueTaskSourceOnCompletedFlags flags) in System.Private.CoreLib.dll

    sometimes with

       at System.Net.Quic.Implementations.MsQuic.Internal.ResettableCompletionSource`1.OnCompleted(Action`1 continuation, Object state, Int16 token, ValueTaskSourceOnCompletedFlags flags)

    in between but always followed by

       at System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable.ConfiguredValueTaskAwaiter.System.Runtime.CompilerServices.IStateMachineBoxAwareAwaiter.AwaitUnsafeOnCompleted(IAsyncStateMachineBox box) in System.Private.CoreLib.dll

    The worst thing is that try-catch doesn't catch it, and the program crashes with Unhandled exception.

  11. CarnaViire
    self-assigned this
    on Jul 22, 2021

  12. karelz commented on Jul 22, 2021

    @karelz
    karelz
    on Jul 22, 2021
    Member

    Triage: Lower priority, unless it is problem when going up to 10 parallel requests.

  13. karelz
    unassigned
    CarnaViire
    on Jul 22, 2021

  14. JamesNK commented on Jul 22, 2021

    @JamesNK
    JamesNK
    on Jul 22, 2021
    MemberAuthor

    I've tested and it fails with even 10 parallel requests. I'm going to move it back to high priority.

    Logs:

     Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull
   Source: QuicConnectionContextTests.cs line 380
   Duration: 5.2 sec

  Message: 
System.TimeoutException : The operation has timed out.

  Stack Trace: 
TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) line 125
QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() line 417
QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() line 424
QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() line 424
--- End of stack trace from previous location ---

  Standard Output: 
| [0.008s] TestLifetime Information: Starting test StreamPool_ManyConcurrentStreams_StreamPoolFull at 2021-07-22T20:16:28
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#61688809,.ctor,[list][0x1F83E7846E0] Listener created ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#61688809,.ctor,[list][0x1F83E7846E0] Listener started ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2852789,.ctor,[conn][0x1F83E789FA0] Outbound connection created ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,.ctor,[conn][0x1F83E962F30] Inbound connection created ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event IDEAL_PROCESSOR_CHANGED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2852789,NativeCallbackHandler,[conn][0x1F83E789FA0] Connection received event STREAMS_AVAILABLE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2852789,NativeCallbackHandler,[conn][0x1F83E789FA0] Connection received event DATAGRAM_STATE_CHANGED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2852789,NativeCallbackHandler,[conn][0x1F83E789FA0] Connection received event PEER_CERTIFICATE_RECEIVED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2852789,NativeCallbackHandler,[conn][0x1F83E789FA0] Connection received event CONNECTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2852789,NativeCallbackHandler,[conn][0x1F83E789FA0] Connection received event IDEAL_PROCESSOR_CHANGED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event CONNECTED ->
| [0.142s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Connection id "0HMAD9MBGBROO" accepted.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#21647132,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#21647132,.ctor,[strm][0x1F83E78D560] Outbound bidirectional stream created in connection [conn][0x1F83E789FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#21647132,HandleEvent,[strm][0x1F83E78D560] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36736776,.ctor,[strm][0x1F83E78D820] Inbound bidirectional stream created in connection [conn][0x1F83E962F30]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36736776,HandleEvent,[strm][0x1F83E78D820] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#21647132,HandleEvent,[strm][0x1F83E78D560] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64538993,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64538993,.ctor,[strm][0x1F83E78DAE0] Outbound bidirectional stream created in connection [conn][0x1F83E789FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64538993,HandleEvent,[strm][0x1F83E78DAE0] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13726014,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13726014,.ctor,[strm][0x1F83E99BA50] Outbound bidirectional stream created in connection [conn][0x1F83E789FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13726014,HandleEvent,[strm][0x1F83E99BA50] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#62474978,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#62474978,.ctor,[strm][0x1F83E977600] Outbound bidirectional stream created in connection [conn][0x1F83E789FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64379541,.ctor,[strm][0x1F83E9778C0] Inbound bidirectional stream created in connection [conn][0x1F83E962F30]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2086040,.ctor,[strm][0x1F83E978150] Inbound bidirectional stream created in connection [conn][0x1F83E962F30]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64379541,HandleEvent,[strm][0x1F83E9778C0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2086040,HandleEvent,[strm][0x1F83E978150] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#62474978,HandleEvent,[strm][0x1F83E977600] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18063220,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18063220,.ctor,[strm][0x1F83EB01090] Outbound bidirectional stream created in connection [conn][0x1F83E789FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64538993,HandleEvent,[strm][0x1F83E78DAE0] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18063220,HandleEvent,[strm][0x1F83EB01090] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43546682,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43546682,.ctor,[strm][0x1F83EB14B90] Outbound bidirectional stream created in connection [conn][0x1F83E789FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24791236,.ctor,[strm][0x1F83EB15ED0] Inbound bidirectional stream created in connection [conn][0x1F83E962F30]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64929777,.ctor,[strm][0x1F83EB15110] Inbound bidirectional stream created in connection [conn][0x1F83E962F30]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24791236,HandleEvent,[strm][0x1F83EB15ED0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64929777,HandleEvent,[strm][0x1F83EB15110] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43546682,HandleEvent,[strm][0x1F83EB14B90] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#42253292,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#42253292,.ctor,[strm][0x1F83EB14E50] Outbound bidirectional stream created in connection [conn][0x1F83E789FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13726014,HandleEvent,[strm][0x1F83E99BA50] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#62474978,HandleEvent,[strm][0x1F83E977600] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18063220,HandleEvent,[strm][0x1F83EB01090] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#42253292,HandleEvent,[strm][0x1F83EB14E50] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64591461,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64591461,.ctor,[strm][0x1F83EB148D0] Outbound bidirectional stream created in connection [conn][0x1F83E789FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#17556181,.ctor,[strm][0x1F83EB153D0] Inbound bidirectional stream created in connection [conn][0x1F83E962F30]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#17556181,HandleEvent,[strm][0x1F83EB153D0] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64591461,HandleEvent,[strm][0x1F83EB148D0] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6532797,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6532797,.ctor,[strm][0x1F83EB15C10] Outbound bidirectional stream created in connection [conn][0x1F83E789FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6532797,HandleEvent,[strm][0x1F83EB15C10] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#7132134,HandleEvent,(null) Stream received event START_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#7132134,.ctor,[strm][0x1F83EB15690] Outbound bidirectional stream created in connection [conn][0x1F83E789FA0]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#50883745,.ctor,[strm][0x1F83EB15950] Inbound bidirectional stream created in connection [conn][0x1F83E962F30]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#23525895,.ctor,[strm][0x1F83EB16190] Inbound bidirectional stream created in connection [conn][0x1F83E962F30]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#50883745,HandleEvent,[strm][0x1F83EB15950] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#39668794,.ctor,[strm][0x1F83EB14610] Inbound bidirectional stream created in connection [conn][0x1F83E962F30]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#23525895,HandleEvent,[strm][0x1F83EB16190] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#39668794,HandleEvent,[strm][0x1F83EB14610] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#7132134,HandleEvent,[strm][0x1F83EB15690] Stream received event SEND_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43546682,HandleEvent,[strm][0x1F83EB14B90] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#42253292,HandleEvent,[strm][0x1F83EB14E50] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64591461,HandleEvent,[strm][0x1F83EB148D0] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event PEER_STREAM_STARTED ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#10140833,.ctor,[strm][0x1F83EB37A60] Inbound bidirectional stream created in connection [conn][0x1F83E962F30]. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#10140833,HandleEvent,[strm][0x1F83EB37A60] Stream received event RECEIVE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6532797,HandleEvent,[strm][0x1F83EB15C10] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#7132134,HandleEvent,[strm][0x1F83EB15690] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64929777,ReadAsync,[strm][0x1F83EB15110] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24791236,ReadAsync,[strm][0x1F83EB15ED0] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#17556181,ReadAsync,[strm][0x1F83EB153D0] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2086040,ReadAsync,[strm][0x1F83E978150] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64379541,ReadAsync,[strm][0x1F83E9778C0] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36736776,ReadAsync,[strm][0x1F83E78D820] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64379541,HandleEvent,[strm][0x1F83E9778C0] Stream received event PEER_SEND_SHUTDOWN ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64379541,HandleEventPeerSendShutdown,[strm][0x1F83E9778C0] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64929777,HandleEvent,[strm][0x1F83EB15110] Stream received event PEER_SEND_SHUTDOWN ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64929777,HandleEventPeerSendShutdown,[strm][0x1F83EB15110] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36736776,HandleEvent,[strm][0x1F83E78D820] Stream received event PEER_SEND_SHUTDOWN ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36736776,HandleEventPeerSendShutdown,[strm][0x1F83E78D820] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#17556181,HandleEvent,[strm][0x1F83EB153D0] Stream received event PEER_SEND_SHUTDOWN ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#17556181,HandleEventPeerSendShutdown,[strm][0x1F83EB153D0] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24791236,HandleEvent,[strm][0x1F83EB15ED0] Stream received event PEER_SEND_SHUTDOWN ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24791236,HandleEventPeerSendShutdown,[strm][0x1F83EB15ED0] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2086040,HandleEvent,[strm][0x1F83E978150] Stream received event PEER_SEND_SHUTDOWN ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2086040,HandleEventPeerSendShutdown,[strm][0x1F83E978150] Stream completing resettable event source. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64379541,ReadAsync,[strm][0x1F83E9778C0] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#17556181,ReadAsync,[strm][0x1F83EB153D0] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24791236,ReadAsync,[strm][0x1F83EB15ED0] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64929777,ReadAsync,[strm][0x1F83EB15110] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36736776,ReadAsync,[strm][0x1F83E78D820] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2086040,ReadAsync,[strm][0x1F83E978150] Stream reading into Memory of '4096' bytes. ->
| [0.179s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMAD9MBGBROO:4" type Bidirectional accepted.
| [0.179s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMAD9MBGBROO:8" type Bidirectional accepted.
| [0.179s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMAD9MBGBROO:12" type Bidirectional accepted.
| [0.179s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMAD9MBGBROO:0" type Bidirectional accepted.
| [0.179s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMAD9MBGBROO:20" type Bidirectional accepted.
| [0.179s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMAD9MBGBROO:16" type Bidirectional accepted.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#50883745,ReadAsync,[strm][0x1F83EB15950] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#50883745,ReadAsync,[strm][0x1F83EB15950] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#50883745,ReadAsync,[strm][0x1F83EB15950] Stream reading into Memory of '4096' bytes. ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#50883745,HandleEvent,[strm][0x1F83EB15950] Stream received event PEER_SEND_SHUTDOWN ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#50883745,HandleEventPeerSendShutdown,[strm][0x1F83EB15950] Stream completing resettable event source. ->
| [0.194s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMAD9MBGBROO:24" type Bidirectional accepted.
| [0.225s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMAD9MBGBROO:24" unexpected error.
| System.InvalidOperationException: Only one read is supported at a time.
|    at System.Net.Quic.Implementations.MsQuic.MsQuicStream.ReadAsync(Memory`1 destination, CancellationToken cancellationToken) in System.Net.Quic.dll:token 0x6000137+0x211
|    at System.Net.Quic.QuicStream.ReadAsync(Memory`1 buffer, CancellationToken cancellationToken) in System.Net.Quic.dll:token 0x60000aa+0x0
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.ProcessReceives() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 226
|    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in System.Private.CoreLib.dll:token 0x6004ee6+0x28
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.ProcessReceives() in Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.dll:token 0x60000fe+0x1f
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.DoReceive() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 184
|    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in System.Private.CoreLib.dll:token 0x6004ee6+0x28
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.DoReceive() in Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.dll:token 0x60000fd+0x1f
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.StartAsync() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 155
|    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in System.Private.CoreLib.dll:token 0x6004ee6+0x28
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.StartAsync() in Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.dll:token 0x60000fc+0x1f
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.Start() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 141
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicConnectionContext.AcceptAsync(CancellationToken cancellationToken) in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicConnectionContext.cs:line 99
|    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine) in System.Private.CoreLib.dll:token 0x6004ee6+0x28
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicConnectionContext.AcceptAsync(CancellationToken cancellationToken) in Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.dll:token 0x60000dd+0x26
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.<StreamPool_ManyConcurrentStreams_StreamPoolFull>g__SendStream|8_0(RequestState requestState) in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\test\QuicConnectionContextTests.cs:line 430
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s) in System.Private.CoreLib.dll:token 0x6004f11+0x0
|    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in System.Private.CoreLib.dll:token 0x6002eab+0x40
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread) in System.Private.CoreLib.dll:token 0x6004f15+0x3f
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext() in System.Private.CoreLib.dll:token 0x6004f14+0x0
|    at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in System.Private.CoreLib.dll:token 0x6003387+0x3b
|    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in System.Private.CoreLib.dll:token 0x6003299+0x65
|    at System.Threading.Tasks.Task.FinishContinuations() in System.Private.CoreLib.dll:token 0x6003298+0x14
|    at System.Threading.Tasks.Task`1.TrySetResult(TResult result) in System.Private.CoreLib.dll:token 0x6003177+0x4b
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result) in System.Private.CoreLib.dll:token 0x6004f09+0x0
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder.SetResult() in System.Private.CoreLib.dll:token 0x6004ef7+0x14
|    at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) in C:\Development\Source\AspNetCore\src\Shared\TaskExtensions.cs:line 143
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s) in System.Private.CoreLib.dll:token 0x6004f11+0x0
|    at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) in System.Private.CoreLib.dll:token 0x6002eab+0x40
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread) in System.Private.CoreLib.dll:token 0x6004f15+0x3f
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext() in System.Private.CoreLib.dll:token 0x6004f14+0x0
|    at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining) in System.Private.CoreLib.dll:token 0x6003387+0x3b
|    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in System.Private.CoreLib.dll:token 0x6003299+0x65
|    at System.Threading.Tasks.Task.FinishContinuations() in System.Private.CoreLib.dll:token 0x6003298+0x14
|    at System.Threading.Tasks.Task`1.TrySetResult(TResult result) in System.Private.CoreLib.dll:token 0x6003177+0x4b
|    at System.Threading.Tasks.Task.CancellationPromise`1.System.Threading.Tasks.ITaskCompletionAction.Invoke(Task completingTask) in System.Private.CoreLib.dll:token 0x60032f5+0x3c
|    at System.Threading.Tasks.Task.RunOrQueueCompletionAction(ITaskCompletionAction completionAction, Boolean allowInlining) in System.Private.CoreLib.dll:token 0x600329a+0x0
|    at System.Threading.Tasks.Task.RunContinuations(Object continuationObject) in System.Private.CoreLib.dll:token 0x6003299+0x90
|    at System.Threading.Tasks.Task.FinishContinuations() in System.Private.CoreLib.dll:token 0x6003298+0x14
|    at System.Threading.Tasks.Task`1.TrySetResult(TResult result) in System.Private.CoreLib.dll:token 0x6003177+0x4b
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result) in System.Private.CoreLib.dll:token 0x6004f09+0x0
|    at System.Runtime.CompilerServices.AsyncValueTaskMethodBuilder.SetResult() in System.Private.CoreLib.dll:token 0x6004f1d+0x14
|    at System.Net.Quic.Implementations.MsQuic.MsQuicStream.WriteAsync(ReadOnlyMemory`1 buffer, Boolean endStream, CancellationToken cancellationToken) in System.Net.Quic.dll:token 0x6000133+0xfe
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s) in System.Private.CoreLib.dll:token 0x6004f11+0x0
|    at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state) in System.Private.CoreLib.dll:token 0x6002eae+0x15
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread) in System.Private.CoreLib.dll:token 0x6004f15+0x4d
|    at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecuteFromThreadPool(Thread threadPoolThread) in System.Private.CoreLib.dll:token 0x6004f13+0x0
|    at System.Threading.ThreadPoolWorkQueue.Dispatch() in System.Private.CoreLib.dll:token 0x6002ffd+0x0
|    at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in System.Private.CoreLib.dll:token 0x60030f7+0x67
|    at System.Threading.Thread.StartCallback() in System.Private.CoreLib.dll:token 0x6002c8f+0xe
| --- End of stack trace from previous location ---
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.ProcessReceives() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 226
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal.QuicStreamContext.DoReceive() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\src\Internal\QuicStreamContext.cs:line 184
| [0.226s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic Debug: Stream id "0HMAD9MBGBROO:24" type Bidirectional accepted.
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36736776,HandleEvent,[strm][0x1F83E78D820] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36736776,HandleEvent,[strm][0x1F83E78D820] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#36736776,HandleEventConnectionClose,[strm][0x1F83E78D820] Stream handling connection [conn][0x1F83E962F30] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64379541,HandleEvent,[strm][0x1F83E9778C0] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64379541,HandleEvent,[strm][0x1F83E9778C0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64379541,HandleEventConnectionClose,[strm][0x1F83E9778C0] Stream handling connection [conn][0x1F83E962F30] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2086040,HandleEvent,[strm][0x1F83E978150] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2086040,HandleEvent,[strm][0x1F83E978150] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2086040,HandleEventConnectionClose,[strm][0x1F83E978150] Stream handling connection [conn][0x1F83E962F30] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24791236,HandleEvent,[strm][0x1F83EB15ED0] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24791236,HandleEvent,[strm][0x1F83EB15ED0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#24791236,HandleEventConnectionClose,[strm][0x1F83EB15ED0] Stream handling connection [conn][0x1F83E962F30] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64929777,HandleEvent,[strm][0x1F83EB15110] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64929777,HandleEvent,[strm][0x1F83EB15110] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64929777,HandleEventConnectionClose,[strm][0x1F83EB15110] Stream handling connection [conn][0x1F83E962F30] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#17556181,HandleEvent,[strm][0x1F83EB153D0] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#17556181,HandleEvent,[strm][0x1F83EB153D0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#17556181,HandleEventConnectionClose,[strm][0x1F83EB153D0] Stream handling connection [conn][0x1F83E962F30] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#50883745,HandleEvent,[strm][0x1F83EB15950] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#50883745,HandleEvent,[strm][0x1F83EB15950] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#50883745,HandleEventConnectionClose,[strm][0x1F83EB15950] Stream handling connection [conn][0x1F83E962F30] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#23525895,HandleEvent,[strm][0x1F83EB16190] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#23525895,HandleEvent,[strm][0x1F83EB16190] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#23525895,HandleEventConnectionClose,[strm][0x1F83EB16190] Stream handling connection [conn][0x1F83E962F30] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#39668794,HandleEvent,[strm][0x1F83EB14610] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#39668794,HandleEvent,[strm][0x1F83EB14610] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#39668794,HandleEventConnectionClose,[strm][0x1F83EB14610] Stream handling connection [conn][0x1F83E962F30] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#10140833,HandleEvent,[strm][0x1F83EB37A60] Stream received event SEND_SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#10140833,HandleEvent,[strm][0x1F83EB37A60] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#10140833,HandleEventConnectionClose,[strm][0x1F83EB37A60] Stream handling connection [conn][0x1F83E962F30] close ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2852789,NativeCallbackHandler,[conn][0x1F83E789FA0] Connection received event SHUTDOWN_INITIATED_BY_PEER ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#21647132,HandleEvent,[strm][0x1F83E78D560] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#21647132,HandleEventConnectionClose,[strm][0x1F83E78D560] Stream handling connection [conn][0x1F83E789FA0] close with code 0 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64538993,HandleEvent,[strm][0x1F83E78DAE0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64538993,HandleEventConnectionClose,[strm][0x1F83E78DAE0] Stream handling connection [conn][0x1F83E789FA0] close with code 0 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13726014,HandleEvent,[strm][0x1F83E99BA50] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#13726014,HandleEventConnectionClose,[strm][0x1F83E99BA50] Stream handling connection [conn][0x1F83E789FA0] close with code 0 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#62474978,HandleEvent,[strm][0x1F83E977600] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#62474978,HandleEventConnectionClose,[strm][0x1F83E977600] Stream handling connection [conn][0x1F83E789FA0] close with code 0 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18063220,HandleEvent,[strm][0x1F83EB01090] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#18063220,HandleEventConnectionClose,[strm][0x1F83EB01090] Stream handling connection [conn][0x1F83E789FA0] close with code 0 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43546682,HandleEvent,[strm][0x1F83EB14B90] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#43546682,HandleEventConnectionClose,[strm][0x1F83EB14B90] Stream handling connection [conn][0x1F83E789FA0] close with code 0 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#42253292,HandleEvent,[strm][0x1F83EB14E50] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#42253292,HandleEventConnectionClose,[strm][0x1F83EB14E50] Stream handling connection [conn][0x1F83E789FA0] close with code 0 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64591461,HandleEvent,[strm][0x1F83EB148D0] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#64591461,HandleEventConnectionClose,[strm][0x1F83EB148D0] Stream handling connection [conn][0x1F83E789FA0] close with code 0 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6532797,HandleEvent,[strm][0x1F83EB15C10] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#6532797,HandleEventConnectionClose,[strm][0x1F83EB15C10] Stream handling connection [conn][0x1F83E789FA0] close with code 0 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#7132134,HandleEvent,[strm][0x1F83EB15690] Stream received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#7132134,HandleEventConnectionClose,[strm][0x1F83EB15690] Stream handling connection [conn][0x1F83E789FA0] close with code 0 ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,NativeCallbackHandler,[conn][0x1F83E962F30] Connection received event SHUTDOWN_COMPLETE ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#49538252,Dispose,[conn][0x1F83E962F30] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#23525895,Dispose,[strm][0x1F83EB16190] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#23525895,Dispose,[strm][0x1F83EB16190] Stream disposed ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#39668794,Dispose,[strm][0x1F83EB14610] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#39668794,Dispose,[strm][0x1F83EB14610] Stream disposed ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#10140833,Dispose,[strm][0x1F83EB37A60] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#10140833,Dispose,[strm][0x1F83EB37A60] Stream disposed ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2852789,Dispose,[conn][0x1F83E789FA0] Stream disposing True ->
<- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2852789,NativeCallbackHandler,[conn][0x1F83E789FA0] Connection received event SHUTDOWN_COMPLETE ->
| [5.180s] Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests Error: Test threw an exception.
| System.TimeoutException: The operation has timed out.
|    at Microsoft.AspNetCore.Testing.TaskExtensions.TimeoutAfter(Task task, TimeSpan timeout, String filePath, Int32 lineNumber) in C:\Development\Source\AspNetCore\src\Shared\TaskExtensions.cs:line 125
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\test\QuicConnectionContextTests.cs:line 417
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\test\QuicConnectionContextTests.cs:line 424
|    at Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull() in C:\Development\Source\AspNetCore\src\Servers\Kestrel\Transport.Quic\test\QuicConnectionContextTests.cs:line 424
|    at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_1.<<InvokeTestMethodAsync>b__1>d.MoveNext() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\Runners\TestInvoker.cs:line 264
| --- End of stack trace from previous location ---
|    at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\ExecutionTimer.cs:line 48
|    at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 90
| [5.222s] TestLifetime Information: Finished test StreamPool_ManyConcurrentStreams_StreamPoolFull in 5.2192827s

  15. wfurt commented on Jul 22, 2021

    @wfurt
    wfurt
    on Jul 22, 2021
    Member
    <- Event Private.InternalDiagnostics.System.Net.Quic - Info : State#2852789,NativeCallbackHandler,[conn][0x1F83E789FA0] Connection received event SHUTDOWN_INITIATED_BY_PEER ->

    where this comes from?

    is there asp.net test that demonstrates that? (or better yet add test ton runtime or have standalone repro)

  16. 6 remaining items

  17. wegylexy commented on Jul 23, 2021

    @wegylexy
    wegylexy
    on Jul 23, 2021
    Contributor

    Try to assert if they are indeed different streams, i.e. no concurrent IO within a stream?

  18. JamesNK commented on Jul 23, 2021

    @JamesNK
    JamesNK
    on Jul 23, 2021
    MemberAuthor

    There shouldn't be any concurrent reads or concurrent writes on a stream.

    Kestrel reads and writes with QuicStream using simple loops:

    A read and write could happen at the same time, but that shouldn't be a problem.

  19. wfurt commented on Aug 3, 2021

    @wfurt
    wfurt
    on Aug 3, 2021
    Member

    I was able to reproduce it but it is pretty rare for me. I also see some other failures, timeouts and

    [xUnit.net 00:00:01.53]     Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull [FAIL]
  Failed Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Tests.QuicConnectionContextTests.StreamPool_ManyConcurrentStreams_StreamPoolFull [568 ms]
  Error Message:
   Assert.Equal() Failure
Expected: 10
Actual:   9

    Thew timeouts are mostly coming from await allConnectionsOnServerTcs.

  20. wfurt
    self-assigned this
    on Aug 3, 2021

  21. ManickaP commented on Aug 10, 2021

    @ManickaP
    ManickaP
    on Aug 10, 2021
    Member

    @JamesNK so is this issue fixed from your point of view?
    We're not 100% sure the change we made should fix this, but for now this might be mitigated and at least punted.

  22. ManickaP
    unassigned
    wfurt
    on Aug 10, 2021
  23. ManickaP
    modified the milestones: 6.0.0, Future on Aug 10, 2021

  24. karelz commented on Nov 16, 2021

    @karelz
    karelz
    on Nov 16, 2021
    Member

    Looks like it is addressed by PR #56768

  25. karelz
    closed this as completedon Nov 16, 2021
  26. karelz
    modified the milestones: Future, 7.0.0 on Nov 16, 2021
  27. karelz
    added
    bug
    tenet-reliabilityReliability/stability related issue (stress, load problems, etc.)
    on Nov 16, 2021
  28. ghost locked as resolved and limited conversation to collaborators on Dec 16, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    area-System.Net.Quicbugtenet-reliabilityReliability/stability related issue (stress, load problems, etc.)

    Type

    No type

    Projects

    No projects

      Milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions