Test Failed: Process terminated. Assertion failed. "!_fileHandle.IsClosed"

[VincentBu]

Detail:
https://helix.dot.net/api/2019-06-17/jobs/0c15185a-2331-4dcf-978c-cd7c4a4b3189/workitems/System.Diagnostics.Process.Tests/console

Log:

C:\dotnetbuild\work\0c15185a-2331-4dcf-978c-cd7c4a4b3189\Work\2eeb62f3-774b-43f1-94ac-c844f873d662\Exec>"C:\dotnetbuild\work\0c15185a-2331-4dcf-978c-cd7c4a4b3189\Payload\dotnet.exe" exec --runtimeconfig System.Diagnostics.Process.Tests.runtimeconfig.json xunit.console.dll System.Diagnostics.Process.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=nonnetcoreapptests -notrait category=nonwindowstests -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing @C:\dotnetbuild\work\0c15185a-2331-4dcf-978c-cd7c4a4b3189\Payload\CoreFX.issues.rsp 
  Discovering: System.Diagnostics.Process.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  System.Diagnostics.Process.Tests (found 221 of 241 test cases)
  Starting:    System.Diagnostics.Process.Tests (parallel test collections = on, max threads = 2)
    System.Diagnostics.Tests.ProcessStartInfoTests.StartInfo_WebPage [SKIP]
      Manual test
    System.Diagnostics.Tests.ProcessStartInfoTests.ShellExecute_Nano_Fails_Start [SKIP]
      Condition(s) not met: "IsWindowsNanoServer"
