nunit-console: NUnit.Console.exe sometimes returns with -100 (SocketException)

We are using NUnit.Console.exe v3.16.0 and we are getting a -100 failure sporadically with a System.Net.Sockets.SocketException.

NUnit v3.13.3 NUnit.Console.exe v3.16.0 NUnit.Extension.NUnitV2ResultWriter v3.6.1 NUnit.Extension.OverlayConfig v3.16.0.13 (custom extension built by us)

Hint: I have adjusted all paths/names due to our company policy.

We are running our tests like so (). The test-ids are collected by using the --explore console argument beforehand:

c:\NUnit.ConsoleRunner.3.16.0\nunit3-console.exe "c:\tests\TestAssembly.dll" "/noheader" "/labels:before" "--trace=Debug" "--work=c:\RuntimeLogs" "--out=c:\RuntimeLogs\TestCaseA.txt" "/result=c:\XmlResults\TestCaseA.xml;format=nunit2" --where "id == 1-3702"

In case such an error occurs, only one trace file is being created. In that case InternalTrace.36104.log but no InternalTrace.36104.TestAssembly.dll.log. In case the error do not occur, the second log file is created.

Unfortunately the mentioned nunit-agent_19228.log does not exist in the c:\RuntimeLogs folder. Any hint where it can be found?

InternalTrace.36104.log output:

