Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
Lorilatschki opened this issue Dec 1, 2022 · 72 comments
Open

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

Lorilatschki opened this issue Dec 1, 2022 · 72 comments
Labels
Investigate We are looking into the issue

Comments

@Lorilatschki
Copy link

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)
@CharliePoole
Copy link
Collaborator

@Lorilatschki Did this process work before you upgraded to 3.16?

This may be related to #1275.

@Lorilatschki
Copy link
Author

@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.

@Lorilatschki
Copy link
Author

Lorilatschki commented Dec 2, 2022

@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?

@CharliePoole
Copy link
Collaborator

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?

@Lorilatschki
Copy link
Author

Lorilatschki commented Dec 2, 2022

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?

@Lorilatschki
Copy link
Author

Lorilatschki commented Dec 2, 2022

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 CharliePoole added this to the 3.16.1 milestone Dec 3, 2022
@CharliePoole CharliePoole removed this from the 3.16.1 milestone Jan 1, 2023
@Lorilatschki
Copy link
Author

@CharliePoole any idea how to proceed on that? We still getting this error regularly in a sporadic manner.

@CharliePoole
Copy link
Collaborator

@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.

@saiparth
Copy link

saiparth commented Jan 25, 2023

  1. 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 

@Lorilatschki
Copy link
Author

@saiparth do you get this error sporadically or constantly?

@saiparth
Copy link

@Lorilatschki
sporadically.

@Lorilatschki
Copy link
Author

@ nunit/engine-team do you have any idea to get more details about the issue?

@saiparth
Copy link

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.
#1189
#1190
#1262

@OsirisTerje
Copy link
Member

OsirisTerje commented Feb 20, 2023

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

@saiparth
Copy link

Hi @OsirisTerje
Any update on this issue?

@OsirisTerje
Copy link
Member

@saiparth

Sorry, no update yet. These issues are hard to figure out.

  1. Do you have any possibility to provide some kind of repro for this?
  2. 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?
  3. Any possibility for moving off the console and using dotnet test instead ?

@saiparth
Copy link

@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.

@OsirisTerje
Copy link
Member

@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?

@saiparth
Copy link

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

@Lorilatschki
Copy link
Author

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.

@OsirisTerje
Copy link
Member

@Lorilatschki

  1. Does this happen also when you run tests locally?
  2. Can you provide a repro ?

@OsirisTerje OsirisTerje added the Repro needed We need a short small repro for this issue. label Apr 21, 2023
@Lorilatschki
Copy link
Author

Lorilatschki commented Apr 21, 2023

@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!

@OsirisTerje
Copy link
Member

OsirisTerje commented Apr 21, 2023

@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.

@Lorilatschki
Copy link
Author

Lorilatschki commented Apr 21, 2023

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?

@Lorilatschki
Copy link
Author

@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?

@JensLeible
Copy link

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.

@OsirisTerje OsirisTerje removed the Repro needed We need a short small repro for this issue. label Apr 27, 2023
@Lorilatschki
Copy link
Author

We kind of stick to net48 for the product we are facing the sporadic issues.
For that we still seeing a lot of sporadic failures. So updating to the latest dotnet 7 sdk will not help!

@OsirisTerje
Copy link
Member

@Lorilatschki Do you see the same sporadic issues if you use dotnet test instead of nunit.console ?

@Lorilatschki
Copy link
Author

@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
Copy link
Author

Lorilatschki commented Aug 2, 2023

@OsirisTerje we are using the --where id=xxx filter to filter for concrete fixtures, this cannot be achived within the nunit3adapter since it only implement the following, right?

  • FullyQualifiedName
  • Name
  • TestCategory
  • Priority

I have also tried to setup the RunSettings UseNUnitIdforTestCaseId to true via -- RunSettings.UseNUnitIdforTestCaseId=true but it doesn't work either.

@OsirisTerje
Copy link
Member

OsirisTerje commented Aug 2, 2023

@Lorilatschki The adapter can also use the where filter, see https://docs.nunit.org/articles/vs-test-adapter/Tips-And-Tricks.html#where

And don't use the UseNUnitIdforTestCaseId :-)

@Lorilatschki
Copy link
Author

@OsirisTerje unfortunately it doesn't work. The name of the test fixture is MyTestCase and the id is 1-1012. The id was determined via the --explore argument through the nunit3-console.exe.

When I run

dotnet test "C:\temp\myTeset.dll" --test-adapter-path C:\temp\NUnit3TestAdapter\build\net48 -- NUnit.Where="id == 1-1012"

it states that there is no matching test No test is available. When I use the name filter like

dotnet test "C:\temp\myTeset.dll" --test-adapter-path C:\temp\NUnit3TestAdapter\build\net48 -- NUnit.Where="name == MyTestCase"

it works as expected and the test can be found and is executed. Any idea what I am doing wrong?

@OsirisTerje
Copy link
Member

I would not trust the id to be the same. To determine the id in this case, use the dump flag and check if that actually is the same. https://docs.nunit.org/articles/vs-test-adapter/Tips-And-Tricks.html#dumpxmltestdiscovery-and-dumpxmltestresults

But, do you actually need the id's ?

@Lorilatschki
Copy link
Author

To determine the id in this case, use the dump flag and check if that actually is the same.

I will give it a try.

But, do you actually need the id's ?

This is hard to explain but let me try it shortly. Because we do have a lot of test dependency tools for our tests, they cannot be run in parallel out of the box, because some of them may not run together with some others. Since we do have a lot of tests and we wanted to take advantage of a parallel test execution we defined some attributes on our tests which are kind of blueprint how the test can run in parallel.
Therefor we made some kind of test executer which collects all the tests (on fixture level) and than uses the nunit.console.exe to execute it.
Since in nunit3 the explore was offered, we are determining the test fixtures using this command. Each and every testcase/fxiture has its own unique id, therefor we decided to use this in order to pass it into the where filter.

We can change the filter under the hood to use the testname instead of the test id, but all that expense to run dotnet test instead of the console without knowing if this will fix this issue is kind of daring.

@Lorilatschki
Copy link
Author

In fact the id's between the nunit.console3.exe --explore command and the NUnit3TestAdapter are not the same.
Is there a way to explore/list the tests using the dotnet test command including the ids? I have tried the --list-tests argument but it only print out the test names.

@OsirisTerje
Copy link
Member

OsirisTerje commented Aug 2, 2023

If you're using --list-tests it should run the discovery, and then you would have the id's in the discovery dump file.

[Thinking] It may be possible to get more info out (without using the dump file) by using the --logger "console;verbosity=normal"....
UPDATE: Just tried it, and it didnt output more, so... you have to use the dump file

@Lorilatschki
Copy link
Author

Lorilatschki commented Aug 2, 2023

UPDATE: Just tried it, and it didnt output more, so... you have to use the dump file

I cannot see a dump file in case I execute it with --list-tests, where is it stored?

@OsirisTerje
Copy link
Member

OsirisTerje commented Aug 2, 2023

dotnet test --list-tests -- NUnit.DumpXmlTestDiscovery=true

NOTE: There are seperate dump commands for discovery and execution

One below your workfolder, aka bin folder

E.g. bin\debug\net6.0\dump

@Lorilatschki
Copy link
Author

Lorilatschki commented Aug 2, 2023

Thanks for the hint, the dump file is created and the ids are part of it. One last question:

In order to give it a try, I need to specify the nunit result file name. Within the nunit.console3.exe we do it that way:

/result=D:\temp\myTestResultFile.xml;format=nunit2

NOTE: We are using the nunit2 format since we have a test result overview generation tool which was developed against the nunit2 schema. In order to avoid adapting this tool we use the nunit2 format extension.

Is there a way to easily achive this via dotnet test?

@OsirisTerje
Copy link
Member

OsirisTerje commented Aug 2, 2023

You should really try to get off that format :-)
There actually is a NUnit2 result writer extension for the engine. You might already be using that with the console. I have never used it with the NUnit3 system, so I am on thin ice here. But making that work with the adapter, I don't think that is possible without doing a code change.
The adapter has an extension point, which is used for calling into report extensions, but it is currently hardcoded to the nunit3 format. It was the intention to allow this to be configurable, but since there are only two relevant formats, and one is deprecated (nunit2), it never got any traction. It is this code line https://github.com/nunit/nunit3-vs-adapter/blob/76b0d3dd48946f61e976c122db3f211fb1c7196a/src/NUnitTestAdapter/NUnitEngine/NUnitEngineAdapter.cs#L171
It might be that if the engine is set up to load the extension, and this line is changed to nunit2 it might work, but I would not bet too much on it.
The extension however, could be used to convert the NUnit3 to NUnit2 format, if we wrapped it in a console app. See https://github.com/nunit/nunit-v2-result-writer
There are also tools to convert between them like https://github.com/wooga/NUnit3-to-NUnit2-Format-Converter

