nunit-console
nunit-console copied to clipboard
nunit
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)
@Lorilatschki Did this process work before you upgraded to 3.16?
This may be related to #1275.
@CharliePoole this also fails sporadically with 3.15.0 and 3.15.2. Other versions we didn‘t tested yet because we recently changed from v2.x. I will have a look into your mentioned issue.
@CharliePoole I did't see the mentioned related issue #1275 realy related to this issue because it then would fail constantly, but it only fails in a sporadic manner.
Do you know where the nunit.console is storing the nunit-agent_*.log because it is not saved to the given --work folder?
The logs should all be found in the same directory. The agent could simply be failing before it creates the named log. Does the log appear when there is no failure?
Unforunately not. I have run a test locally which succeeded. The InternalTrace.*.log has been created in the --work folder and contained following:
...
14:20:53.529 Debug [ 1] TestAgency: Launched Agent process 39648 - see nunit-agent_39648.log
...
The nunit-agent_39648.log does not exist on my drive. I have searched the whole drive, I doesn't found it. But different to the failing case, there are 2 InternalTrace.*.log files. Does the second one seem to be the one for the nunit-agent.exe process which is invoked by the nunit-console.exe because the PIDs are matching (39648) and the second trace file is exactly named InternalTrace.39648.log?
I have checked the failing case scenario and indeed I found the second trace file by searching for PID of the nunit-agent.exe process. The trace output is:
InternalTrace: Initializing at level Debug
10:11:27.720 Info [ 1] ExtensionService: Scanning nunit.engine.core assembly for extension points
10:11:27.730 Info [ 1] ExtensionService: Found Path=/NUnit/Engine/NUnitV2Driver, Type=NUnit.Engine.Extensibility.IFrameworkDriver
10:11:27.774 Info [ 1] ExtensionService: Scanning nunit.engine.api assembly for extension points
10:11:27.775 Info [ 1] ExtensionService: Found Path=/NUnit/Engine/TypeExtensions/IService, Type=NUnit.Engine.IService
10:11:27.775 Info [ 1] ExtensionService: Found Path=/NUnit/Engine/TypeExtensions/ITestEventListener, Type=NUnit.Engine.ITestEventListener
10:11:27.775 Info [ 1] ExtensionService: Found Path=/NUnit/Engine/TypeExtensions/IDriverFactory, Type=NUnit.Engine.Extensibility.IDriverFactory
10:11:27.775 Info [ 1] ExtensionService: Found Path=/NUnit/Engine/TypeExtensions/IProjectLoader, Type=NUnit.Engine.Extensibility.IProjectLoader
10:11:27.775 Info [ 1] ExtensionService: Found Path=/NUnit/Engine/TypeExtensions/IResultWriter, Type=NUnit.Engine.Extensibility.IResultWriter
10:11:27.783 Info [ 1] ExtensionService: Processing file C:NUnitV3.x\bin\NUnit.ConsoleRunner.3.16.0\agents\net462\nunit.agent.addins
10:11:27.788 Info [ 1] ExtensionService: Scanning directory 'C:NUnitV3.x\bin\NUnit.ConsoleRunner.3.16.0' for extensions.
10:11:27.789 Info [ 1] ExtensionService: Processing file C:NUnitV3.x\bin\NUnit.ConsoleRunner.3.16.0\nunit.console.nuget.addins
10:11:27.792 Info [ 1] ExtensionService: Processing file C:NUnitV3.x\bin\NUnit.ConsoleRunner.3.16.0\nunit.extensions.addins
10:11:27.800 Info [ 1] ExtensionService: Scanning directory 'C:NUnitV3.x\bin\NUnit.Extension.NUnitV2ResultWriter.3.6.1\tools' for extensions.
10:11:27.801 Info [ 1] ExtensionService: Processing file C:NUnitV3.x\bin\NUnit.Extension.NUnitV2ResultWriter.3.6.1\tools\net20.engine.addins
10:11:27.900 Info [ 1] ExtensionService: Scanning directory 'C:NUnitV3.x\bin\NUnit.Extension.OverlayConfig.3.16.0.132\net48\tools' for extensions.
10:11:27.901 Info [ 1] ExtensionService: Processing file C:NUnitV3.x\bin\NUnit.Extension.OverlayConfig.3.16.0.132\net48\tools\NUnit.Extension.OverlayConfig.addins
10:11:27.908 Info [ 1] ExtensionService: Scanning C:NUnitV3.x\bin\NUnit.Extension.NUnitV2ResultWriter.3.6.1\tools\net20\nunit-v2-result-writer.dll for Extensions
10:11:27.924 Info [ 1] ExtensionService: Found ExtensionAttribute on Type NUnit2XmlResultWriter
10:11:27.925 Info [ 1] ExtensionService: ExtensionProperty Format = nunit2
10:11:27.932 Info [ 1] ExtensionService: Scanning C:NUnitV3.x\bin\NUnit.Extension.OverlayConfig.3.16.0.132\net48\tools\NUnit.Extension.OverlayConfig.dll for Extensions
10:11:27.941 Info [ 1] ExtensionService: Found ExtensionAttribute on Type DriverFactory
10:11:27.956 Info [ 1] TestAgentRemotingTransport: Agent starting
10:11:27.983 Info [ 1] TestAgentRemotingTransport: Connecting to TestAgency at tcp://127.0.0.1:57615/TestAgency-93b26a3d-c6b2-4979-ac64-8419bbcfb5a6
10:11:28.084 Debug [ 1] TestAgentRemotingTransport: Registered agent with TestAgency
10:11:28.412 Info [ 5] DomainManager: Creating application domain domain-
10:11:28.421 Debug [ 5] DriverService: Trying DriverFactory
10:11:28.598 Info [ 5] NUnitFrameworkDriver: Loading TestAssembly.dll - see separate log file
10:11:29.376 Info [ 5] NUnitFrameworkDriver: Loaded TestAssembly.dll
10:11:29.377 Info [ 5] NUnitFrameworkDriver: Running TestAssembly.dll - see separate log file
10:13:05.732 Info [ 5] TestAgentRemotingTransport: Stopping
10:13:05.732 Info [47] TestAgentRemotingTransport: Waiting for messages to complete
10:13:05.732 Info [47] TestAgentRemotingTransport: Attempting shut down channel
10:13:05.732 Info [47] TestAgentRemotingTransport: Set stop signal
So no trace output other than Info/Debug 😞 and compared to the success case the same output at the end (Set stop signal).
@CharliePoole any idea how to proceed on that? We still getting this error regularly in a sporadic manner.
@Lorilatschki Best best would be for you to create a non-intermittent repro, if possible.
There seems to be an associated issue here as well: the main log tells you to look for an nunit_agent_*.log file but it is actually created by the agent process with a different name.
FYI I'm actually no longer working on this project but I'm sure someone on the @nunit/engine-team will have to look at this.
- System.Net.Sockets.SocketException. (I downloaded the zip file from https://nunit.org/download/ and using without installing) I am also facing same issue. Nunit 3.16 console Nunit version is 3.13.3
<message><![CDATA[System.Net.Sockets.SocketException : An existing connection was forcibly closed by the remote host]]></message>
<stack-trace><![CDATA[--SocketException
An existing connection was forcibly closed by the remote host
at NUnit.Engine.Communication.Transports.Tcp.SocketReader.GetNextMessage() in C:\Users\charlie\dev\NUnit\nunit-console\src\NUnitEngine\nunit.engine.core\Communication\Transports\Tcp\SocketReader.cs:line 42
at NUnit.Engine.Communication.Transports.Tcp.TestAgentTcpProxy.TestRunResult(ITestEventListener listener) in C:\Users\charlie\dev\NUnit\nunit-console\src\NUnitEngine\nunit.engine\Communication\Transports\Tcp\TestAgentTcpProxy.cs:line 116
at NUnit.Engine.Runners.ProcessRunner.RunTests(ITestEventListener listener, TestFilter filter) in C:\Users\charlie\dev\NUnit\nunit-console\src\NUnitEngine\nunit.engine\Runners\ProcessRunner.cs:line 138
]]></stack-trace>
This issue is inconsistent and I am not sure where to find agent logs. 2. In some cases below exception is displayed.
2023-01-25T03:00:21.0413325Z 1) Error :
2023-01-25T03:00:21.0414701Z
2023-01-25T03:00:21.0436746Z NUnit.Engine.NUnitEngineException : Unable to acquire remote process agent
2023-01-25T03:00:21.0438162Z
2023-01-25T03:00:21.0460690Z --NUnitEngineException
2023-01-25T03:00:21.0462073Z
2023-01-25T03:00:21.0484546Z Unable to acquire remote process agent
2023-01-25T03:00:21.0485932Z
2023-01-25T03:00:21.0508134Z at NUnit.Engine.Runners.ProcessRunner.CreateAgentAndRunnerIfNeeded() in C:\Users\charlie\dev\NUnit\nunit-console\src\NUnitEngine\nunit.engine\Runners\ProcessRunner.cs:line 253
2023-01-25T03:00:21.0509482Z
2023-01-25T03:00:21.0531623Z at NUnit.Engine.Runners.ProcessRunner.RunTests(ITestEventListener listener, TestFilter filter) in C:\Users\charlie\dev\NUnit\nunit-console\src\NUnitEngine\nunit.engine\Runners\ProcessRunner.cs:line 138
2023-01-25T03:00:21.0532968Z
2023-01-25T03:00:21.0555224Z
2023-01-25T03:00:21.0556657Z
@ nunit/engine-team do you have any idea to get more details about the issue?
Hi @OsirisTerje Can you please check or inform any team member. We are facing lot of challenges due to this issue and not able to understand why this occurs. I believe below bugs are also somewhat similar. https://github.com/nunit/nunit-console/issues/1189 https://github.com/nunit/nunit-console/issues/1190 https://github.com/nunit/nunit-console/issues/1262
@saiparth Sorry for the delay here, we're re-organizing, so..... But will see if we can figure this one out.
@saiparth
Sorry, no update yet. These issues are hard to figure out.
- Do you have any possibility to provide some kind of repro for this?
- I understand you're in the process of moving tests from NUnit V2 and up to V3. Can you also use only the V3 report schema, and skip whatever is in V2?
- Any possibility for moving off the console and using dotnet test instead ?
@OsirisTerje Thanks for replying. Sorry. I wont able to share any repo because why it happens I don't know. It works most of the time. Only thing I suspect is, during 1000+ test run, server will be slow, In that case NUnit agent is not able to register within timeout(30 seconds may be) and fails. Reducing worker count and Server restart once in a week is the workaround I am fallowing now.
Framework was upgraded from 4.6 to 6. hence I wont be able to use any previous version. I cant because my reports have some dependency and I created utility for retry based on Nunit xml results.
@saiparth Sorry, I didn't mean to share your production code. But if you could create a small repro with some slow tests that would repro this. You know the situation, so more straightforward for you to create something.
It may very well be a timeout issue. Have you looked at the source code and seen something that concerns you in that respect?
I could not find anything so far, I will get back to you when I am able to reproduce the issue. there is no specific use-case, its 4000 tests running in app server everyday for over a week. Selenium and Rest sharp are used
Same on our site. We run about 2000 tests/fixtures each run (up to 128 in parallel dependend on our agent hardware set). Almost every second run we do have at least one failure saying
nunit-console.exe failed with error code -100
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)
It is always a different test which fails.
@Lorilatschki
- Does this happen also when you run tests locally?
- Can you provide a repro ?
@OsirisTerje
Does this happen also when you run tests locally?
Yes is also occurs locally!
Can you provide a repro?
Due to our company policy we are not able to share this, sorry!
@Lorilatschki We don't want nor need your company code. We need a repro from you, fake code, which is organized so that the error you report can be reproduced. Then we have a better chance of fixing it.
Since you confirm it also fails locally, then we have a much better chance of finding out what's going wrong here, but we need code that fails.
The other option is that you simply build the console code yourself, in debug mode, use that in your local build and then grab more information from that, possibly also being able to debug into the console/engine.
Since you confirm it also fails locally, then we have a much better chance of finding out what's going wrong here, but we need code that fails
Since we do not know which is the root cause of the failure, it is hard to create a repo for that. I assume it is enough to run a banch of tests in parallel and from time to time this failure ocurrs. I can give it a try if I can easily create a repo to repoduce the issue.
The other option is that you simply build the console code yourself, in debug mode, use that in your local build and then grab more information from that, possibly also being able to debug into the console/engine.
What do you mean grap more information from that? What information do you expect are part of the console code in debug mode rather than release?
@OsirisTerje meanwhile we have enabled windows dump file creation for
nunit3-console.exe
nunit-agent.exe
on all our agents. Hopefully we get a dump created in the -100 scenario. If so, would that help as well?
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.
I'd like to emphasize that this is an important topic for us, since our CI build chain does not run reliably without it being fixed. The respective builds fail quite frequently. Would it be possible to provide a rough estimation on how long it will take to implement and release a fix. Thanks in advance!
I am sorry it is not possible to give any ETA for a fix. The engine/console team is currently very small, and we're all occupied with the NUnit framework work. The console/engine is also in a mixed state now, with version 3.15.X, 3.16.X and 4.X diverging. We need to get those aligned. I will try to get time to look into your repro asap, so that I at least get an idea of what is going on.
That said, since you now have a repro, and the source code is fully available, you could make a try to dive into it, possibly also making some debugging changes along the way in the code, let it write out something useful, or even use the debugger to see if that helps. That is more or less the same approach we would take here.
I just ran your repro, multiple times too. I did use the 16.2 version which I already had installed, and it run with no errors. Have you tried this on different machines?
Mine is a Windows 10 Pro, lots of RAM and CPU.
Please have a look at the content of the TestOutputOnMyMachine directory of the test project. The ProducedPowerShellConsole.log states that I was running NUnit Console 3.16.3 (Release). OS Version is the same as in your log.
Only difference is we are running Windows 10 Enterprise LTSC (Version 10.0.17763 Build 17763).
The build server is running Windows 10 Enterprise, Version 22H2, OS build 19045.2846 , Experience Windows Feature Experience Pack 120.2212.4190.0
I would rather suspect the different console/enginge version being the reason for it not failing? Sorry for not mentioning the Windows Version in the README.md. I forgot about that.