InternalTrace: Initializing at level Debug
10:11:26.307 Debug [ 1] ServiceManager: Added SettingsService
10:11:26.312 Debug [ 1] ServiceManager: Added RecentFilesService
10:11:26.312 Debug [ 1] ServiceManager: Added TestFilterService
10:11:26.314 Debug [ 1] ServiceManager: Added ExtensionService
10:11:26.314 Debug [ 1] ServiceManager: Added ProjectService
10:11:26.314 Debug [ 1] ServiceManager: Added RuntimeFrameworkService
10:11:26.417 Debug [ 1] ServiceManager: Added TestAgency
10:11:26.418 Debug [ 1] ServiceManager: Added DriverService
10:11:26.418 Debug [ 1] ServiceManager: Added ResultService
10:11:26.418 Debug [ 1] ServiceManager: Added DefaultTestRunnerFactory
10:11:26.419 Info  [ 1] ServiceManager: Initializing SettingsService
10:11:26.421 Info  [ 1] ServiceManager: Initializing RecentFilesService
10:11:26.423 Debug [ 1] ServiceManager: Request for service ISettings satisfied by SettingsService
10:11:26.424 Info  [ 1] ServiceManager: Initializing TestFilterService
10:11:26.424 Info  [ 1] ServiceManager: Initializing ExtensionService
10:11:26.428 Info  [ 1] ExtensionService: Scanning nunit.engine.core assembly for extension points
10:11:26.428 Info  [ 1] ExtensionService:   Found Path=/NUnit/Engine/NUnitV2Driver, Type=NUnit.Engine.Extensibility.IFrameworkDriver
10:11:26.453 Info  [ 1] ExtensionService: Scanning nunit.engine.api assembly for extension points
10:11:26.453 Info  [ 1] ExtensionService:   Found Path=/NUnit/Engine/TypeExtensions/IService, Type=NUnit.Engine.IService
10:11:26.453 Info  [ 1] ExtensionService:   Found Path=/NUnit/Engine/TypeExtensions/ITestEventListener, Type=NUnit.Engine.ITestEventListener
10:11:26.453 Info  [ 1] ExtensionService:   Found Path=/NUnit/Engine/TypeExtensions/IDriverFactory, Type=NUnit.Engine.Extensibility.IDriverFactory
10:11:26.453 Info  [ 1] ExtensionService:   Found Path=/NUnit/Engine/TypeExtensions/IProjectLoader, Type=NUnit.Engine.Extensibility.IProjectLoader
10:11:26.453 Info  [ 1] ExtensionService:   Found Path=/NUnit/Engine/TypeExtensions/IResultWriter, Type=NUnit.Engine.Extensibility.IResultWriter
10:11:26.461 Info  [ 1] ExtensionService: Processing file C:\NUnit.ConsoleRunner.3.16.0\nunit.console.nuget.addins
10:11:26.471 Info  [ 1] ExtensionService: Processing file C:\NUnit.ConsoleRunner.3.16.0\nunit.extensions.addins
10:11:26.511 Info  [ 1] ExtensionService: Scanning directory 'C:\NUnit.Extension.NUnitV2ResultWriter.3.6.1\tools' for extensions.
10:11:26.513 Info  [ 1] ExtensionService: Processing file C:\NUnit.Extension.NUnitV2ResultWriter.3.6.1\tools\net20.engine.addins
10:11:26.644 Info  [ 1] ExtensionService: Scanning directory 'C:\NUnit.Extension.OverlayConfig.3.16.0.132\net48\tools' for extensions.
10:11:26.644 Info  [ 1] ExtensionService: Processing file C:\NUnit.Extension.OverlayConfig.3.16.0.132\net48\tools\NUnit.Extension.OverlayConfig.addins
10:11:26.655 Info  [ 1] ExtensionService: Scanning C:\NUnit.Extension.NUnitV2ResultWriter.3.6.1\tools\net20\nunit-v2-result-writer.dll for Extensions
10:11:26.673 Info  [ 1] ExtensionService:   Found ExtensionAttribute on Type NUnit2XmlResultWriter
10:11:26.675 Info  [ 1] ExtensionService:         ExtensionProperty Format = nunit2
10:11:26.682 Info  [ 1] ExtensionService: Scanning C:\NUnit.Extension.OverlayConfig.3.16.0.132\net48\tools\NUnit.Extension.OverlayConfig.dll for Extensions
10:11:26.686 Info  [ 1] ExtensionService:   Found ExtensionAttribute on Type DriverFactory
10:11:26.686 Info  [ 1] ServiceManager: Initializing ProjectService
10:11:26.688 Debug [ 1] ServiceManager: Request for service ExtensionService satisfied by ExtensionService
10:11:26.690 Info  [ 1] ServiceManager: Initializing RuntimeFrameworkService
10:11:26.690 Info  [ 1] ServiceManager: Initializing TestAgency
10:11:26.691 Debug [ 1] ServiceManager: Request for service IRuntimeFrameworkService satisfied by RuntimeFrameworkService
10:11:26.728 Info  [ 1] ServiceManager: Initializing DriverService
10:11:26.730 Debug [ 1] ServiceManager: Request for service ExtensionService satisfied by ExtensionService
10:11:26.734 Info  [ 1] ServiceManager: Initializing ResultService
10:11:26.734 Debug [ 1] ServiceManager: Request for service ExtensionService satisfied by ExtensionService
10:11:26.735 Info  [ 1] ServiceManager: Initializing DefaultTestRunnerFactory
10:11:26.735 Debug [ 1] ServiceManager: Request for service IProjectService satisfied by ProjectService
10:11:26.735 Debug [ 1] ServiceManager: Request for service IResultService satisfied by ResultService
10:11:26.735 Debug [ 1] ServiceManager: Request for service ITestFilterService satisfied by TestFilterService
10:11:26.735 Debug [ 1] ServiceManager: Request for service IExtensionService satisfied by ExtensionService
10:11:26.822 Debug [ 1] ServiceManager: Request for service IProjectService satisfied by ProjectService
10:11:26.822 Debug [ 1] ServiceManager: Request for service ITestRunnerFactory satisfied by DefaultTestRunnerFactory
10:11:26.823 Debug [ 1] ServiceManager: Request for service IRuntimeFrameworkService satisfied by RuntimeFrameworkService
10:11:26.823 Debug [ 1] ServiceManager: Request for service ExtensionService satisfied by ExtensionService
10:11:27.289 Debug [ 1] RuntimeFrameworkService: Assembly C:\bin\TestAssembly.dll uses version 4.0.30319
10:11:27.289 Debug [ 1] RuntimeFrameworkService: Assembly C:\bin\TestAssembly.dll targets .NETFramework,Version=v4.8
10:11:27.294 Debug [ 1] RuntimeFrameworkService: Current framework is net-4.5
10:11:27.294 Debug [ 1] RuntimeFrameworkService: No specific framework requested for TestAssembly.dll
10:11:27.295 Debug [ 1] RuntimeFrameworkService: Test will use net-4.8 for TestAssembly.dll
10:11:27.295 Debug [ 1] RuntimeFrameworkService: Current framework is net-4.5
10:11:27.295 Debug [ 1] RuntimeFrameworkService: No specific framework requested for 
10:11:27.295 Debug [ 1] RuntimeFrameworkService: Test will use net-4.8 for 
10:11:27.297 Debug [ 1] ServiceManager: Request for service ITestRunnerFactory satisfied by DefaultTestRunnerFactory
10:11:27.297 Debug [ 1] ServiceManager: Request for service TestAgency satisfied by TestAgency
10:11:27.298 Info  [ 1] ProcessRunner: Running 
10:11:27.308 Debug [ 1] AgentProcess: TargetRuntime = net-4.8
10:11:27.311 Debug [ 1] AgentProcess: GetTestAgentExePath(net-4.8, False)
10:11:27.311 Debug [ 1] AgentProcess: Checking for agents at C:\NUnit.ConsoleRunner.3.16.0\agents
10:11:27.311 Debug [ 1] AgentProcess: Using nunit-agent at C:\NUnit.ConsoleRunner.3.16.0\agents\net462\nunit-agent.exe
10:11:27.485 Debug [ 1] TestAgency: Launched Agent process 19228 - see nunit-agent_19228.log
10:11:27.485 Debug [ 1] TestAgency: Command line: "C:\NUnit.ConsoleRunner.3.16.0\agents\net462\nunit-agent.exe" f7ac21be-2ad1-4a57-a7c8-1df7e39a7360 tcp://127.0.0.1:57615/TestAgency-93b26a3d-c6b2-4979-ac64-8419bbcfb5a6 --pid=36104 --trace=Debug --work=C:\RuntimeLogs
10:11:27.489 Debug [ 1] TestAgency: Waiting for agent {f7ac21be-2ad1-4a57-a7c8-1df7e39a7360} to register
10:11:28.100 Debug [ 1] TestAgency: Returning new agent {f7ac21be-2ad1-4a57-a7c8-1df7e39a7360}
10:13:05.513 Info  [ 1] ProcessRunner: Done running 
10:13:05.529 Info  [ 1] ProcessRunner: Unloading 
10:13:05.717 Debug [ 1] ProcessRunner: Stopping remote agent
10:13:05.967 Info  [ 1] ServiceManager: Stopping DefaultTestRunnerFactory
10:13:05.967 Info  [ 1] ServiceManager: Stopping ResultService
10:13:05.967 Info  [ 1] ServiceManager: Stopping DriverService
10:13:05.967 Info  [ 1] ServiceManager: Stopping TestAgency
10:13:05.967 Info  [ 1] ServiceManager: Stopping RuntimeFrameworkService
10:13:05.982 Info  [ 1] ServiceManager: Stopping ProjectService
10:13:05.982 Info  [ 1] ServiceManager: Stopping ExtensionService
10:13:05.982 Info  [ 1] ServiceManager: Stopping TestFilterService
10:13:05.982 Info  [ 1] ServiceManager: Stopping RecentFilesService
10:13:05.982 Info  [ 1] ServiceManager: Stopping SettingsService

