Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[wasm] Wasm.Build.Tests xharness crash: "There is no currently active test." #55999

Closed
stephentoub opened this issue Jul 20, 2021 · 3 comments · Fixed by #56180
Closed

[wasm] Wasm.Build.Tests xharness crash: "There is no currently active test." #55999

stephentoub opened this issue Jul 20, 2021 · 3 comments · Fixed by #56180
Assignees
Labels
arch-wasm WebAssembly architecture area-VM-meta-mono

Comments

@stephentoub
Copy link
Member

https://dev.azure.com/dnceng/public/_build/results?buildId=1248297&view=ms.vss-test-web.build-test-results-tab&runId=37078550&resultId=100001&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-55955-merge-df508acdb75840a58a/EMSDK-Wasm.Build.Tests/console.4429ff13.log?sv=2019-07-07&se=2021-08-09T14%3A09%3A49Z&sr=c&sp=rl&sig=H%2BE9ltDz7FuP717ePuXO2wnb0M35hgrRFN%2FFAnvQI44%3D

WorkingDirectory: /datadisks/disk1/work/B4AD09AE/w/B12E09A0/e/xldgeugb.tbm
    Wasm.Build.Tests.RebuildTests.NoOpRebuild(buildArgs: BuildArgs { ProjectName = placeholder, Config = Release, AOT = False, ProjectFileContents = placeholder, ExtraBuildArgs =  }, nativeRelink: False, host: V8, id: "rrumfb4u.ged") [FINISHED] Time: 47.1978775s
    Wasm.Build.Tests.RebuildTests.NoOpRebuild(buildArgs: BuildArgs { ProjectName = placeholder, Config = Release, AOT = False, ProjectFileContents = placeholder, ExtraBuildArgs =  }, nativeRelink: True, host: V8, id: "xldgeugb.tbm") [STARTING]
System.InvalidOperationException: There is no currently active test.
   at Xunit.Sdk.TestOutputHelper.GuardInitialized() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\TestOutputHelper.cs:line 51
   at Xunit.Sdk.TestOutputHelper.QueueTestOutput(String output) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\TestOutputHelper.cs:line 66
   at Wasm.Build.Tests.BuildTestBase.<>c__DisplayClass37_0.<RunProcess>g__LogData|2(String label, String message) in /_/src/tests/BuildWasmApps/Wasm.Build.Tests/BuildTestBase.cs:line 569
   at System.Diagnostics.AsyncStreamReader.FlushMessageQueue(Boolean rethrowInNewThread) in System.Diagnostics.Process.dll:token 0x6000098+0x87
--- End of stack trace from previous location ---
   at System.Diagnostics.AsyncStreamReader.<>c.<FlushMessageQueue>b__18_0(Object edi) in System.Diagnostics.Process.dll:token 0x600009f+0x0
   at System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute() in System.Private.CoreLib.dll:token 0x6002a84+0x14
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in System.Private.CoreLib.dll:token 0x6002a5f+0x10a
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in System.Private.CoreLib.dll:token 0x6002b39+0x6c
   at System.Threading.Thread.StartCallback() in System.Private.CoreLib.dll:token 0x60026db+0xe
./RunTests.sh: line 37: 13021 Aborted                 (core dumped) dotnet exec xunit.console.dll Wasm.Build.Tests.dll -xml $XHARNESS_OUT/testResults.xml -nocolor -verbose -notrait category=IgnoreForCI -notrait category=failing $RSP_FILE
XHarness artifacts: /datadisks/disk1/work/B4AD09AE/w/B12E09A0/uploads/xharness-output
@dotnet-issue-labeler
Copy link

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

@dotnet-issue-labeler dotnet-issue-labeler bot added the untriaged New issue has not been triaged by the area owner label Jul 20, 2021
@ghost
Copy link

ghost commented Jul 21, 2021

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

Issue Details

https://dev.azure.com/dnceng/public/_build/results?buildId=1248297&view=ms.vss-test-web.build-test-results-tab&runId=37078550&resultId=100001&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-55955-merge-df508acdb75840a58a/EMSDK-Wasm.Build.Tests/console.4429ff13.log?sv=2019-07-07&se=2021-08-09T14%3A09%3A49Z&sr=c&sp=rl&sig=H%2BE9ltDz7FuP717ePuXO2wnb0M35hgrRFN%2FFAnvQI44%3D

WorkingDirectory: /datadisks/disk1/work/B4AD09AE/w/B12E09A0/e/xldgeugb.tbm
    Wasm.Build.Tests.RebuildTests.NoOpRebuild(buildArgs: BuildArgs { ProjectName = placeholder, Config = Release, AOT = False, ProjectFileContents = placeholder, ExtraBuildArgs =  }, nativeRelink: False, host: V8, id: "rrumfb4u.ged") [FINISHED] Time: 47.1978775s
    Wasm.Build.Tests.RebuildTests.NoOpRebuild(buildArgs: BuildArgs { ProjectName = placeholder, Config = Release, AOT = False, ProjectFileContents = placeholder, ExtraBuildArgs =  }, nativeRelink: True, host: V8, id: "xldgeugb.tbm") [STARTING]
