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

.Net (DotNet) tests get stuck with no reported errors or warning and I could not find the cause on Gitlab Runner's Kubernetes executor #27106

Open
rshad opened this issue Aug 11, 2022 · 17 comments

Comments

@rshad
Copy link

rshad commented Aug 11, 2022

Describe the bug

We have a .Net repository whose pipelines run 3 stages build, test, and deployment.

1 one of the test jobs always gets stuck at a random point without reporting any error or warning that justifies this behavior. Note that this is running on Gitlab Runner's Kubernetes executor, and this same job, does not fail when using Gitlab Runner's Docker executor.

We're using .Net 6, and the latest Docker image of .Net SDK mcr.microsoft.com/dotnet/sdk:6.0


A sample output of the logs where the job gets stuck usually is

Test run for /builds/vistaprint-org/channel-technology/real-time-offer-service/api/src/MerchandisingFeeds.AcceptanceTests/bin/Release/net6.0/MerchandisingFeeds.AcceptanceTests.dll (.NETCoreApp,Version=v6.0)
Microsoft (R) Test Execution Command Line Tool Version 17.3.0 (x64)
Copyright (c) Microsoft Corporation.  All rights reserved.
Starting test execution, please wait...
A total of 1 test files matched the specified pattern.

I also enabled the detailed verbosity of the logs and no error or warning are reported.

I tried many workarounds and verifications which some are proposed in similar or alike reported issues and these workarounds are:

  • Run test jobs sequentially.
  • Change Dockerfiles' ENTRYPOINT from dotnet to bash.
  • Run the job on different instances with different computing capacities.
  • Verified that we have enough resources and disk space.

I also reviewed the logs of the Kubernetes pod and the corresponding container where the jobs' service is running and no errors/warnings or anything related are reported.


Some say that with .Net 5 this would be solved but in my case, it'd be really difficult to run the project with .Net 5 as this implies a lot of code changes.


similar failure cases are already reported and no clear solution or cause is reported. Related issues:

Further technical details

  • Include the output of dotnet --info
$ dotnet --info
.NET SDK (reflecting any global.json):
 Version:   6.0.400
 Commit:    7771abd614
Runtime Environment:
 OS Name:     debian
 OS Version:  11
 OS Platform: Linux
 RID:         debian.11-x64
 Base Path:   /usr/share/dotnet/sdk/6.0.400/
global.json file:
  Not found
Host:
  Version:      6.0.8
  Architecture: x64
  Commit:       55fb7ef977
.NET SDKs installed:
  6.0.400 [/usr/share/dotnet/sdk]
.NET runtimes installed:
  Microsoft.AspNetCore.App 6.0.8 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 6.0.8 [/usr/share/dotnet/shared/Microsoft.NETCore.App]
Download .NET:
  https://aka.ms/dotnet-download
Learn about .NET Runtimes and SDKs:
  https://aka.ms/dotnet/runtimes-sdk-info
@dotnet-issue-labeler dotnet-issue-labeler bot added Area-DotNet Test untriaged Request triage from a team member labels Aug 11, 2022
@nohwnd
Copy link
Member

nohwnd commented Oct 24, 2022

if you add parameter --diag:/some/folder/log.txt it will log diagnostics log of your run, and there we can see way more information. Would you be able to provide those logs please?

There is also --blame-hang-timeout 15min that would trigger hang dump after a test takes more than 15minutes. I see you describe this as being stuck after test run is done, so it might not apply. But might not hurt to try it.

@nohwnd nohwnd removed the untriaged Request triage from a team member label Oct 24, 2022
@rshad
Copy link
Author

rshad commented Oct 26, 2022

Hi @nohwnd!

I retried the job with the parameters you mentioned above and below you can find the info you requested:

Regarding the parameter --blame-hang-timeout 15minI noticed that it did not have any effect. The test continued stuck for more than 15 minutes and no blame output was generated.


