Nunit-console: Nunit.Console 3.8 - Socket Exception

[BlythMeister]

Since upgrading from 3.7 to 3.8 i more instances of a failed tests with "NUnit.Engine.NUnitEngineUnloadException"

[17:06:51][Test:Run] NUnit.Engine.NUnitEngineUnloadException : Multiple exceptions encountered. Retrieve AggregatedExceptions property for more information
[17:06:51][Test:Run] ----> System.Net.Sockets.SocketException : An existing connection was forcibly closed by the remote host
[17:06:51][Test:Run] Running build failed.
[17:06:51][Test:Run] Error:
[17:06:51][Test:Run] NUnit test failed. Process finished with exit code FatalError (-5).

Unfortunatly this error gives me no hint as to why the socket exception has occured, or where i can look to find out....

[ChrisMaddock]

Did you previously see SocketExceptions in NUnit Console 3.7?

This is what https://github.com/nunit/nunit-console/issues/255 will now look like - if the socket exception occured whilst the test run was being cleaned up. It could either be that the test agent crashed during this process - or it could be an instance of a potential race condition we haven't been able to pin down. Try running with --trace#Debug - see what the agent logs look like when you get this exception.

If you didn't see SocketExceptions with 3.7, this may be a new issue. 😞

[BlythMeister]

We did sometimes see socket exception
I can try running with trace to see what I get.

Would it be possible to output the library which the missing agent was testing?
We pass around 200 DLL to nunit console so trying to work out which one caused the issue is near impossible.
But some extra logging here to give hints would be really useful.

[ChrisMaddock]

Yes, so long as you’re running in separate processes, i think it would be? Definitely plans to do more to output better debug information here.

That would be a great pull request, if you’d be willing? It should be possible to catch the socketexception, and rethrow as an Nunitengine exception with the socket exception as the innerexception, and some more information in the exception message as to which app domain caused the issue.

[BlythMeister]

The problem is that there is no longer a stack track to find out where the exception is coming from...I'll have a look see if I can add anything else around this error handling in the console runner itself to help users when nunit exceptions occur.
Essentially giving more context to the error.

[ChrisMaddock]

Something like https://github.com/nunit/nunit-console/issues/335 may help diagnose as to whether there is an agent crash or not.

[BlythMeister]

@ChrisMaddock is there a way to set where the tracelogs get put?

[CharliePoole]

The logs are saved relative to the "work" directory if you set it using option --work.

Note that the "work" directory is the place where NUnit saves all logs and reports, it's not the Windows "working" directory. Bad naming on my part back when I'm afraid.

[BlythMeister]

I have been able to capture the agent/trace logs and the only error in here is

14:40:08.244 Info  [ 4] ProcessRunner: Running FifteenBelow.Barcode.Tests.dll
14:40:08.244 Info  [ 4] TestAgency: Getting standard agent for use under net-4.5
14:40:08.244 Debug [ 4] TestAgency: Using nunit-agent at F:\GIT\Source\packages\NUnit.ConsoleRunner\tools\nunit-agent.exe
14:40:08.249 Debug [ 4] TestAgency: Launched Agent process 17664 - see nunit-agent_17664.log
14:40:08.249 Debug [ 4] TestAgency: Command line: "F:\GIT\Source\packages\NUnit.ConsoleRunner\tools\nunit-agent.exe" 37fe0d48-f65c-4276-8db1-613ecdb4d673 tcp://127.0.0.1:59999/TestAgency --pid=1864 --trace:Verbose --work=F:\GIT\Source
14:40:08.249 Debug [ 4] TestAgency: Waiting for agent {37fe0d48-f65c-4276-8db1-613ecdb4d673} to register
14:40:08.649 Debug [ 4] TestAgency: Returning new agent {37fe0d48-f65c-4276-8db1-613ecdb4d673}
14:40:09.077 Info  [ 4] ProcessRunner: Done running FifteenBelow.Barcode.Tests.dll
14:40:09.077 Info  [ 4] ProcessRunner: Unloading FifteenBelow.Barcode.Tests.dll
14:40:09.084 Debug [ 4] ProcessRunner: Stopping remote agent
14:40:09.095 Error [ 4] ProcessRunner: Failed to stop the remote agent. An existing connection was forcibly closed by the remote host