System.InvalidOperationException: There is no currently active test.
   at Xunit.Sdk.TestOutputHelper.GuardInitialized() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\TestOutputHelper.cs:line 51
   at Xunit.Sdk.TestOutputHelper.QueueTestOutput(String output) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\TestOutputHelper.cs:line 66
   at Wasm.Build.Tests.BuildTestBase.<>c__DisplayClass37_0.<RunProcess>g__LogData|2(String label, String message) in /_/src/tests/BuildWasmApps/Wasm.Build.Tests/BuildTestBase.cs:line 569
   at System.Diagnostics.AsyncStreamReader.FlushMessageQueue(Boolean rethrowInNewThread) in System.Diagnostics.Process.dll:token 0x6000098+0x87
--- End of stack trace from previous location ---
   at System.Diagnostics.AsyncStreamReader.<>c.<FlushMessageQueue>b__18_0(Object edi) in System.Diagnostics.Process.dll:token 0x600009f+0x0
   at System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute() in System.Private.CoreLib.dll:token 0x6002a84+0x14
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in System.Private.CoreLib.dll:token 0x6002a5f+0x10a
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in System.Private.CoreLib.dll:token 0x6002b39+0x6c
   at System.Threading.Thread.StartCallback() in System.Private.CoreLib.dll:token 0x60026db+0xe
./RunTests.sh: line 37: 13021 Aborted                 (core dumped) dotnet exec xunit.console.dll Wasm.Build.Tests.dll -xml $XHARNESS_OUT/testResults.xml -nocolor -verbose -notrait category=IgnoreForCI -notrait category=failing $RSP_FILE
XHarness artifacts: /datadisks/disk1/work/B4AD09AE/w/B12E09A0/uploads/xharness-output
Author: stephentoub
Assignees: -
Labels:

area-VM-meta-mono, untriaged

Milestone: -

@radical radical self-assigned this Jul 22, 2021
radical added a commit to radical/runtime that referenced this issue Jul 22, 2021
.. when the process ends.

`BuildTestBase.RunProcess` subscribes to messages from stdout/stderr.
It seems that sometimes after the process is done, and the test has also
ended, the streams might still be flushing messages, and ends up
invoking our stdout/stderr message handlers.

And these handlers call xunit's `ITestOutputHelper.WriteLine`, which
then fails with:

```
System.InvalidOperationException: There is no currently active test.
   at Xunit.Sdk.TestOutputHelper.GuardInitialized() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\TestOutputHelper.cs:line 51
   at Xunit.Sdk.TestOutputHelper.QueueTestOutput(String output) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\TestOutputHelper.cs:line 66
   at Wasm.Build.Tests.BuildTestBase.<>c__DisplayClass37_0.<RunProcess>g__LogData|2(String label, String message) in /_/src/tests/BuildWasmApps/Wasm.Build.Tests/BuildTestBase.cs:line 569
   at System.Diagnostics.AsyncStreamReader.FlushMessageQueue(Boolean rethrowInNewThread) in System.Diagnostics.Process.dll:token 0x6000098+0x87
--- End of stack trace from previous location ---
   at System.Diagnostics.AsyncStreamReader.<>c.<FlushMessageQueue>b__18_0(Object edi) in System.Diagnostics.Process.dll:token 0x600009f+0x0
   at System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute() in System.Private.CoreLib.dll:token 0x6002a84+0x14
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in System.Private.CoreLib.dll:token 0x6002a5f+0x10a
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in System.Private.CoreLib.dll:token 0x6002b39+0x6c
   at System.Threading.Thread.StartCallback() in System.Private.CoreLib.dll:token 0x60026db+0xe
```

Note: I couldn't actually reproduce this, so this change is just to be
defensive, and hopefully fix this issue.

Fixes: dotnet#55999
@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Jul 22, 2021
@radical radical added the arch-wasm WebAssembly architecture label Jul 22, 2021
@ghost
Copy link

ghost commented Jul 22, 2021

Tagging subscribers to 'arch-wasm': @lewing
See info in area-owners.md if you want to be subscribed.

Issue Details

https://dev.azure.com/dnceng/public/_build/results?buildId=1248297&view=ms.vss-test-web.build-test-results-tab&runId=37078550&resultId=100001&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-55955-merge-df508acdb75840a58a/EMSDK-Wasm.Build.Tests/console.4429ff13.log?sv=2019-07-07&se=2021-08-09T14%3A09%3A49Z&sr=c&sp=rl&sig=H%2BE9ltDz7FuP717ePuXO2wnb0M35hgrRFN%2FFAnvQI44%3D

WorkingDirectory: /datadisks/disk1/work/B4AD09AE/w/B12E09A0/e/xldgeugb.tbm
    Wasm.Build.Tests.RebuildTests.NoOpRebuild(buildArgs: BuildArgs { ProjectName = placeholder, Config = Release, AOT = False, ProjectFileContents = placeholder, ExtraBuildArgs =  }, nativeRelink: False, host: V8, id: "rrumfb4u.ged") [FINISHED] Time: 47.1978775s
    Wasm.Build.Tests.RebuildTests.NoOpRebuild(buildArgs: BuildArgs { ProjectName = placeholder, Config = Release, AOT = False, ProjectFileContents = placeholder, ExtraBuildArgs =  }, nativeRelink: True, host: V8, id: "xldgeugb.tbm") [STARTING]