Stuck Test Entry

Starting test execution, please wait...
Logging Vstest Diagnostics in file: .../test-output.log
A total of 1 test files matched the specified pattern.
No test matches the given testcase filter `TestType=AcceptanceTest` in ....Tests.dll
Results File: ../../test-results/....Tests-test-results.xml

Verbose Logs

TpTrace Information: 0 : 1268, 1, 2022/10/25, 16:42:42.253, 210147537849, vstest.console.dll, TestRequestManager.RunTests: run tests completed.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147549952, vstest.console.dll, SocketServer.Stop: Cancellation requested. Stopping message loop.
TpTrace Information: 0 : 1268, 1, 2022/10/25, 16:42:42.253, 210147639579, vstest.console.dll, RunTestsArgumentProcessor:Execute: Test run is completed.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147662626, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: LengthPrefixCommunicationChannel: MessageReceived: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender+<>c__DisplayClass31_0.<StartTestRun>b__1, took 60 ms.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147711592, vstest.console.dll, SocketServer.PrivateStop: Stopping server endPoint: 127.0.0.1:45589 error:
TpTrace Verbose: 0 : 1268, 1, 2022/10/25, 16:42:42.253, 210147854024, vstest.console.dll, Executor.Execute: Exiting with exit code of 0
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.254, 210148167562, vstest.console.dll, LengthPrefixCommunicationChannel.Dispose: Dispose reader and writer.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.254, 210148237676, vstest.console.dll, SocketServer.Stop: Raise disconnected event endPoint: 127.0.0.1:45589 error:
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.254, 210148301205, vstest.console.dll, TestRequestSender: OnTestRunAbort: Operation is already complete. Skip error message.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.254, 210148331682, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: SocketServer: ClientDisconnected: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender.<InitializeCommunication>b__24_1, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.254, 210148355210, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: exiting MessageLoopAsync remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
root@runner-oayymdux-project-12359850-concurrent-2kxjjm:.../api# tail -100f test-output.log
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:39.297, 207191763255, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestMessageHandler, took 0 ms.
TpTrace Verbose: 0 : 1268, 5, 2022/10/25, 16:42:39.307, 207201470321, vstest.console.dll, TestRequestSender.StartTestRun: Sending test run with message: {"Version":7,"MessageType":"TestExecution.StartWithSources","Payload":{"AdapterSourceMap":{"_none_":[".../api/tests/MerchandisingFeeds.Offers.Tests/bin/Release/net6.0/MerchandisingFeeds.Offers.Tests.dll"]},"RunSettings":"<RunSettings>\n  <RunConfiguration>\n    <ResultsDirectory>.../api/tests/MerchandisingFeeds.Offers.Tests/TestResults</ResultsDirectory>\n    <TargetFrameworkVersion>.NETCoreApp,Version=v6.0</TargetFrameworkVersion>\n    <TestAdaptersPaths>.../api;/root/.nuget/packages/coverlet.collector/3.1.2/build/netstandard1.0/</TestAdaptersPaths>\n    <DesignMode>False</DesignMode>\n    <CollectSourceInformation>False</CollectSourceInformation>\n  </RunConfiguration>\n  <LoggerRunSettings>\n    <Loggers>\n      <Logger friendlyName=\"junit\" enabled=\"True\">\n        <Configuration>\n          <LogFilePath>../../test-results/{assembly}-test-results.xml</LogFilePath>\n          <MethodFormat>Class</MethodFormat>\n          <FailureBodyFormat>Verbose</FailureBodyFormat>\n        </Configuration>\n      </Logger>\n      <Logger friendlyName=\"Console\"uri=\"logger://microsoft/TestPlatform/ConsoleLogger/v1\" assemblyQualifiedName=\"Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger, vstest.console, Version=15.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a\" codeBase=\"/usr/share/dotnet/sdk/6.0.402/vstest.console.dll\" enabled=\"True\" />\n    </Loggers>\n  </LoggerRunSettings>\n</RunSettings>","TestExecutionContext":{"FrequencyOfRunStatsChangeEvent":10,"RunStatsChangeEventTimeout":"00:00:01.5000000","InIsolation":false,"KeepAlive":false,"AreTestCaseLevelEventsRequired":false,"IsDebug":false,"TestCaseFilter":"TestType=AcceptanceTest","FilterOptions":null},"Package":null}}
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:39.481, 207375549388, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:39.481, 207375695664, vstest.console.dll, TestRequestSender.OnExecutionMessageReceived: Received message: {"Version":7,"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.5+1caef2f33e (64-bit .NET 6.0.10)"}}
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:39.481, 207375892126, vstest.console.dll, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:39.482, 207375976438, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: TestRun.LogMessages: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommandLine.TestRunResultAggregator.TestRunMessageHandler, took 0 ms.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:39.482, 207376003741, vstest.console.dll, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:39.482, 207376037144, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: LengthPrefixCommunicationChannel: MessageReceived: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender+<>c__DisplayClass31_0.<StartTestRun>b__1, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:39.482, 207376061616, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:39.482, 207376115746, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 1/2 for Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_1, took 0 ms.
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:39.482, 207376213705, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestMessageHandler, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:40.483, 208377152811, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:41.484, 209378318322, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.080, 209974214632, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.080, 209974374421, vstest.console.dll, TestRequestSender.OnExecutionMessageReceived: Received message: {"Version":7,"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:02.60]   Discovering: MerchandisingFeeds.Offers.Tests"}}
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.080, 209974491479, vstest.console.dll, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.080, 209974559429, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: TestRun.LogMessages: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommandLine.TestRunResultAggregator.TestRunMessageHandler, took 0 ms.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.080, 209974604740, vstest.console.dll, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.080, 209974615018, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 1/2 for Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_1, took 0 ms.
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.080, 209974718977, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestMessageHandler, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.080, 209974631720, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: LengthPrefixCommunicationChannel: MessageReceived: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender+<>c__DisplayClass31_0.<StartTestRun>b__1, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.080, 209974776292, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.129, 210023155331, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.129, 210023289076, vstest.console.dll, TestRequestSender.OnExecutionMessageReceived: Received message: {"Version":7,"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:02.65]   Discovered:  MerchandisingFeeds.Offers.Tests"}}
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.129, 210023400241, vstest.console.dll, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.129, 210023464048, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: TestRun.LogMessages: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommandLine.TestRunResultAggregator.TestRunMessageHandler, took 0 ms.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.129, 210023486957, vstest.console.dll, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.129, 210023539923, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: LengthPrefixCommunicationChannel: MessageReceived: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender+<>c__DisplayClass31_0.<StartTestRun>b__1, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.129, 210023563534, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.129, 210023580088, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 1/2 for Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_1, took 0 ms.
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.129, 210023662063, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestMessageHandler, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.136, 210030604671, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.136, 210030726934, vstest.console.dll, TestRequestSender.OnExecutionMessageReceived: Received message: {"Version":7,"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:02.66]   Starting:    MerchandisingFeeds.Offers.Tests"}}
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.136, 210030832564, vstest.console.dll, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.136, 210030902805, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: TestRun.LogMessages: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommandLine.TestRunResultAggregator.TestRunMessageHandler, took 0 ms.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.137, 210030927648, vstest.console.dll, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.137, 210030951887, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: LengthPrefixCommunicationChannel: MessageReceived: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender+<>c__DisplayClass31_0.<StartTestRun>b__1, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.137, 210030973886, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.137, 210031009336, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 1/2 for Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_1, took 0 ms.
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.137, 210031088195, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestMessageHandler, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.157, 210051611510, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.157, 210051723863, vstest.console.dll, TestRequestSender.OnExecutionMessageReceived: Received message: {"Version":7,"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:02.68]   Finished:    MerchandisingFeeds.Offers.Tests"}}
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.157, 210051827298, vstest.console.dll, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.157, 210051892077, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: TestRun.LogMessages: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommandLine.TestRunResultAggregator.TestRunMessageHandler, took 0 ms.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.158, 210051914564, vstest.console.dll, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.158, 210051934899, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: LengthPrefixCommunicationChannel: MessageReceived: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender+<>c__DisplayClass31_0.<StartTestRun>b__1, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.158, 210051956710, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.158, 210052008713, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 1/2 for Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_1, took 0 ms.
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.158, 210052081714, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestMessageHandler, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.163, 210057274649, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.163, 210057357092, vstest.console.dll, TestRequestSender.OnExecutionMessageReceived: Received message: {"Version":7,"MessageType":"TestSession.Message","Payload":{"MessageLevel":1,"Message":"No test matches the given testcase filter `TestType=AcceptanceTest` in .../api/tests/MerchandisingFeeds.Offers.Tests/bin/Release/net6.0/MerchandisingFeeds.Offers.Tests.dll"}}
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.163, 210057451284, vstest.console.dll, TestRunRequest:SendTestRunMessage: Starting.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.163, 210057510585, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: TestRun.LogMessages: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommandLine.TestRunResultAggregator.TestRunMessageHandler, took 0 ms.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.163, 210057533383, vstest.console.dll, TestRunRequest:SendTestRunMessage: Completed.
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.163, 210057538420, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 1/2 for Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_1, took 0 ms.
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.163, 210057762453, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunMessage: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestMessageHandler, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.163, 210057554260, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: LengthPrefixCommunicationChannel: MessageReceived: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender+<>c__DisplayClass31_0.<StartTestRun>b__1, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.163, 210057877876, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: Polling on remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.193, 210087491627, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: NotifyDataAvailable remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.193, 210087683730, vstest.console.dll, TestRequestSender.OnExecutionMessageReceived: Received message: {"Version":7,"MessageType":"TestExecution.Completed","Payload":{"TestRunCompleteArgs":{"TestRunStatistics":{"ExecutedTests":0,"Stats":{}},"IsCanceled":false,"IsAborted":false,"Error":null,"AttachmentSets":[],"InvokedDataCollectors":[],"ElapsedTimeInRunningTests":"00:00:02.6931454","Metrics":{},"DiscoveredExtensions":{"TestDiscoverers":["Xunit.Runner.VisualStudio.VsTestRunner, xunit.runner.visualstudio.dotnetcore.testadapter, Version=2.4.0.0, Culture=neutral, PublicKeyToken=8d05b1bb7a6fdb6c"],"TestExecutors":["executor://xunit/VsTestRunner2/netcoreapp"],"TestExecutors2":[],"TestSettingsProviders":[]}},"LastRunTests":{"NewTestResults":[],"TestRunStatistics":{"ExecutedTests":0,"Stats":{}},"ActiveTests":[]},"RunAttachments":[],"ExecutorUris":[]}}
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.193, 210087795896, vstest.console.dll, TestRequestSender.EndSession: Sending end session.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.194, 210087966062, vstest.console.dll, ProxyOperationManager.Close: waiting for test host to exit for 100 ms
TpTrace Warning: 0 : 1268, 5, 2022/10/25, 16:42:42.208, 210102437546, vstest.console.dll, TestHostManagerCallbacks.ErrorReceivedCallback Test host standard error line:
TpTrace Verbose: 0 : 1268, 11, 2022/10/25, 16:42:42.208, 210102806859, vstest.console.dll, TestHostProvider.ExitCallBack: Host exited starting callback.
TpTrace Information: 0 : 1268, 11, 2022/10/25, 16:42:42.208, 210102908292, vstest.console.dll, TestHostManagerCallbacks.ExitCallBack: Testhost processId: 1281 exited with exitcode: 0 error: ''
TpTrace Verbose: 0 : 1268, 11, 2022/10/25, 16:42:42.209, 210102940012, vstest.console.dll, DotnetTestHostManager.OnHostExited: invoking OnHostExited callback
TpTrace Verbose: 0 : 1268, 11, 2022/10/25, 16:42:42.209, 210102994502, vstest.console.dll, CrossPlatEngine.TestHostManagerHostExited: calling on client process exit callback.
TpTrace Information: 0 : 1268, 11, 2022/10/25, 16:42:42.209, 210103051724, vstest.console.dll, TestRequestSender.OnClientProcessExit: Test host process exited. Standard error:
TpTrace Information: 0 : 1268, 11, 2022/10/25, 16:42:42.209, 210103084738, vstest.console.dll, SocketServer.Stop: Stop server endPoint: 127.0.0.1:45589
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.209, 210103100691, vstest.console.dll, SocketServer.Stop: Stop server endPoint: 127.0.0.1:45589
TpTrace Information: 0 : 1268, 11, 2022/10/25, 16:42:42.209, 210103109002, vstest.console.dll, SocketServer.Stop: Cancellation requested. Stopping message loop.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.209, 210103166642, vstest.console.dll, SocketServer.Stop: Cancellation requested. Stopping message loop.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.209, 210103236391, vstest.console.dll, Closing the connection
TpTrace Verbose: 0 : 1268, 11, 2022/10/25, 16:42:42.209, 210103275624, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: HostProviderEvents.OnHostExited: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CrossPlatEngine.Client.ProxyOperationManager.TestHostManagerHostExited, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.239, 210133922674, vstest.console.dll, TestRunRequest:SendTestRunStatsChange: Starting.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.240, 210134092038, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: TestRun.RunStatsChanged: Invoking callbacks was skipped because there are no subscribers.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.240, 210134119487, vstest.console.dll, TestRunRequest:SendTestRunStatsChange: Completed.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.240, 210134377403, vstest.console.dll, ParallelProxyExecutionManager: HandlePartialRunComplete: Total completed clients = 1, Run complete = True, Run canceled: False.
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.247, 210141479315, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunComplete: Invoking callback 1/2 for Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_3, took 3 ms.
TpTrace Verbose: 0 : 1268, 4, 2022/10/25, 16:42:42.250, 210144157456, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: InternalTestLoggerEvents.SendTestRunComplete: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Internal.ConsoleLogger.TestRunCompleteHandler, took 2 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.250, 210144448499, vstest.console.dll, TestRunRequest:TestRunComplete: Starting. IsAborted:False IsCanceled:False.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.252, 210146192851, vstest.console.dll, TestLoggerManager.HandleTestRunComplete: Ignoring as the object is disposed.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147090375, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: TestRun.TestRunComplete: Invoking callback 1/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.TestRunResultAggregator.TestRunCompletionHandler, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147185576, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: TestRun.TestRunComplete: Invoking callback 2/2 for Microsoft.VisualStudio.TestPlatform.CommandLine.Processors.RunTestsArgumentExecutor+TestRunRequestEventsRegistrar.TestRunRequest_OnRunCompletion, took 0 ms.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147304889, vstest.console.dll, TestRunRequest:TestRunComplete: Completed.
TpTrace Verbose: 0 : 1268, 1, 2022/10/25, 16:42:42.253, 210147338874, vstest.console.dll, TestRunRequest.Dispose: Starting.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147359510, vstest.console.dll, TestRequestSender.SetOperationComplete: Setting operation complete.
TpTrace Information: 0 : 1268, 1, 2022/10/25, 16:42:42.253, 210147429315, vstest.console.dll, TestRunRequest.Dispose: Completed.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147474908, vstest.console.dll, SocketServer.Stop: Stop server endPoint: 127.0.0.1:45589
TpTrace Information: 0 : 1268, 1, 2022/10/25, 16:42:42.253, 210147537849, vstest.console.dll, TestRequestManager.RunTests: run tests completed.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147549952, vstest.console.dll, SocketServer.Stop: Cancellation requested. Stopping message loop.
TpTrace Information: 0 : 1268, 1, 2022/10/25, 16:42:42.253, 210147639579, vstest.console.dll, RunTestsArgumentProcessor:Execute: Test run is completed.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147662626, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: LengthPrefixCommunicationChannel: MessageReceived: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender+<>c__DisplayClass31_0.<StartTestRun>b__1, took 60 ms.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.253, 210147711592, vstest.console.dll, SocketServer.PrivateStop: Stopping server endPoint: 127.0.0.1:45589 error:
TpTrace Verbose: 0 : 1268, 1, 2022/10/25, 16:42:42.253, 210147854024, vstest.console.dll, Executor.Execute: Exiting with exit code of 0
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.254, 210148167562, vstest.console.dll, LengthPrefixCommunicationChannel.Dispose: Dispose reader and writer.
TpTrace Information: 0 : 1268, 7, 2022/10/25, 16:42:42.254, 210148237676, vstest.console.dll, SocketServer.Stop: Raise disconnected event endPoint: 127.0.0.1:45589 error:
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.254, 210148301205, vstest.console.dll, TestRequestSender: OnTestRunAbort: Operation is already complete. Skip error message.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.254, 210148331682, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: SocketServer: ClientDisconnected: Invoking callback 1/1 for Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.TestRequestSender.<InitializeCommunication>b__24_1, took 0 ms.
TpTrace Verbose: 0 : 1268, 7, 2022/10/25, 16:42:42.254, 210148355210, vstest.console.dll, TcpClientExtensions.MessageLoopAsync: exiting MessageLoopAsync remoteEndPoint: 127.0.0.1:40368 localEndPoint: 127.0.0.1:45589