Test output:

Test console output:
Runtime Environment
   OS Version: Microsoft Windows NT 6.2.9200.0
   Runtime: .NET Framework CLR v4.0.30319.42000

Test Files
    C:\bin\TestAssembly.dll

Test Filters
    Where: id == 1-3702

System.Net.Sockets.SocketException : An existing connection was forcibly closed by the remote host

--SocketException
An existing connection was forcibly closed by the remote host

Server stack trace: 
   at System.Runtime.Remoting.Channels.SocketStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Runtime.Remoting.Channels.SocketHandler.ReadFromSocket(Byte[] buffer, Int32 offset, Int32 count)
   at System.Runtime.Remoting.Channels.SocketHandler.Read(Byte[] buffer, Int32 offset, Int32 count)
   at System.Runtime.Remoting.Channels.Tcp.TcpFixedLengthReadingStream.Read(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.BinaryReader.ReadBytes(Int32 count)
   at System.Runtime.Serialization.Formatters.Binary.SerializationHeaderRecord.Read(__BinaryParser input)
   at System.Runtime.Serialization.Formatters.Binary.__BinaryParser.ReadSerializationHeaderRecord()
   at System.Runtime.Serialization.Formatters.Binary.__BinaryParser.Run()
   at System.Runtime.Serialization.Formatters.Binary.ObjectReader.Deserialize(HeaderHandler handler, __BinaryParser serParser, Boolean fCheck, Boolean isCrossAppDomain, IMethodCallMessage methodCallMessage)
   at System.Runtime.Serialization.Formatters.Binary.BinaryFormatter.Deserialize(Stream serializationStream, HeaderHandler handler, Boolean fCheck, Boolean isCrossAppDomain, IMethodCallMessage methodCallMessage)
   at System.Runtime.Remoting.Channels.CoreChannel.DeserializeBinaryResponseMessage(Stream inputStream, IMethodCallMessage reqMsg, Boolean bStrictBinding)
   at System.Runtime.Remoting.Channels.BinaryClientFormatterSink.SyncProcessMessage(IMessage msg)

Exception rethrown at [0]: 
   at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
   at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
   at NUnit.Engine.ITestAgent.Stop()
   at NUnit.Engine.Runners.ProcessRunner.Dispose(Boolean disposing)
   at NUnit.Engine.Runners.AbstractTestRunner.Dispose()
   at NUnit.Engine.Runners.MasterTestRunner.Dispose(Boolean disposing)
   at NUnit.Engine.Runners.MasterTestRunner.Dispose()
   at NUnit.ConsoleRunner.ConsoleRunner.RunTests(TestPackage package, TestFilter filter)
   at NUnit.ConsoleRunner.Program.Main(String[] args)

About this issue

Original URL
State: open
Created 2 years ago
Comments: 70 (27 by maintainers)

Most upvoted comments

Hi there,

we were able to reproduce the issue on our end. This issue appears to be reproducible reliably when run with the -x86 flag for the nunit3-console. It’s also flaky on our end when run without that.

I attached a zipped test project to reproduce the issue. It contains a dummy test project targeted at net7.0 and a PowerShell file with the exact command we used along with the outcome that resulted in on our end, including the console output and an additional windows application error event with another interesting stack trace. Feel free to contact me for more information.

JensLeible on Apr 27, 2023

@saiparth Sorry for the delay here, we’re re-organizing, so… But will see if we can figure this one out.

OsirisTerje on Feb 20, 2023

Yeah… I am on travels right now, but back next week. I’ll try to get it out during that week.

OsirisTerje on Aug 23, 2023

The adapter with @Lorilatschki 's PRs are here: https://www.myget.org/feed/nunit/package/nuget/NUnit3TestAdapter/4.5.0-dev-02467

OsirisTerje on Aug 4, 2023

@Lorilatschki Thanks a lot for this work! It’s really appreciated!
I’ll raise an issue in the adapter repo to connect these PRs, so that I can get it into the release notes.

OsirisTerje on Aug 3, 2023

I don’t think this is suiteable since the filenames should be predictable as we have some post processing of the files. Currently we are storing all results in the same folder, if we use the NUnit.NewOutputXmlFileForEachRun=true setting, this will most likely fail since properly up to 80 tests are running in parallel and file sync’s will only work safely in case they use a mutex, otherwise it can happen, that after test1 has not found a file named test.xml it assumes it is free but in the very same moment test2 creates such a file which will result in a file access violation.

So without the possibilty to define a own result file name, we cannot easily change to dotnet test.

We do have another issue which will arise when moving to dotnet test. As I said, we do have some specific test tools within our test environment as well as a requirement, that for one of our module to test, it is necessary that the test host is signed with a specific key file. In our case, we do that by packing our own NUnit.ConsoleRunner by simply signing the nunit3-console.exe. I know this sound wierd, but for this specific kind of tests we cannot change this requirement.

As a consequence we would love to get this fixed within the NUnit.ConsoleRunner itself, because switching to dotnet test will be huge effort and has some downsites due to the above mentioned aspects.

We much appreciate your support!

Lorilatschki on Aug 2, 2023

@OsirisTerje we try to setup several runs using the dotnet test instead of the nunit.console. We will update on this once we do have succeeded on that.

Lorilatschki on Aug 1, 2023

Hi there,

one of our build servers managed to run the tests without problems. After some comparisons of the environment it turns out that the .NET SDK version has been different. It failed on all build servers with .NET SDK 7.0.100. The successful one had .NET SDK 7.0.109 installed. After updating the other servers to .NET SDK 7.0.109, the tests run successfully there, too.

JensLeible on Aug 1, 2023

I just tested with 3.16.2 and it is also reliably reproducing the issue on my machine.

An update on what I said about our build servers though: I tested the project there and it did not fail. However the “real” CI build chain for our projects did fail reliably with the -x86 flag. I cannot yet say what makes the difference there.

Anyway, your assumption is correct. It seems somewhat related to the Windows build.

JensLeible on May 8, 2023