nunit / nunit-console

NUnit Console runner and test engine
MIT License
215 stars 152 forks source link

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

Open Lorilatschki opened 1 year ago

Lorilatschki commented 1 year ago

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 commented 1 year ago

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

This may be related to #1275.

Lorilatschki commented 1 year ago

@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 commented 1 year ago

@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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

Lorilatschki commented 1 year ago

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

CharliePoole commented 1 year ago

@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 commented 1 year ago
  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 commented 1 year ago

@saiparth do you get this error sporadically or constantly?

saiparth commented 1 year ago

@Lorilatschki sporadically.

Lorilatschki commented 1 year ago

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

saiparth commented 1 year ago

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

OsirisTerje commented 1 year ago

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

saiparth commented 1 year ago

Hi @OsirisTerje Any update on this issue?

OsirisTerje commented 1 year ago

@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 commented 1 year ago

@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 commented 1 year ago

@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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

@Lorilatschki

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

@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 commented 1 year ago

@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 commented 1 year ago

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 commented 1 year ago

@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 commented 1 year ago

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 commented 1 year ago

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!

OsirisTerje commented 1 year ago

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.

OsirisTerje commented 1 year ago

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

JensLeible commented 1 year ago

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.

OsirisTerje commented 1 year ago

What happens using 3.16.2 on your side?

JensLeible commented 1 year ago

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 commented 1 year ago

Running against the test project on my machine with the current main branch (nunit4-console) of the nunit-console repo results in the following console output:

NUnit Console 3.99.0.0-VSIDE (Debug)
Copyright (c) 2022 Charlie Poole, Rob Prouse
Monday, May 8, 2023 1:55:11 PM

Runtime Environment
    OS Version: Microsoft Windows NT 10.0.17763.0
    Runtime: .NET Framework CLR v4.0.30319.42000

Test Files
    .\NUnitTestDummy.dll

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

Unhandled Exception: --SocketException
An existing connection was forcibly closed by the remote host
   at System.Net.Sockets.Socket.Send(Byte[] buffer)
   at NUnit.Engine.Communication.Transports.Tcp.TestAgentTcpProxy.SendCommandMessage(String command, Object[] arguments) in ~\nunit-console\src\NUnitEngine\nunit.engine\Communication\Transports\Tcp\TestAgentTcpProxy.cs:line 101
   at NUnit.Engine.Communication.Transports.Tcp.TestAgentTcpProxy.Stop() in ~\nunit-console\src\NUnitEngine\nunit.engine\Communication\Transports\Tcp\TestAgentTcpProxy.cs:line 43
   at NUnit.Engine.Communication.Transports.Remoting.TestAgentRemotingProxy.Stop() in ~\nunit-console\src\NUnitEngine\nunit.engine\Communication\Transports\Remoting\TestAgentRemotingProxy.cs:line 38
   at NUnit.Engine.Runners.ProcessRunner.Dispose(Boolean disposing) in ~\nunit-console\src\NUnitEngine\nunit.engine\Runners\ProcessRunner.cs:line 226
   at NUnit.Engine.Runners.TestEngineRunner.Dispose() in ~\nunit-console\src\NUnitEngine\nunit.engine\Runners\TestEngineRunner.cs:line 183
   at NUnit.Engine.Runners.MasterTestRunner.Dispose(Boolean disposing) in ~\nunit-console\src\NUnitEngine\nunit.engine\Runners\MasterTestRunner.cs:line 234
   at NUnit.Engine.Runners.MasterTestRunner.Dispose() in ~\nunit-console\src\NUnitEngine\nunit.engine\Runners\MasterTestRunner.cs:line 222
   at NUnit.ConsoleRunner.ConsoleRunner.RunTests(TestPackage package, TestFilter filter) in ~\nunit-console\src\NUnitConsole\nunit4-console\ConsoleRunner.cs:line 203
   at NUnit.ConsoleRunner.ConsoleRunner.Execute() in ~\nunit-console\src\NUnitConsole\nunit4-console\ConsoleRunner.cs:line 104
   at NUnit.ConsoleRunner.Program.Main(String[] args) in ~\nunit-console\src\NUnitConsole\nunit4-console\Program.cs:line 131

NUnit.Engine.NUnitEngineException: Remote test agent exited with non-zero exit code -532462766
   at NUnit.Engine.Services.TestAgency.OnAgentExit(Process process, Guid agentId) in ~\nunit-console\src\NUnitEngine\nunit.engine\Services\TestAgency.cs:line 159
   at NUnit.Engine.Services.TestAgency.<>c__DisplayClass14_0.<GetAgent>b__0(Object sender, EventArgs e) in ~\nunit-console\src\NUnitEngine\nunit.engine\Services\TestAgency.cs:line 74
   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)
OsirisTerje commented 1 year ago

nunit4-console is not ready, but it obviously has an error.

JensLeible commented 1 year ago

What would be the correct branch to test with?

OsirisTerje commented 1 year ago

version3

JensLeible commented 1 year ago

I just tested with said branch (version3).

Here's the console output with the nunit3-console:

NUnit Console 3.99.0.0-VSIDE (Debug)
Copyright (c) 2022 Charlie Poole, Rob Prouse
Tuesday, May 9, 2023 11:30:55 AM

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