@Kuinox
Copy link

Kuinox commented Nov 7, 2022

Hi, I think this issue is due to a bug in the Process type, I opened an issue about it here: dotnet/runtime#51277

In summary:

The issue is that WaitForExit() will synchronously wait for the stderr/stdout to complete, the summoned process has exited, but it has childs process still running (the nodereuse processes in msbuild case).
In this case, it looks like that the stderr/stdout pipes wont close.

Here I guess --blame-hang-timeout 15min doesn't do anything because it will try to kill a process that is already dead, and something is still stuck on WaitForExit()

@olfek
Copy link

olfek commented Jan 16, 2023

I'm experiencing the exact same problem right now ☹️

@olfek
Copy link

olfek commented Jan 16, 2023

My .gitlab-ci.yml file

workflow:
  rules:
    - if: $CI_PIPELINE_SOURCE == "web"

stages:
  - all

woo:
  stage: all
  image: mcr.microsoft.com/dotnet/sdk:6.0
  script:
    - 'dotnet restore'
    - 'dotnet build --no-restore <TESTS PROJECT>'
    - 'dotnet test --no-build --verbosity normal <TESTS PROJECT>'

Pretty straight forward I think

@olfek
Copy link

olfek commented Jan 16, 2023

"solution"

Okay this "solution" works for me ➡️ #9452 (comment)

