.NET/.NetCore - Profiler's SocketException when running tests via VSTest.Console
- Marc Amouyal
Problem
In certain cases, we can see an exception at the end of the test execution that may cause coverage loss for the last chunk of metadata cached by the agent and that may not be sent before the exception occurs
17:03:55.632 ERROR [Endpoint for 0xfa79db0f00002724] Got exception on receive: An existing connection was forcibly closed by the remote host.
17:03:55.633 DEBUG [Endpoint for 0xfa79db0f00002724] System.Net.Sockets.SocketException (10054): An existing connection was forcibly closed by the remote host.
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource<System.Int32>.GetResult(Int16 token)
at System.Threading.Tasks.ValueTask`1.ValueTaskSourceAsTask.<>c.<.cctor>b__4_0(Object state)
--- End of stack trace from previous location ---
at System.Threading.Tasks.TaskToApm.End[TResult](IAsyncResult asyncResult)
at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location ---
at SL.DotNet.IpcLibraryCrossPlatform.IpcTcpSocket.ReceiveInternalAsync(Int32 size, Action resetTimeoutTimer)
at SL.DotNet.IpcLibraryCrossPlatform.IpcTcpSocket.ReceiveAsync(Int32 size, Int32 timeoutMs)
at SL.DotNet.IpcLibraryCrossPlatform.IpcTcpEndpoint.ProcessConnectionRequests()
17:03:55.636 INFO [CoverageCollector / Active session 72ead1dd-d713-4f7c-86ad-87d6ad89f8ec / Profiler ID 0xFA79DB0F00002724] Profiler 'ended' event received
17:03:55.652 INFO [CoverageCollector / Active session 72ead1dd-d713-4f7c-86ad-87d6ad89f8ec] Profiler ID 0xFA79DB0F00002724 closed. Reason=UnexpectedThis Exception usually happens when running your tests with an old version of the command-line tool VSTest.Console.exe wrapped with the Sealights .Net Agent run command.
$vstest = "C:\Program Files (x86)\Microsoft Visual Studio\2019\Professional\Common7\IDE\CommonExtensions\Microsoft\TestWindow\vstest.console.exe"
$testsToRun = Get-Item -Path "${BuildRoot}\AcmeCoreService\UnitTests\UnitTestsCompiled\*Test*.dll" | ForEach-Object { $_.FullName } | Where-Object { $_ -notlike '*Microsoft.VisualStudio.QualityTools.UnitTestFramework.dll' }
. sl/sldotnet/sl.dotnet.exe run --buildSessionIdFile sl/sldotnet/buildsessionid.txt --testStage "$SealightsStageName" `
--target $vstest --targetArgs "$testsToRun /Diag:`"${buildroot}\out\logs\sealights\utests\vstest_log_sl.txt`" /platform:x64 /resultsdirectory:`"${buildroot}\out\testresults1`" /logger:trx" Cause
The test host process that executes tests is terminated by the test console immediately after the last test.
The error we see in the logs of the test console could happen even without sealights profilers attached, but because our agent wraps the test host process, it makes it a bit slower than usual and the exception is more likely to happen.
Solution
Microsoft’s VSTest.Console starting from version 17.2 (see PR #3466) supports the environment variable VSTEST_TESTHOST_SHUTDOWN_TIMEOUT that allows to override shutdown timeout to increase it and avoid abrupt disconnection
$Env:VSTEST_TESTHOST_SHUTDOWN_TIMEOUT = 2000An additional enhancement would be to decrease the interval for sending data from the Sealights profiler to the Sealights collector via the environment variable $Env:SL_Profiler_CoverageSamplingTimeoutSec (Default is 5, Recommended is 2).