3.15.0 - sporadic SocketException during shutdown of test agents

[mac-hi]

Hi,

in our nightly test build we are using NUnit to execute a high number of tests by running multiple instances of nunit3-console in parallel.
Every couple of days we observe that a few number of console runners return with exit code -100.
The output shows:

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)

When using command line option '--inprocess' the exception does not occur.

To track the problem down I've enabled debug tracing. As the original log files contain company internal information I stripped the unimportant top of the log files.

InternalTrace.9600.log

[...]
23:25:30.099 Info  [ 1] ProcessRunner: Running 
23:25:30.108 Debug [ 1] AgentProcess: TargetRuntime = net-4.8
23:25:30.110 Debug [ 1] AgentProcess: GetTestAgentExePath(net-4.8, False)
23:25:30.111 Debug [ 1] AgentProcess: Checking for agents at C:\src\packages\NUnit.ConsoleRunner.3.15.0\tools\agents
23:25:30.111 Debug [ 1] AgentProcess: Using nunit-agent at C:\src\packages\NUnit.ConsoleRunner.3.15.0\tools\agents\net40\nunit-agent.exe
23:25:30.370 Debug [ 1] TestAgency: Launched Agent process 20244 - see nunit-agent_20244.log
23:25:30.370 Debug [ 1] TestAgency: Command line: "C:\src\packages\NUnit.ConsoleRunner.3.15.0\tools\agents\net40\nunit-agent.exe" 3bc1eb2c-eeb7-49a3-b375-6bde0cf32322 tcp://127.0.0.1:54725/TestAgency-6717ea8b-64ed-4aa7-bc84-6276d98f5afe --pid=9600 --trace=Verbose --work=C:\bin\logs
23:25:30.374 Debug [ 1] TestAgency: Waiting for agent {3bc1eb2c-eeb7-49a3-b375-6bde0cf32322} to register
23:25:30.776 Debug [ 1] TestAgency: Returning new agent {3bc1eb2c-eeb7-49a3-b375-6bde0cf32322}
00:06:16.850 Info  [ 1] ProcessRunner: Done running 
00:06:16.866 Info  [ 1] ProcessRunner: Unloading 
00:06:17.147 Debug [ 1] ProcessRunner: Stopping remote agent
00:06:17.428 Info  [ 1] ServiceManager: Stopping DefaultTestRunnerFactory
00:06:17.428 Info  [ 1] ServiceManager: Stopping ResultService
00:06:17.428 Info  [ 1] ServiceManager: Stopping DriverService
00:06:17.428 Info  [ 1] ServiceManager: Stopping TestAgency
00:06:17.428 Info  [ 1] ServiceManager: Stopping RuntimeFrameworkService
00:06:17.428 Info  [ 1] ServiceManager: Stopping ProjectService
00:06:17.428 Info  [ 1] ServiceManager: Stopping ExtensionService
00:06:17.428 Info  [ 1] ServiceManager: Stopping TestFilterService
00:06:17.428 Info  [ 1] ServiceManager: Stopping RecentFilesService
00:06:17.428 Info  [ 1] ServiceManager: Stopping SettingsService

nunit-agent_20244.log

[...]
23:25:30.667 Info  [ 1] NUnitTestAgent: Starting RemoteTestAgent
23:25:30.671 Info  [ 1] TestAgentRemotingTransport: Agent starting
23:25:30.691 Info  [ 1] TestAgentRemotingTransport: Connecting to TestAgency at tcp://127.0.0.1:54725/TestAgency-6717ea8b-64ed-4aa7-bc84-6276d98f5afe
23:25:30.751 Debug [ 1] TestAgentRemotingTransport: Registered agent with TestAgency
23:25:30.752 Debug [ 1] NUnitTestAgent: Waiting for stopSignal
23:25:30.782 Error [ 6] ServiceManager: Requested service NUnit.Engine.ITestRunnerFactory was not found
23:25:30.931 Info  [ 6] DomainManager: Creating application domain domain-
23:25:30.935 Debug [ 6] ServiceManager: Request for service IDriverService satisfied by DriverService
23:25:30.941 Debug [ 6] DriverService: Trying DriverFactory
23:25:31.067 Info  [ 6] NUnitFrameworkDriver: Loading xyz.dll - see separate log file
23:25:31.428 Info  [ 6] NUnitFrameworkDriver: Loaded xyz.dll
23:25:31.429 Info  [ 6] NUnitFrameworkDriver: Running xyz.dll - see separate log file
00:06:17.163 Info  [ 6] TestAgentRemotingTransport: Stopping
00:06:17.163 Info  [58] TestAgentRemotingTransport: Waiting for messages to complete
00:06:17.163 Info  [58] TestAgentRemotingTransport: Attempting shut down channel
00:06:17.163 Info  [58] TestAgentRemotingTransport: Set stop signal
00:06:17.163 Debug [ 1] NUnitTestAgent: Stop signal received
00:06:17.163 Info  [ 1] NUnitTestAgent: Agent process 20244 exiting cleanly

InternalTrace.20244.xyz.dll.log

InternalTrace: Initializing at level Debug
23:25:31.136 Debug [ 6] DefaultTestAssemblyBuilder: Loading xyz.dll in AppDomain domain-
23:25:31.154 Debug [ 6] DefaultTestAssemblyBuilder: Examining assembly for test fixtures
23:25:31.246 Debug [ 6] DefaultTestAssemblyBuilder: Found 98 classes to examine
23:25:31.393 Debug [ 6] DefaultTestAssemblyBuilder: Found 39 fixtures with 620 test cases
23:25:31.532 Info  [ 6] DefaultTestAssemblyRunner: Running tests
23:25:31.620 Debug [ 9] EventPump: Starting EventPump
00:06:16.834 Debug [ 9] EventPump: EventPump Terminating

According to the logs the TestAgent exits cleanly so the issue seems to be located somewhere in the communication/synchronization of the ProcessRunner and the TestAgent.
Unfortunately I do not have any experience with .NET Remoting so I'm not able to analyze/debug this further.
For me it looks like a race condition between the program flow returning from method ITestAgent.Stop() in ProcessRunner.Dispose() and the code in TestAgentRemotingTransport.Stop() that is executed in a background thread.

Kind regards,
Achim