@codenesium
Copy link

What we found was our TestWebapplicationFactory was calling async code in the Dispose Method(also occurs in the constructor) on that factory using .Wait(). In our case we were using xUnit version 2 which has a synchronization context and was being deadlocked. We were only able to see this info by running dotnet test with --blame-hang-dump-type full.

@augustfengd
Copy link

Our tests got a little bit further than OPs but still hang'ed.

I found a blog post and tried the xunit.runner.json workaround which worked marvellously.

@Evengard
Copy link

Evengard commented Sep 6, 2023

Beware of the ultimate workaround which seems (at least in my case with Jenkins pipelines running inside Kubernetes) to have COMPLETELY alleviated the issue!
No xunit.runner.json fiddling needed. No attributes needed. No parallelization disabling needed. No running with tini or smth like that. No weird properties passed on dotnet command or smth like that. No build server shutdown needed. No need to enable tty for the container.

Nothing of that.

The ultimate workaround is this:

sh -c "dotnet test yourproject.csproj & wait"

Yep, that's it. You can even omit the sh -c part with the double quotes if you run within a sh-compatible shell.

Honestly, I still don't completely understand WHY this workaround works (at least for me), it failed not once with it. Not once after that I had to wait those damn 15 minutes. It Just Works.

I have a teory that it somehow "unblocks" the dotnet test input/output fds which seems to somehow help to alleviate this issue, but I do not have any deeper understanding. I'm just happy, because I was fighting that bug for almost a year now.