in the agent logs it states this at the end

14:40:09.086 Info  [ 5] RemoteTestAgent: Stopping
14:40:09.087 Info  [11] RemoteTestAgent: Waiting for messages to complete
14:40:09.088 Info  [11] RemoteTestAgent: Attempting shut down channel
14:40:09.088 Info  [11] RemoteTestAgent: Set stop signal
14:40:09.088 Debug [ 1] NUnitTestAgent: Stop signal received
14:40:09.088 Info  [ 1] NUnitTestAgent: Agent process 17664 exiting cleanly

Nunit.zip
So this leaves me none the wiser as to why the socket error is occurring.

I have also setup a rig which runs our full test suite until it errors and have captured this more than once but everytime for different .dll (so i'm dubious to think it's something in the test code itself)

[BlythMeister]

I've done some digging on this and I can't work out the link between the process runner and the agent itself.
I can see the code in the agent which matches the logging and showing the agent stopping.
And I can see the error handling in the process runner.
I wonder if the dispose in process runner when it calls stop should catch a socket exception and treat that as a happy path.
The aim of the function is to stop the agent, if the agent has gone from the other end of the pipe then the net result is the agent has been stopped?
Granted, the shutdown might not be as graceful as we would like, but the net result is the same.

Would you accept a PR to that affect?

[CharliePoole]

I don't know what the current team will accept, however, I can give a bit of background.

NUnit originally simply ignored any failure to unload a Process it an AppDomain by swallowing the exception. At some point, somebody wanted this reported, so we started down the path that took us to the point where we are today. We are piling fix upon fix to deal with what's essentially a non-issue for us.

IMO we should record information directly at the time a problem occurs but should not attempt to handle it through an exception in the runner.

[BlythMeister]

I can see what you mean.

My ci build failing when actually the only thing wrong is that for some reason nunit agent didn't stop as expected is kind of annoying.
If the tests all pass, I'm happy 🙂

[ChrisMaddock]

This isn’t related to app domain unload, is it? That would be a different stack trace/log if it was?

I believe this is a race condition in the agent shut down that we are aware of - @jnm2 did some digging, but it was difficult to pin down. Given we wanted to change the communication protocol anyway, the most prodictive solution seemed to be to invest time there instead.

In the meantime, I think something to catch this exception and discard is probably a worthwhile sticking plaster - fixing the actual cause is a big piece of work which has been hanging on for a while.

@BlythMeister - my only concern with your idea is that the agent could genuinely crash during shut down, and your suggestion would hide that. How about something that catches the socketexception - then checks the exit code of the agent process (which I believe is stored somewhere), and swallows the exception only If the agent exited with a 0? I believe that would be possible - I’m not looking at the code right now.

I’d like to hear @jnm2’s thoughts before moving on here. 😊

[CharliePoole]

@ChrisMaddock Catching the exception and not rethrowing in the agent doesn't necessarily mean hiding it. The agent can report the information in some way. I think it's trying to deduce the cause of the problem in the primary process that's causing us so much effort.

The return code of the agent process is already available to us. I like your idea of checking it but I wouldn't necessarily throw another exception. Instead, I might just report it as a warning on the assembly level test suite for the particular assembly.

[jnm2]

Sticking plaster sounds good. The five second pause before shutdown was the plaster I thought we would ship, but anything really is fine. Too bad there's only so many of us!

[ChrisMaddock]

Did you intend to close this Charlie?

[ChrisMaddock]

And yes - warnings would be nice - but would be a bigger piece or work, I believe?

[BlythMeister]

i've pushed a set of sticky plaster fixes in #372 as well as including a stack trace to the error logs.

I've actually implemented both sticky plaster ideas.
@ChrisMaddock we check the process exit code and only throw error if it's not 0.
@jnm2 i've added a 2 second sleep before the agent itself will exit.

[ChrisMaddock]

Fixed in https://github.com/nunit/nunit-console/pull/372

[aolszowka]

We're running on Master as well (due to #290) and can confirm that this fix works for us.