The best is if you can check if it works to run the tests with dotnet test, and if that fails or not the same way. I have never seen any errors like this with the dotnet test/adapter, so that is why I am asking.

To set the result file, use the TestOutputXml command

@Lorilatschki
Copy link
Author

Regarding the nunit2 format, we can get rid of it by adapting our overview generator to that.

To set the result file, use the TestOutputXml command

Unfortunately this way you can only define the output folder rather than the output filename! Since we are running tests in parallel and the default name is the name of the test assembly (independend to what the fixture name is) there will be confilicts across the filenames. As I found in a separate issue, setting up the name of the result file is not possible yet within dotnet test.

@OsirisTerje
Copy link
Member

You can set the NewOutputXmlFileForEachRun to True and it will create new files if there already is a file with that name. You will then get whatever.xml, whatever.1.xml, whatever.2.xml and so on.

@Lorilatschki
Copy link
Author

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!

@OsirisTerje
Copy link
Member

OsirisTerje commented Aug 2, 2023

To change things in the adapter is rather easy, so nunit/nunit3-vs-adapter#1114 could be fixed. Also including a mutex for the file creation (good point), alternatively added a guid to the filename to make them unique.

Fixing the socket exception in the console though, is quite a different thing. We do need a working repro, which we don't have, and then we have some uncharted territory to go through there. The NUnit.Console covers much more than the adapter based system, and we don't have anyone focused on the console right now.

I'll try to collect together the different console issues that seems related and see if there are any good hints on what is actually causing this.

Note also that you could build the console/engine code yourself try to get some more debugging information in there. In particular in the NUnit.Engine.ITestAgent.Stop() method (this is an interface, so there are two possible implementation which could be the culprit) where the crash seems to originate. Running a debug version might also give some more information.

First, figure out which implementation is actually being used here, by adding some debug output in those two methods. Then perhaps try a catch socketexception there.
It would be much faster if you build this locally and create a nuget package locally that you can use for this purpose.

ALTERNATIVELY: I could do some changes to get more debug info in, and release that out to our Myget feed. This would be more slow though, but the fact you have something where this is reproduced makes it interesting.

@Lorilatschki
Copy link
Author

ALTERNATIVELY: I could do some changes to get more debug info in, and release that out to our Myget feed. This would be more slow though, but the fact you have something where this is reproduced makes it interesting.

That sounds great, can you give a update once you have deployed such a version to the Myget feed?

To change things in the adapter is rather easy, so nunit/nunit3-vs-adapter#1114 could be fixed. Also including a mutex for the file creation (good point), alternatively added a guid to the filename to make them unique.

If I have some free time I can fix it and creating MRs out of it. Regarding the naming issue, shall I add a new RunSettings property TestOutputXmlFileName where clients can setup a predefined name for the result file?

@Lorilatschki
Copy link
Author

@OsirisTerje
Copy link
Member

@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.

@Lorilatschki
Copy link
Author

@Lorilatschki Thanks a lot for this work! It's really appreciated!

Same to me, your support is amazing!

@OsirisTerje
Copy link
Member

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

@Lorilatschki
Copy link
Author

@OsirisTerje since we figured out that using the dotnet test is not suiteable in our case, can I kindly ask you to provide a console package with further debug output according to?

ALTERNATIVELY: I could do some changes to get more debug info in, and release that out to our Myget feed. This would be more slow though, but the fact you have something where this is reproduced makes it interesting.

@OsirisTerje
Copy link
Member

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

@lsoft
Copy link

lsoft commented Oct 20, 2023

we are moving our system from net48 to net6.0 (with its tests of course) and started to see this issue:

NUnit.Engine.NUnitEngineException: Remote test agent exited with non-zero exit code -532462766
      NUnit.Engine.Services.TestAgency.OnAgentExit(Process process, Guid agentId)
      NUnit.Engine.Services.TestAgency.<>c__DisplayClass13_0.<GetAgent>b__0(Object sender, EventArgs e)
      System.Diagnostics.Process.OnExited()
      System.Diagnostics.Process.RaiseOnExited()
      System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
      System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
      System.Threading._ThreadPoolWaitOrTimerCallback.PerformWaitOrTimerCallback(Object state, Boolean timedOut)
  
  Errors, Failures and Warnings
  
  1) Error : 
  System.Net.Sockets.SocketException : An existing connection was forcibly closed by the remote host

      NUnit.Engine.Communication.Transports.Tcp.SocketReader.GetNextMessage()
      NUnit.Engine.Communication.Transports.Tcp.TestAgentTcpProxy.TestRunResult(ITestEventListener listener)
      NUnit.Engine.Runners.ProcessRunner.RunTests(ITestEventListener listener, TestFilter filter)

is this is related with the topicstarter's issue? should I create a new issue? if this is the same issue,. am I correct, that the reasons are not fully known?

thank you!

@OsirisTerje
Copy link
Member

@lsoft Yes, It might be the same issue. And yes, we're not sure how to handle this. Also, BInaryFormatter is going away, so this has to be changed anyway.
If you do have a viable repro solution, you could raise a new issue, referring to this, because this issue is now rather overloaded.

@tkolb-recom
Copy link

tkolb-recom commented Apr 25, 2024

We ran into this including the CI test suite being evaluated falsely positive. The circumstances are complicated and multi threading is involved. There was a trivial exception within a thread, the UnhandledExceptionHandler catching and KILLing the process after logging. That is totally unrelated to NUnit. But when running within the test agent that kills it.

I stripped it down and this test case in turn always produces the SocketException (Agent), NUnitEngineException ("Remote test agent believes agency process has exited") and ExitCode -100 (Console):

NUnitSocketException.zip

nunit3-console.exe --process=Multiple --agents=2 .\NUnitSocketException.dll

NUnit Console 3.17.0+685c5b542b5e9ba632c905f0bd514a773d9758af (Release)

@LukeS5310
Copy link

Got this very similar issue with our test suite recently (occures after all tests had run and report is about to be generated):

Unhandled Exception: --SocketException
An existing connection was forcibly closed by the remote host
   at NUnit.Engine.Communication.Transports.Tcp.TestAgentTcpProxy.SendCommandMessage(String command, Object[] arguments)
   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)

NUnit.Engine.NUnitEngineException: Remote test agent exited with non-zero exit code -532462766
   at NUnit.Engine.Services.TestAgency.OnAgentExit(Process process, Guid agentId)
   at NUnit.Engine.Services.TestAgency.<>c__DisplayClass13_0.<GetAgent>b__0(Object sender, EventArgs e)
   at System.Diagnostics.Process.OnExited()
   at System.Diagnostics.Process.RaiseOnExited()
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   at System.Threading._ThreadPoolWaitOrTimerCallback.PerformWaitOrTimerCallback(Object state, Boolean timedOut)

stumbled upon this issue: #3446
and followed advice of looking inside windows event viewer to find out that message exceeding maximum size (logs presumably):

Application: dotnet.exe
CoreCLR Version: 7.0.2024.26716
.NET Version: 7.0.20
Description: The process was terminated due to an unhandled exception.
Exception Info: System.Exception: Message is too big (148770846 bytes). Max allowed length is 134217728 bytes.
   at NUnit.Engine.Communication.Protocols.BinarySerializationProtocol.Encode(Object message) in d:\repos\NUnit\nunit-console\src\NUnitEngine\nunit.engine.core\Communication\Protocols\BinarySerializationProtocol.cs:line 40
   at NUnit.Engine.Communication.Transports.Tcp.TestAgentTcpTransport.SendResult(Object result) in d:\repos\NUnit\nunit-console\src\NUnitEngine\nunit.engine.core\Communication\Transports\Tcp\TestAgentTcpTransport.cs:line 126
   at NUnit.Engine.Communication.Transports.Tcp.TestAgentTcpTransport.CommandLoop() in d:\repos\NUnit\nunit-console\src\NUnitEngine\nunit.engine.core\Communication\Transports\Tcp\TestAgentTcpTransport.cs:line 106

Tweaking our logging output to be more compact did the trick. Hope this helps someone

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Investigate We are looking into the issue
Projects
None yet
Development

No branches or pull requests

9 participants