@Kuinox
Copy link

Kuinox commented Sep 6, 2023

I do keep thinking it's the Process.Start issue I keep referencing everywhere.
Since I suspect it's a Process.WaitForExit not returning because the output/error pipes don't close despite the process being exited, I can see your workaround messing with how pipes behave and avoid the issue in the end.

dotnet/runtime#51277

@animaonline
Copy link

Any updates on this?

@zeinali0
Copy link

same problem with .net 7

@Daniyal-MDKY
Copy link

Daniyal-MDKY commented Jan 25, 2024

Any updates on this?

Hello Guys, I tried all options mentioned here, but nothing seems to work.

I solved my problem by turning off parallel test execution.
(It works on all configs I think I have tried it on
Jenkins pipelines running inside Kubernetes
&
Bamboo pipelines running inside docker)

In my test project >
Add folder Properties >
Add _AssemblyInfo.cs_
Add below code in the file

using Xunit;

[assembly: CollectionBehavior(DisableTestParallelization = true)]

@nahyanshiwani
Copy link

Any updates on this?

Hello Guys, I tried all options mentioned here, but nothing seems to work.

I solved my problem by turning off parallel test execution. (It works on all configs I think I have tried it on Jenkins pipelines running inside Kubernetes & Bamboo pipelines running inside docker)