Test Files
    .\NUnitTestDummy.dll

Unhandled Exception: NUnit.Engine.NUnitEngineException: Remote test agent exited with non-zero exit code -532462766
   at NUnit.Engine.Services.TestAgency.OnAgentExit(Process process, Guid agentId) in ~\nunit-console\src\NUnitEngine\nunit.engine\Services\TestAgency.cs:line 158
   at NUnit.Engine.Services.TestAgency.<>c__DisplayClass13_0.<GetAgent>b__0(Object sender, EventArgs e) in ~\nunit-console\src\NUnitEngine\nunit.engine\Services\TestAgency.cs:line 73
   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)

Errors, Failures and Warnings

1) Error : ~\NUnitTestDummy\bin\Debug\net7.0\NUnitTestDummy.dll
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
   at System.Net.Sockets.Socket.Receive(Byte[] buffer)
   at NUnit.Engine.Communication.Transports.Tcp.SocketReader.GetNextMessage() in ~\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 ~\nunit-console\src\NUnitEngine\nunit.engine\Communication\Transports\Tcp\TestAgentTcpProxy.cs:line 116
   at NUnit.Engine.Communication.Transports.Tcp.TestAgentTcpProxy.Run(ITestEventListener listener, TestFilter filter) in ~\nunit-console\src\NUnitEngine\nunit.engine\Communication\Transports\Tcp\TestAgentTcpProxy.cs:line 73
   at NUnit.Engine.Runners.ProcessRunner.RunTests(ITestEventListener listener, TestFilter filter) in ~\nunit-console\src\NUnitEngine\nunit.engine\Runners\ProcessRunner.cs:line 138

Test Run Summary
  Overall result: Failed
  Test Count: 0, Passed: 0, Failed: 0, Warnings: 0, Inconclusive: 0, Skipped: 0
  Start time: 2023-05-09 09:30:55Z
    End time: 2023-05-09 09:30:56Z
    Duration: 0.384 seconds

Results (nunit3) saved as .\TestOutput\results_N3.xml

NUnit.Engine.NUnitEngineUnloadException : Multiple exceptions encountered. Retrieve AggregatedExceptions property for more information
  ----> NUnit.Engine.NUnitEngineUnloadException : Agent Process was terminated successfully after error.
  ----> System.Net.Sockets.SocketException : An existing connection was forcibly closed by the remote host

With the nunit3-netcore-console.exe however, the error does not occur:

NUnit Console 3.99.0.0-VSIDE (Debug)
Copyright (c) 2022 Charlie Poole, Rob Prouse
Tuesday, May 9, 2023 11:38:28 AM

Runtime Environment
   OS Version: Microsoft Windows 10.0.17763
  Runtime: .NET 6.0.16

Test Files
    .\NUnitTestDummy.dll

Run Settings
    DisposeRunners: True
    SkipNonTestAssemblies: True
    WorkDirectory: ~\NUnitTestDummy\bin\Debug\net7.0
    NumberOfTestWorkers: 12

Test Run Summary
  Overall result: Passed
  Test Count: 1, Passed: 1, Failed: 0, Warnings: 0, Inconclusive: 0, Skipped: 0
  Start time: 2023-05-09 09:38:29Z
    End time: 2023-05-09 09:38:29Z
    Duration: 0.190 seconds

Results (nunit3) saved as .\TestOutput\results_N3.xml
JensLeible commented 1 year ago

Can I provide more information to help?

OsirisTerje commented 1 year ago

It is hard to see what we can do here with no repro that reproduces the problem. You also found it worked on some machines, and not on yours and the build server. I believe you are the closest person to find the cause here. The error code can indicate issues with security, with paths, nearly anything. This might not be related to NUnit at all, but be more that NUnit is killed due to this.
Since you can reproduce it locally, you can also alter the code around where it crashes, and dump more information out there, that is one possibility.
Since it is the Unloading that fails, you could also catch the exception there, and just continue. If that works, you could even raise a PR for that.

JensLeible commented 1 year ago

I have a quick side question: Are you aware of the fact that the NUnit.ConsoleRunner.NetCore nuget package on nuget.org holds a nunit3-netcore-console.dll instead of an executable? Since this could be a potential track to circumvent the current issue, I thought I'd ask that here. Follow up question would be: If you are aware, how should this package be used? I could not find any documentation about that. The executable seems missing starting with Version 3.16.1. Versions 3.16.0 and 3.15.2 do contain an executable.

image

Scordo commented 1 year ago

Hello,

we are running in this issue, too. This happens now with new build servers having more cores. The new build-servers are clones of the old ones. So they are exactly the same like the old machines. The only difference is that they have more cores. The previous build machines had 8 cores, the new ones have 46 cores.

Seems to be a parallelism issue?! It does not always happen on the new machines. But it starts happening there.

JensLeible commented 1 year ago

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.

OsirisTerje commented 1 year ago

Thanks @JensLeible !! @Scordo @Lorilatschki Can you also check the SDK as @JensLeible points out.

Lorilatschki commented 1 year ago

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 commented 1 year ago

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

Lorilatschki commented 1 year ago

@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 commented 1 year ago

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

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

OsirisTerje commented 1 year ago

@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 commented 1 year ago

@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 commented 1 year ago

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 ?