.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

rshad · 2022-08-11T16:19:15Z

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

The text was updated successfully, but these errors were encountered:

nohwnd · 2022-10-24T12:59:37Z

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.

rshad · 2022-10-26T09:51:11Z

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, 209974586329, 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 · 2022-11-07T10:19:55Z

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 · 2023-01-16T13:20:41Z

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

olfek · 2023-01-16T13:24:06Z

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 · 2023-01-16T16:14:03Z

"solution"

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

codenesium · 2023-05-24T21:17:41Z

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 · 2023-08-03T19:26:48Z

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 · 2023-09-06T20:44:23Z

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 · 2023-09-06T21:03:19Z

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 · 2023-10-27T07:50:42Z

Any updates on this?

zeinali0 · 2023-11-10T11:57:30Z

same problem with .net 7

Daniyal-MDKY · 2024-01-25T11:25:17Z

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 · 2024-01-25T16:05:50Z

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 · 2024-01-26T10:44:57Z

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 · 2024-04-09T11:52:57Z

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 · 2024-08-23T08:24:40Z

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.

dotnet-issue-labeler bot added Area-DotNet Test untriaged Request triage from a team member labels Aug 11, 2022

nohwnd removed the untriaged Request triage from a team member label Oct 24, 2022

Piedone mentioned this issue Nov 16, 2022

UI testing randomly getting stuck in CI (OSOE-464) Lombiq/UI-Testing-Toolbox#228

Open

9 tasks

johanparmar mentioned this issue May 2, 2023

The action never finishes cake-build/cake-action#47

Closed

Evengard mentioned this issue Sep 6, 2023

Regression: dotnet test hangs for 15 minutes after test run completed on mac and linux #9452

Open

GabrielHSFerreira mentioned this issue Apr 23, 2024

DotNetCoreCLI@2's dotnet test hangs indefinitely when a child process inherited the STDIO streams and has not yet exited microsoft/azure-pipelines-tasks#17548

Open

lukebakken mentioned this issue Nov 7, 2024

Fix GitHub actions timeouts rabbitmq/rabbitmq-amqp-dotnet-client#87

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

.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

.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

rshad commented Aug 11, 2022

nohwnd commented Oct 24, 2022

rshad commented Oct 26, 2022

Kuinox commented Nov 7, 2022

olfek commented Jan 16, 2023

olfek commented Jan 16, 2023

olfek commented Jan 16, 2023 •

edited

Loading

codenesium commented May 24, 2023

augustfengd commented Aug 3, 2023

Evengard commented Sep 6, 2023 •

edited

Loading

Kuinox commented Sep 6, 2023 •

edited

Loading

animaonline commented Oct 27, 2023

zeinali0 commented Nov 10, 2023

Daniyal-MDKY commented Jan 25, 2024 •

edited

Loading

nahyanshiwani commented Jan 25, 2024

bmahmoodisran commented Jan 26, 2024

sksk571 commented Apr 9, 2024

KonradZaremba commented Aug 23, 2024

.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

.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

Comments

rshad commented Aug 11, 2022

Describe the bug

Further technical details

nohwnd commented Oct 24, 2022

rshad commented Oct 26, 2022

Kuinox commented Nov 7, 2022

olfek commented Jan 16, 2023

olfek commented Jan 16, 2023

olfek commented Jan 16, 2023 • edited Loading

"solution"

codenesium commented May 24, 2023

augustfengd commented Aug 3, 2023

Evengard commented Sep 6, 2023 • edited Loading

Kuinox commented Sep 6, 2023 • edited Loading

animaonline commented Oct 27, 2023

zeinali0 commented Nov 10, 2023

Daniyal-MDKY commented Jan 25, 2024 • edited Loading

nahyanshiwani commented Jan 25, 2024

bmahmoodisran commented Jan 26, 2024

sksk571 commented Apr 9, 2024

KonradZaremba commented Aug 23, 2024

olfek commented Jan 16, 2023 •

edited

Loading

Evengard commented Sep 6, 2023 •

edited

Loading

Kuinox commented Sep 6, 2023 •

edited

Loading

Daniyal-MDKY commented Jan 25, 2024 •

edited

Loading