Process terminated. Assertion failed.
!_fileHandle.IsClosed
   at System.IO.FileStream.AssertCanRead() in /_/src/System.Private.CoreLib/shared/System/IO/FileStream.Windows.cs:line 482
   at System.IO.FileStream.ReadNative(Span`1 buffer) in /_/src/System.Private.CoreLib/shared/System/IO/FileStream.Windows.cs:line 497
   at System.IO.FileStream.ReadSpan(Span`1 destination) in /_/src/System.Private.CoreLib/shared/System/IO/FileStream.Windows.cs:line 429
   at System.IO.FileStream.Read(Byte[] array, Int32 offset, Int32 count) in /_/src/System.Private.CoreLib/shared/System/IO/FileStream.cs:line 304
   at System.IO.Stream.<>c.<BeginReadInternal>b__43_0(Object <p0>) in /_/src/System.Private.CoreLib/shared/System/IO/Stream.cs:line 303
   at System.Threading.Tasks.Task`1.InnerInvoke() in /_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Future.cs:line 512
   at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj) in /_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs:line 2372
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state) in /_/src/System.Private.CoreLib/shared/System/Threading/ExecutionContext.cs:line 289
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread) in /_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs:line 2333
   at System.Threading.Tasks.Task.ExecuteEntryUnsafe(Thread threadPoolThread) in /_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs:line 2271
   at System.Threading.Tasks.Task.ExecuteFromThreadPool(Thread threadPoolThread) in /_/src/System.Private.CoreLib/shared/System/Threading/Tasks/Task.cs:line 2256
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in /_/src/System.Private.CoreLib/shared/System/Threading/ThreadPool.cs:line 664
   at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback() in /_/src/System.Private.CoreLib/src/System/Threading/ThreadPool.CoreCLR.cs:line 29
exit code -2146232797 

[jeffschwMSFT]

This looks more like a test issue/race (using a closed file handle). @danmosemsft is there someone to take a look?

[jeffschwMSFT]

I took a deeper look at this. The error output is not specific enough to know which of the sub tests is actually failing, but the test calls out there is an inherent race: https://github.com/dotnet/corefx/blob/master/src/System.Diagnostics.Process/tests/ProcessStreamReadTests.cs#L99

Through code review and experimentation I attempted to induce the race, but was not able to get the failure that occurred above.

I ran this test on Windows X64 against a Check and Release build of master and saw it consistently pass. I am going to close this issue for now and we should keep an eye on this test.

[jkotas]

This failed again in #31629 on runtime (Libraries Test Run checked coreclr Windows_NT x64 Debug):

  Starting:    System.Diagnostics.Process.Tests (parallel test collections = on, max threads = 2)
    System.Diagnostics.Tests.ProcessStartInfoTests.StartInfo_WebPage [SKIP]
      Manual test
    System.Diagnostics.Tests.ProcessStartInfoTests.ShellExecute_Nano_Fails_Start [SKIP]
      Condition(s) not met: "IsWindowsNanoServer"
Process terminated. Assertion failed.
CanRead
   at System.IO.FileStream.AssertCanRead() in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.Windows.cs:line 482
   at System.IO.FileStream.ReadNative(Span`1 buffer) in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.Windows.cs:line 494
   at System.IO.FileStream.ReadSpan(Span`1 destination) in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.Windows.cs:line 429
   at System.IO.FileStream.Read(Byte[] array, Int32 offset, Int32 count) in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.cs:line 305
   at System.IO.Stream.<>c.<BeginReadInternal>b__46_0(Object <p0>) in /_/src/libraries/System.Private.CoreLib/src/System/IO/Stream.cs:line 384
   at System.Threading.Tasks.Task`1.InnerInvoke() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Future.cs:line 504
   at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2358
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs:line 289
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2320
   at System.Threading.Tasks.Task.ExecuteEntryUnsafe(Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2252
   at System.Threading.Tasks.Task.ExecuteFromThreadPool(Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2243
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPool.cs:line 659
   at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback() in /_/src/coreclr/src/System.Private.CoreLib/src/System/Threading/ThreadPool.CoreCLR.cs:line 29

[ViktorHofer]

Failed again: https://dnceng.visualstudio.com/public/_build/results?buildId=519363&view=ms.vss-test-web.build-test-results-tab&runId=16419870&resultId=173296&paneView=attachments

Configuration: netcoreapp5.0-Windows_NT-Release-x64-CoreCLR_checked-Windows.10.Amd64.Open

console.dabdd3b1.log:
  https://helix.dot.net/api/2019-06-17/jobs/8fba0916-d85c-4f4d-831c-80760931d37c/workitems/System.Diagnostics.Process.Tests/files/console.dabdd3b1.log

dotnet.exe.3032.dmp:
  https://helix.dot.net/api/2019-06-17/jobs/8fba0916-d85c-4f4d-831c-80760931d37c/workitems/System.Diagnostics.Process.Tests/files/dotnet.exe.3032.dmp

[ViktorHofer]

I'm failing loading the dump with a managed debugger in VS:

I downloaded the correct coreclr binaries from the CI artifacts and pointed VS to resolve symbols from that local directory. No idea how to debug further here?

[ViktorHofer]

Happened again: https://dnceng.visualstudio.com/public/_build/results?buildId=553760&view=ms.vss-test-web.build-test-results-tab&runId=17474298&resultId=173399&paneView=attachments

Configuration: netcoreapp5.0-Windows_NT-Release-x86-CoreCLR_checked-Windows.10.Amd64.Open

  Discovering: System.Diagnostics.Process.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  System.Diagnostics.Process.Tests (found 234 of 253 test cases)
  Starting:    System.Diagnostics.Process.Tests (parallel test collections = on, max threads = 2)
    System.Diagnostics.Tests.ProcessStartInfoTests.StartInfo_WebPage [SKIP]
      Manual test
    System.Diagnostics.Tests.ProcessStartInfoTests.ShellExecute_Nano_Fails_Start [SKIP]
      Condition(s) not met: "IsWindowsNanoServer"
Process terminated. Assertion failed.
!_fileHandle.IsClosed
   at System.IO.FileStream.AssertCanRead() in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.Windows.cs:line 481
   at System.IO.FileStream.ReadNative(Span`1 buffer) in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.Windows.cs:line 494
   at System.IO.FileStream.ReadSpan(Span`1 destination) in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.Windows.cs:line 429
   at System.IO.FileStream.Read(Byte[] array, Int32 offset, Int32 count) in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.cs:line 305
   at System.IO.Stream.<>c.<BeginReadInternal>b__45_0(Object <p0>) in /_/src/libraries/System.Private.CoreLib/src/System/IO/Stream.cs:line 383
   at System.Threading.Tasks.Task`1.InnerInvoke() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Future.cs:line 504
   at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2350
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs:line 289
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2314
   at System.Threading.Tasks.Task.ExecuteEntryUnsafe(Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2246
   at System.Threading.Tasks.Task.ExecuteFromThreadPool(Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2237
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPool.cs:line 659
   at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback() in /_/src/coreclr/src/System.Private.CoreLib/src/System/Threading/ThreadPool.CoreCLR.cs:line 29
----- end Tue 03/10/2020 12:24:25.30 ----- exit code -2146232797 ----------------------------------------------------------

console.480ab2ef.log:
https://helix.dot.net/api/2019-06-17/jobs/0327a460-bc02-49bb-85ef-38d05776a8c3/workitems/System.Diagnostics.Process.Tests/files/console.480ab2ef.log

dotnet.exe.5304.dmp:
https://helix.dot.net/api/2019-06-17/jobs/0327a460-bc02-49bb-85ef-38d05776a8c3/workitems/System.Diagnostics.Process.Tests/files/dotnet.exe.5304.dmp

cc @adamsitnik @eiriktsarpalis @stephentoub

[trylek]

Latest repro: https://dev.azure.com/dnceng/public/_build/results?buildId=568935&view=logs&j=96447df6-cb08-536e-96a6-2b28fb9fc6e6&t=61766eb9-82c8-5112-90f4-584fc817826e

  Starting:    System.Diagnostics.Process.Tests (parallel test collections = on, max threads = 2)
    System.Diagnostics.Tests.ProcessStartInfoTests.StartInfo_WebPage [SKIP]
      Manual test
    System.Diagnostics.Tests.ProcessStartInfoTests.ShellExecute_Nano_Fails_Start [SKIP]
      Condition(s) not met: "IsWindowsNanoServer"
Process terminated. Assertion failed.
!_fileHandle.IsClosed
   at System.IO.FileStream.AssertCanRead() in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.Windows.cs:line 481
   at System.IO.FileStream.ReadNative(Span`1 buffer) in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.Windows.cs:line 494
   at System.IO.FileStream.ReadSpan(Span`1 destination) in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.Windows.cs:line 429
   at System.IO.FileStream.Read(Byte[] array, Int32 offset, Int32 count) in /_/src/libraries/System.Private.CoreLib/src/System/IO/FileStream.cs:line 305
   at System.IO.Stream.<>c.b__45_0(Object ) in /_/src/libraries/System.Private.CoreLib/src/System/IO/Stream.cs:line 383
   at System.Threading.Tasks.Task`1.InnerInvoke() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Future.cs:line 504
   at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2350
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs:line 289
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2314
   at System.Threading.Tasks.Task.ExecuteEntryUnsafe(Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2246
   at System.Threading.Tasks.Task.ExecuteFromThreadPool(Thread threadPoolThread) in /_/src/libraries/System.Private.CoreLib/src/System/Threading/Tasks/Task.cs:line 2237
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in /_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPool.cs:line 659
   at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback() in /_/src/coreclr/src/System.Private.CoreLib/src/System/Threading/ThreadPool.CoreCLR.cs:line 29
----- end Sun 03/22/2020 10:41:17.68 ----- exit code -2146232797 ----------------------------------------------------------

[stephentoub]

I'm currently building a checked runtime to help validate, but I suspect the issue is that:

• Process.BeginOutputReadLine() kicks off an asynchronous read loop on the the output stream
• The output stream of a Process.Start with redirected output uses a FileStream created as non-asynchronous, thus all ReadAsync calls made by BeginOutputReadLine are doing async-over-sync ReadAsyncs
• Such ReadAsync calls on FileStream will check early on in the sync Read call and throw if the FileStream has been closed; it then similarly later asserts that the handle is still open... that will be invalid if the FileStream was disposed of while that operation was still in progress and just the right interleaving occurred
• Process.WaitForExit(timeout) doesn't wait for this asynchronous read loop to shut down, even when it returns true. There's an explicit check in the code for timeout == Infinite, and only if it's true does it wait for the loop to exit. The docs state "When standard output has been redirected to asynchronous event handlers, it is possible that output processing will not have completed when this method returns. To ensure that asynchronous event handling has been completed, call the WaitForExit() overload that takes no parameter after receiving a true from this overload."
• We have tests that are using BeginOutputReadLine() and then WaitForExit(nonInfiniteTimeout) not followed by WaitForExit(), and then Dispose'ing of the Process object, which will dispose of the output stream.

Assuming I'm right, the fix is to add WaitForExit() calls into the offending tests.

[danmoseley]

To ensure that asynchronous event handling has been completed, call the WaitForExit() overload that takes no parameter after receiving a true from this overload."

@stephentoub can you help me understand the assert here? (I realize this is in Unix, and this bug concerns Windows).

        private bool WaitForExitCore(int milliseconds)
        {
            bool exited = GetWaitState().WaitForExit(milliseconds);
            Debug.Assert(exited || milliseconds != Timeout.Infinite);

It seems to me a confusing design that WaitForExit(timeout) has logically distinct behavior for infinite, even if the timeout doesn't expire, so I went to read source.dot.net, forgetting it was Unix sources. Now I'm having trouble understanding the assert. Does WaitHandle itself also have special behavior for infinite?

[stephentoub]

I'm not understanding the question. What's the confusion?

That assert you highlighted is just saying that either the handle was set or that the timeout wasn't infinite: if it was infinite and the handle hadn't been set, the call wouldn't have returned.

As for the bug, it's not specific to Windows. The relevant part is what comes after the code you listed above, where we only wait on the output streams if the timeout is infinite.