In my test project > Add folder Properties > Add _AssemblyInfo.cs_ Add below code in the file

using Xunit;

[assembly: CollectionBehavior(DisableTestParallelization = true)]

Thanks @Daniyal-MDKY
Your solution worked for me

@bmahmoodisran
Copy link

Any updates on this?

Hello Guys, I tried all options mentioned here, but nothing seems to work.

I solved my problem by turning off parallel test execution. (It works on all configs I think I have tried it on Jenkins pipelines running inside Kubernetes & Bamboo pipelines running inside docker)

In my test project > Add folder Properties > Add _AssemblyInfo.cs_ Add below code in the file

using Xunit;

[assembly: CollectionBehavior(DisableTestParallelization = true)]

Thank You!

@sksk571
Copy link

sksk571 commented Apr 9, 2024

We have hit a similar problem during the migration from .NET6 to .NET8. In our case the issue turned out to be an excessive memory usage caused by a task spawned in one of the tests. The task was effectively spinning in a short loop generating temp objects. This somehow worked in .NET6, but in .NET8 GC wasn't able to keep up with the task and it was periodically crashing the build agent. Enabling pipeline diagnostics and running locally with memory profiler allowed to spot the problem.

@KonradZaremba
Copy link

Any updates on this?

Hello Guys, I tried all options mentioned here, but nothing seems to work.

I solved my problem by turning off parallel test execution. (It works on all configs I think I have tried it on Jenkins pipelines running inside Kubernetes & Bamboo pipelines running inside docker)

In my test project > Add folder Properties > Add _AssemblyInfo.cs_ Add below code in the file

using Xunit;

[assembly: CollectionBehavior(DisableTestParallelization = true)]

Thank you very much this solved my problem.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests