nunit / nunit/nunit-console

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

Open
#1,276 74 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Investigate Needs Confirmation V4
Dominant language
C#
Stars
234
Forks
163
Avg merge
13h 32m
Merged PRs (30d)
25

Description

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)

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with the NUnit.Console.exe command, the InternalTrace.36104.log output, and the reported nunit-agent_19228.log path. Compare runs that create both trace files with runs that return -100, focusing on the agent connection and stop sequence. Done means the sporadic SocketException is reproducible or explained and the missing agent log location or handling is clarified.

Written by the indexing model from the issue text.

Assessment

Tech stack
csharp
Domain
cli, testing
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.