failfast in native code invoked by MsQuicStream.Dispose in CI

[jakobbotsch]

Seen in #68922 on win-x86.
Run: https://dev.azure.com/dnceng/public/_build/results?buildId=1754498&view=logs&jobId=457f7e88-dfa2-5bd9-f871-fdf124c2477d
Log: https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-68922-merge-f0ab2c259372473799/System.Net.Http.Functional.Tests/1/console.68ce3ff2.log?helixlogtype=result

The log shows

    System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_Cookies_Http3_MsQuic.GetAsync_SetCookieContainer_CookieSent(cookieName: "foo", cookieValue: "bar", useCookies: True) [FAIL]
      Assert.Throws() Failure
      Expected: typeof(System.Net.Quic.QuicConnectionAbortedException)
      Actual:   typeof(System.NullReferenceException): Object reference not set to an instance of an object.
      ---- System.NullReferenceException : Object reference not set to an instance of an object.
      Stack Trace:
        /_/src/libraries/Common/tests/System/Net/Http/Http3LoopbackConnection.cs(300,0): at System.Net.Test.Common.Http3LoopbackConnection.<WaitForClientDisconnectAsync>b__43_0()

But when looking at the dump it shows a failfast inside msquic!CxPlatRefIncrement with
Subcode: 0xe FAST_FAIL_INVALID_REFERENCE_COUNT . Upper frames of the stack:

0:031> k
 # ChildEBP RetAddr      
00 (Inline) --------     msquic!CxPlatRefIncrement+0x15 [D:\a\_work\1\s\src\msquic\src\inc\quic_platform_winuser.h @ 466] 
01 1365e268 73318894     msquic!QuicStreamAddRef+0x15 [D:\a\_work\1\s\src\msquic\src\core\stream.h @ 626] 
02 1365e268 0eac5db4     msquic!MsQuicStreamShutdown+0x1a4 [D:\a\_work\1\s\src\msquic\src\core\api.c @ 985] 
03 1365e2f0 15320db3     System_Net_Quic!System.Net.Quic.Implementations.MsQuic.MsQuicStream.Dispose(Boolean)+0xfc78079c
04 1365e2fc 1537fb6f     System_Net_Quic!System.Net.Quic.Implementations.MsQuic.MsQuicStream.Dispose()+0x2fdb7d3
05 1365e30c 1537e42f     System_Net_Http!System.Net.Http.Http3RequestStream.Dispose()+0x29b02ff
06 1365e320 125a7d78     System_Net_Http!System.Net.Http.Http3RequestStream+Http3ReadStream.Dispose(Boolean)+0x29aec67
07 1365e334 125a52f5     System_Private_CoreLib!System.IO.Stream.Close()+0xa7643d78
08 1365e348 158f22f7     System_Private_CoreLib!System.IO.Stream.Dispose()+0xa7641345
09 1365e390 158f2b63     System_Net_Http!System.Net.Http.HttpConnectionResponseContent+<<SerializeToStreamAsync>g__Impl|6_0>d.MoveNext()+0x3d811e7
0a 1365e3c4 158f2ad5     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[System.Net.Http.HttpContent+<WaitAndReturnAsync>d__82`2[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]], System.Net.Http]](<WaitAndReturnAsync>d__82`2<System.__Canon,System.__Canon> ByRef)+0x3281063
0b 1365e3ec 158f2a74     System_Net_Http!System.Net.Http.HttpConnectionResponseContent.<SerializeToStreamAsync>g__Impl|6_0(System.IO.Stream, System.Net.TransportContext, System.Threading.CancellationToken)+0x3d81b3d
0c 1365e3fc 158d0081     System_Net_Http!System.Net.Http.HttpConnectionResponseContent.SerializeToStreamAsync(System.IO.Stream, System.Net.TransportContext, System.Threading.CancellationToken)+0x3d81b24
0d 1365e434 126d9d2c     System_Net_Http!System.Net.Http.HttpContent.LoadIntoBufferAsync(Int64, System.Threading.CancellationToken)+0x6b99891
0e 1365e498 158da38e     System_Net_Http!System.Net.Http.HttpClient+<<SendAsync>g__Core|83_0>d.MoveNext()+0x49994dc
0f 1365e4a0 125360da     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[System.Net.Http.Functional.Tests.HttpContentTest+<ReadAsStreamAsync_GetFromBufferedContent_SucceedsAfterReadAsStream>d__19, System.Net.Http.Functional.Tests]].ExecutionContextCallback(System.Object)+0x6dcb13e
10 1365e4d4 158da292     System_Private_CoreLib!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0xa768827a
11 1365e4fc 158da1b8     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[System.Net.Http.Functional.Tests.HttpContentTest+<ReadAsStreamAsync_GetFromBufferedContent_SucceedsAfterReadAsStream>d__19, System.Net.Http.Functional.Tests]].MoveNext(System.Threading.Thread)+0x6dcb1a2
12 1365e530 12536891     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[System.Net.Http.Functional.Tests.HttpContentTest+<ReadAsStreamAsync_GetFromBufferedContent_SucceedsAfterReadAsStream>d__19, System.Net.Http.Functional.Tests]].MoveNext()+0x6dcb0f0
13 1365e530 1253623c     System_Private_CoreLib!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+0xa766e4e1
14 1365e584 12537cf7     System_Private_CoreLib!System.Threading.Tasks.Task.RunContinuations(System.Object)+0xa767266c
15 1365e59c 12537dda     System_Private_CoreLib!System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+0xa74f78c7
16 1365e5b0 0e650d36     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, System.Private.CoreLib]].SetExistingTaskResult(System.Threading.Tasks.Task`1<System.__Canon>, System.__Canon)+0xa74f241a
17 1365e6cc 126f703e     System_Net_Http!System.Net.Http.RedirectHandler+<SendAsync>d__4.MoveNext()+0xd16

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

Issue Details

---

Seen in #68922 on win-x86.
Run: https://dev.azure.com/dnceng/public/_build/results?buildId=1754498&view=logs&jobId=457f7e88-dfa2-5bd9-f871-fdf124c2477d
Log: https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-68922-merge-f0ab2c259372473799/System.Net.Http.Functional.Tests/1/console.68ce3ff2.log?helixlogtype=result

The log shows

    System.Net.Http.Functional.Tests.SocketsHttpHandlerTest_Cookies_Http3_MsQuic.GetAsync_SetCookieContainer_CookieSent(cookieName: "foo", cookieValue: "bar", useCookies: True) [FAIL]
      Assert.Throws() Failure
      Expected: typeof(System.Net.Quic.QuicConnectionAbortedException)
      Actual:   typeof(System.NullReferenceException): Object reference not set to an instance of an object.
      ---- System.NullReferenceException : Object reference not set to an instance of an object.
      Stack Trace:
        /_/src/libraries/Common/tests/System/Net/Http/Http3LoopbackConnection.cs(300,0): at System.Net.Test.Common.Http3LoopbackConnection.<WaitForClientDisconnectAsync>b__43_0()

But when looking at the dump it shows a failfast inside msquic!CxPlatRefIncrement with
Subcode: 0xe FAST_FAIL_INVALID_REFERENCE_COUNT . Upper frames of the stack:

0:031> k
 # ChildEBP RetAddr      
00 (Inline) --------     msquic!CxPlatRefIncrement+0x15 [D:\a\_work\1\s\src\msquic\src\inc\quic_platform_winuser.h @ 466] 
01 1365e268 73318894     msquic!QuicStreamAddRef+0x15 [D:\a\_work\1\s\src\msquic\src\core\stream.h @ 626] 
02 1365e268 0eac5db4     msquic!MsQuicStreamShutdown+0x1a4 [D:\a\_work\1\s\src\msquic\src\core\api.c @ 985] 
03 1365e2f0 15320db3     System_Net_Quic!System.Net.Quic.Implementations.MsQuic.MsQuicStream.Dispose(Boolean)+0xfc78079c
04 1365e2fc 1537fb6f     System_Net_Quic!System.Net.Quic.Implementations.MsQuic.MsQuicStream.Dispose()+0x2fdb7d3
05 1365e30c 1537e42f     System_Net_Http!System.Net.Http.Http3RequestStream.Dispose()+0x29b02ff
06 1365e320 125a7d78     System_Net_Http!System.Net.Http.Http3RequestStream+Http3ReadStream.Dispose(Boolean)+0x29aec67
07 1365e334 125a52f5     System_Private_CoreLib!System.IO.Stream.Close()+0xa7643d78
08 1365e348 158f22f7     System_Private_CoreLib!System.IO.Stream.Dispose()+0xa7641345
09 1365e390 158f2b63     System_Net_Http!System.Net.Http.HttpConnectionResponseContent+<<SerializeToStreamAsync>g__Impl|6_0>d.MoveNext()+0x3d811e7
0a 1365e3c4 158f2ad5     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[System.Net.Http.HttpContent+<WaitAndReturnAsync>d__82`2[[System.__Canon, System.Private.CoreLib],[System.__Canon, System.Private.CoreLib]], System.Net.Http]](<WaitAndReturnAsync>d__82`2<System.__Canon,System.__Canon> ByRef)+0x3281063
0b 1365e3ec 158f2a74     System_Net_Http!System.Net.Http.HttpConnectionResponseContent.<SerializeToStreamAsync>g__Impl|6_0(System.IO.Stream, System.Net.TransportContext, System.Threading.CancellationToken)+0x3d81b3d
0c 1365e3fc 158d0081     System_Net_Http!System.Net.Http.HttpConnectionResponseContent.SerializeToStreamAsync(System.IO.Stream, System.Net.TransportContext, System.Threading.CancellationToken)+0x3d81b24
0d 1365e434 126d9d2c     System_Net_Http!System.Net.Http.HttpContent.LoadIntoBufferAsync(Int64, System.Threading.CancellationToken)+0x6b99891
0e 1365e498 158da38e     System_Net_Http!System.Net.Http.HttpClient+<<SendAsync>g__Core|83_0>d.MoveNext()+0x49994dc
0f 1365e4a0 125360da     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[System.Net.Http.Functional.Tests.HttpContentTest+<ReadAsStreamAsync_GetFromBufferedContent_SucceedsAfterReadAsStream>d__19, System.Net.Http.Functional.Tests]].ExecutionContextCallback(System.Object)+0x6dcb13e
10 1365e4d4 158da292     System_Private_CoreLib!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0xa768827a
11 1365e4fc 158da1b8     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[System.Net.Http.Functional.Tests.HttpContentTest+<ReadAsStreamAsync_GetFromBufferedContent_SucceedsAfterReadAsStream>d__19, System.Net.Http.Functional.Tests]].MoveNext(System.Threading.Thread)+0x6dcb1a2
12 1365e530 12536891     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[[System.Threading.Tasks.VoidTaskResult, System.Private.CoreLib],[System.Net.Http.Functional.Tests.HttpContentTest+<ReadAsStreamAsync_GetFromBufferedContent_SucceedsAfterReadAsStream>d__19, System.Net.Http.Functional.Tests]].MoveNext()+0x6dcb0f0
13 1365e530 1253623c     System_Private_CoreLib!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(System.Runtime.CompilerServices.IAsyncStateMachineBox, Boolean)+0xa766e4e1
14 1365e584 12537cf7     System_Private_CoreLib!System.Threading.Tasks.Task.RunContinuations(System.Object)+0xa767266c
15 1365e59c 12537dda     System_Private_CoreLib!System.Threading.Tasks.Task`1[[System.__Canon, System.Private.CoreLib]].TrySetResult(System.__Canon)+0xa74f78c7
16 1365e5b0 0e650d36     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[[System.__Canon, System.Private.CoreLib]].SetExistingTaskResult(System.Threading.Tasks.Task`1<System.__Canon>, System.__Canon)+0xa74f241a
17 1365e6cc 126f703e     System_Net_Http!System.Net.Http.RedirectHandler+<SendAsync>d__4.MoveNext()+0xd16

Author:	jakobbotsch
Assignees:	-
Labels:	area-System.Net.Http
Milestone:	-

[jkotas]

cc @ManickaP This crash was likely introduced by the reverted #68288. It would be a good idea to get it fixed before we try to merge it again.

[ManickaP]

@nibanks What would cause the FAST_FAIL_INVALID_REFERENCE_COUNT on a stream? Does it mean we have "closed" the stream and then tried to call shutdown (or anything else) on it again?

[nibanks]

@nibanks What would cause the FAST_FAIL_INVALID_REFERENCE_COUNT on a stream? Does it mean we have "closed" the stream and then tried to call shutdown (or anything else) on it again?

It means you closed a stream twice.

[nibanks]

Sorry, I didn't read the context correctly. In this case it's a use after free (or close) scenario. You're calling shutdown on a closed stream.

[ManickaP]

There are two problems:

• Failing Assert which is caused by race between control and request streams. We do not wait to accept the control stream on the server side, so it might not be initialized yet the moment we try to access it. This should be easily fixed with a simple await for the control stream.
• Use after free of a client side stream causing the FAST_FAIL_INVALID_REFERENCE_COUNT. Also race, once again an issue with not doing work inside the lock. So we call Dispose in which we set ShutdownDone:
  

  runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs

  Line 873 in 86836e4

  releaseHandles = Interlocked.Exchange(ref _state.ShutdownDone, State.ShutdownDone_Disposed) == State.ShutdownDone_NotificationReceived;

  
  Then, a lock ends, SHUTDOWN_COMPLETE event comes and we call state.Cleanup:
  

  runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs

  Lines 1287 to 1291 in 86836e4

  	bool releaseHandles = Interlocked.Exchange(ref state.ShutdownDone, State.ShutdownDone_NotificationReceived) == State.ShutdownDone_Disposed;
  	if (releaseHandles)
  	{
  	state.Cleanup();
  	}

  
  which will Dispose the safe handle and thus free msquic stream object. Finally, we get back to the rest of Dispose, which will try to call Shutdown:
  

  runtime/src/libraries/System.Net.Quic/src/System/Net/Quic/Implementations/MsQuic/MsQuicStream.cs

  Line 885 in 86836e4

  StartShutdown(QUIC_STREAM_SHUTDOWN_FLAGS.GRACEFUL, errorCode: 0);

Both of these issue were already there and were probably only exposed with the interop change due to timing changes, i.e. making the issue more likely to occur.