System.InvalidOperationException: There is no currently active test.
   at Xunit.Sdk.TestOutputHelper.GuardInitialized() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\TestOutputHelper.cs:line 51
   at Xunit.Sdk.TestOutputHelper.QueueTestOutput(String output) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\TestOutputHelper.cs:line 66
   at Wasm.Build.Tests.BuildTestBase.<>c__DisplayClass37_0.<RunProcess>g__LogData|2(String label, String message) in /_/src/tests/BuildWasmApps/Wasm.Build.Tests/BuildTestBase.cs:line 569
   at System.Diagnostics.AsyncStreamReader.FlushMessageQueue(Boolean rethrowInNewThread) in System.Diagnostics.Process.dll:token 0x6000098+0x87
--- End of stack trace from previous location ---
   at System.Diagnostics.AsyncStreamReader.<>c.<FlushMessageQueue>b__18_0(Object edi) in System.Diagnostics.Process.dll:token 0x600009f+0x0
   at System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute() in System.Private.CoreLib.dll:token 0x6002a84+0x14
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in System.Private.CoreLib.dll:token 0x6002a5f+0x10a
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in System.Private.CoreLib.dll:token 0x6002b39+0x6c
   at System.Threading.Thread.StartCallback() in System.Private.CoreLib.dll:token 0x60026db+0xe
./RunTests.sh: line 37: 13021 Aborted                 (core dumped) dotnet exec xunit.console.dll Wasm.Build.Tests.dll -xml $XHARNESS_OUT/testResults.xml -nocolor -verbose -notrait category=IgnoreForCI -notrait category=failing $RSP_FILE
XHarness artifacts: /datadisks/disk1/work/B4AD09AE/w/B12E09A0/uploads/xharness-output
Author: stephentoub
Assignees: radical
Labels:

arch-wasm, area-VM-meta-mono, in pr, untriaged

Milestone: -

@radical radical removed the untriaged New issue has not been triaged by the area owner label Jul 22, 2021
@radical radical changed the title xharness crash: "There is no currently active test." [wasm] Wasm.Build.Tests xharness crash: "There is no currently active test." Jul 22, 2021
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Jul 28, 2021
radical added a commit to radical/runtime that referenced this issue Jul 29, 2021
Earlier commit[1] tried to fix the
[issue](dotnet#55999) where messages would be
received from a process that had exited, but after the test was
complete.

The exception in that case:
```
System.InvalidOperationException: There is no currently active test.
   at Xunit.Sdk.TestOutputHelper.GuardInitialized() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\TestOutputHelper.cs:line 51
   at Xunit.Sdk.TestOutputHelper.QueueTestOutput(String output) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\TestOutputHelper.cs:line 66
   at Wasm.Build.Tests.BuildTestBase.<>c__DisplayClass37_0.<RunProcess>g__LogData|2(String label, String message) in /_/src/tests/BuildWasmApps/Wasm.Build.Tests/BuildTestBase.cs:line 569
   at System.Diagnostics.AsyncStreamReader.FlushMessageQueue(Boolean rethrowInNewThread) in System.Diagnostics.Process.dll:token 0x6000098+0x87
--- End of stack trace from previous location ---
   at System.Diagnostics.AsyncStreamReader.<>c.<FlushMessageQueue>b__18_0(Object edi) in System.Diagnostics.Process.dll:token 0x600009f+0x0
   at System.Threading.QueueUserWorkItemCallbackDefaultContext.Execute() in System.Private.CoreLib.dll:token 0x6002a84+0x14
   at System.Threading.ThreadPoolWorkQueue.Dispatch() in System.Private.CoreLib.dll:token 0x6002a5f+0x10a
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart() in System.Private.CoreLib.dll:token 0x6002b39+0x6c
   at System.Threading.Thread.StartCallback() in System.Private.CoreLib.dll:token 0x60026db+0xe
```

But that commit didn't quite fix the issue, and we now get
dotnet#56513 , where we still end up
missing last few lines.

The reason seems to be that we use `process.WaitForExit(timeout)`, and
once that returns, we return from the method. But the documentation[2]
suggests that we need to call `process.WaitForExit()` after this, to
ensure that all the async event handlers get called. It should mean that
we are not stopping the event handlers early.

Fixes: dotnet#56513

--

1.
```
commit ec2d25c

Author: Ankit Jain <radical@gmail.com>
Date:   Wed Jul 28 12:35:23 2021 -0400

    [wasm] Wasm.Build.Tests - try to close down the stdout/err readers (dotnet#56180)
```

2. https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.process.waitforexit?view=net-6.0#System_Diagnostics_Process_WaitForExit_System_Int32_

```
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.
```
@ghost ghost locked as resolved and limited conversation to collaborators Aug 27, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
arch-wasm WebAssembly architecture area-VM-meta-mono
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants