Rider and VS test runner - value cannot be null task in TestOutputMessage..ctor

tpeplow commented 3 years ago

I took the latest since this fix (https://github.com/machine/machine.specifications/issues/432) and I get the this error in both VS and Rider:

2021.05.03 13:34:15.127   ERROR TestRunner: TestExecutionSink System.ArgumentNullException: Value cannot be null. Parameter name: task at JetBrains.ReSharper.TestRunner.Abstractions.Objects.TestOutputMessage..ctor(RemoteTask task, String text, TestOutputType outputType) in C:\BuildAgent\work\1b668fe37ef92293\ReSharperTestRunner\src\TestRunner.Abstractions\Objects\Server\TestOutputMessage.cs:line 16 at JetBrains.ReSharper.TestRunner.Implementation.TestExecutionSink.TestOutput(RemoteTask task, String text, TestOutputType outputType) in C:\BuildAgent\work\1b668fe37ef92293\ReSharperTestRunner\src\TestRunner.Merged\Implementation\UnitTestRemoteAgent.cs:line 261

--- EXCEPTION #1/1 [LoggerException]
Message = “
  TestRunner: TestExecutionSink  System.ArgumentNullException: Value cannot be null.
  Parameter name: task
     at JetBrains.ReSharper.TestRunner.Abstractions.Objects.TestOutputMessage..ctor(RemoteTask task, String text, TestOutputType outputType) in C:\BuildAgent\work\1b668fe37ef92293\ReSharperTestRunner\src\TestRunner.Abstractions\Objects\Server\TestOutputMessage.cs:line 16
     at JetBrains.ReSharper.TestRunner.Implementation.TestExecutionSink.TestOutput(RemoteTask task, String text, TestOutputType outputType) in C:\BuildAgent\work\1b668fe37ef92293\ReSharperTestRunner\src\TestRunner.Merged\Implementation\UnitTestRemoteAgent.cs:line 261
”
ExceptionPath = Root
ClassName = JetBrains.Util.LoggerException
HResult = COR_E_APPLICATION=80131600
StackTraceString = “
  at JetBrains.Util.ILoggerEx.LogMessage(ILogger this, LoggingLevel level, String message)
     at JetBrains.ReSharper.UnitTestFramework.TestRunner.Handlers.TestRunnerAgentLoggingHandler.Execute(LogMessage message)
     at lambda_method(Closure , IAutoRegisterInProtocol )
     at JetBrains.ReSharper.UnitTestFramework.TestRunner.ServerEndpoint.<>c__DisplayClass9_2.<TryRegisterHandler>b__3()
     at System.Threading.Tasks.Task`1.InnerInvoke()
     at System.Threading.Tasks.Task.Execute()
     at System.Threading.Tasks.Task.ExecutionContextCallback(Object obj)
     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.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
     at System.Threading.Tasks.Task.ExecuteEntry(Boolean bPreventDoubleExecution)
     at System.Threading.Tasks.Task.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
     at System.Threading.ThreadPoolWorkQueue.Dispatch()
     at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()
”

tpeplow commented 3 years ago

This log may help, I replaced some identifiable information with ***

13:55:58.282 |T| Launch: 9812da54-105d-4347-89a4-95fe28e999ac >> RunHostController.AfterLaunchStarted
13:55:58.285 |T| Launch: 9812da54-105d-4347-89a4-95fe28e999ac << RunHostController.AfterLaunchStarted
13:55:58.295 |I| BuildStage started
13:55:58.313 |I| Build policy: Automatic
13:56:34.228 |I| 2 projects built
13:56:34.228 |V|     ***
    ***
13:56:34.230 |I| BuildStage completed
13:56:34.230 |I| RefreshProjectPropertiesStage started
13:56:34.233 |I| RefreshProjectPropertiesStage completed
13:56:34.234 |I| DiscoveryStage started
13:56:34.241 |I| Test exploration required for 1 projects
13:56:34.241 |V|     ***
13:56:39.794 |I| DiscoveryStage completed
13:56:39.794 |I| BuildPipelineStage started
13:56:39.795 |I| BuildPipelineStage completed
13:56:39.795 |I| ApplyRulesStage started
13:56:39.809 |V| Running elements from criterion: {TestAncestorCriterion: Machine.Specifications::357EE7BA-2716-4A16-AEB2-1959B3E7575B::.NETFramework,Version=v4.7.2::***}
13:56:39.809 |I| Got 2 elements (1 explicit) to run
13:56:39.812 |V| Marking 2 elements as Pending
13:56:39.848 |V| Marking elements as Pending completed
13:56:39.850 |V| Distributing 2 elements into runs
13:56:39.898 |V| Distributing elements completed
13:56:39.899 |I| Created 1 unit-test runs
13:56:39.900 |I| ApplyRulesStage completed
13:56:39.900 |I| RunTestsStage started
13:56:39.915 |I| Running up to 1 unit-test runs in parallel
13:56:39.923 |I| Run: 805a26a2-ba84-4943-a5ae-18e30e2719b7 - Starting
13:56:39.924 |V|     Provider: Machine.Specifications
    Target Framework: .NETFramework,Version=v4.7.2
    Strategy: MspecTestRunnerRunStrategy
    Runtime Environment: TestRunnerRuntimeEnvironment
  Host: JetBrains.ReSharper.UnitTestFramework.TestRunner.DefaultTestRunnerHost
  Project: ***
  TargetPlatform: X64
  TargetFrameworkId: .NETFramework,Version=v4.7.2
  RunAsTargetFrameworkId: .NETFramework,Version=v4.7.2
  IsUnmanaged: False
13:56:39.943 |T| Run: 805a26a2-ba84-4943-a5ae-18e30e2719b7 >> RunHostController.PrepareForRun
13:56:39.944 |T| Run: 805a26a2-ba84-4943-a5ae-18e30e2719b7 << RunHostController.PrepareForRun
13:56:40.090 |V| RunSettings: 
**
13:56:40.118 |V| [ProcessStartInfoPatchResult]
  Original request: FrameworkRequest (UseInternal: False, UseMono: False, MonoDebugMode: True, MonoPlatform: PreferX64)
  Success: True
  ErrorMessage: <Empty>
  Original StartInfo: FileName = 'C:\Program Files\JetBrains\JetBrains Rider 2020.1.4\lib\ReSharperHost\TestRunner\net461\ReSharperTestRunner64.exe', Arguments = '-f .NETFramework,Version=v4.7.2 -p 50726 -r be30ea06-225c-4c35-b337-ed0a3eeb8e4e --parentProcessId 9764', WorkDir = '***.Tests\bin\x64\Debug\net472'
  Patched  StartInfo: FileName = 'C:\Program Files\JetBrains\JetBrains Rider 2020.1.4\lib\ReSharperHost\TestRunner\net461\ReSharperTestRunner64.exe', Arguments = '-f .NETFramework,Version=v4.7.2 -p 50726 -r be30ea06-225c-4c35-b337-ed0a3eeb8e4e --parentProcessId 9764', WorkDir = '***.Tests\bin\x64\Debug\net472'

13:56:40.122 |I| Starting process: C:\Program Files\JetBrains\JetBrains Rider 2020.1.4\lib\ReSharperHost\TestRunner\net461\ReSharperTestRunner64.exe -f .NETFramework,Version=v4.7.2 -p 50726 -r be30ea06-225c-4c35-b337-ed0a3eeb8e4e --parentProcessId 9764
13:56:40.126 |I| Started process with pid 35016
13:56:41.266 |V| Registering message handlers from 'JetBrains.ReSharper.UnitTestFramework.TestRunner.DefaultTestRunnerHost'...
13:56:41.276 |V| Registering message handlers from 'JetBrains.ReSharper.UnitTesting.MSTest.Provider.DotNetCore.Proprietary.MsTestTestRunnerOrchestrator'...
13:56:41.276 |V| Registering message handlers from 'JetBrains.ReSharper.UnitTestProvider.nUnit.v30.NUnitTestRunnerOrchestrator'...
13:56:41.277 |V| Registering message handlers from 'JetBrains.ReSharper.UnitTestProvider.nUnit.v26.NUnitTestRunnerOrchestrator'...
13:56:41.278 |V| Registering message handlers from 'JetBrains.ReSharper.UnitTesting.VsTest.Provider.VsTestTestRunnerOrchestrator'...
13:56:41.279 |V| Registering message handlers from 'JetBrains.ReSharper.UnitTestProvider.Xunit.DotNetCore.Proprietary.XUnitTestRunnerOrchestrator'...
13:56:41.280 |V| Registering message handlers from 'Machine.Specifications.Runner.ReSharper.MspecTestRunnerOrchestrator'...
13:56:41.368 |V| TestRunner: TestAdapterLoadContextFactoryFactory Registered protocol entities: 9 scalars and 0 serializers 
13:56:41.414 |V| TestRunner: DefaultTestAdapterLoadContextFactory Initializing test adapter load context: NoIsolation = False 
13:56:41.414 |I| TestRunner: ShadowCopyBehavior+NoShadowCopyBehavior Shadow-copy will be skipped as it is disabled 
13:56:41.491 |V| TestRunner: AssemblyLoader(Tests) AssemblyLoader installed into Tests 
13:56:41.491 |V| TestRunner: AssemblyLoader(Tests) Added probing path 'C:\Program Files\JetBrains\JetBrains Rider 2020.1.4\lib\ReSharperHost\TestRunner\net461' 
13:56:41.491 |V| TestRunner: AssemblyLoader(Tests) Tests: Assembly 'JetBrains.ReSharper.TestRunner.Abstractions, Version=1.3.1.0, Culture=neutral, PublicKeyToken=5c492ec4f3eccde3' resolved from 'C:\Program Files\JetBrains\JetBrains Rider 2020.1.4\lib\ReSharperHost\TestRunner\net461\JetBrains.ReSharper.TestRunner.Abstractions.dll' 
13:56:41.491 |V| TestRunner: TestAdapterLoadContext Using application configuration: ***.Tests\bin\x64\Debug\net472\**.Tests.dll.config 
13:56:41.492 |V| TestRunner: LoadContextTracker Load context Tests is non-collectible and will not be tracked 
13:56:41.506 |V| TestRunner: AssemblyLoader(Tests) Added probing path '**.Tests\bin\x64\Debug\net472' 
13:56:41.506 |V| TestRunner: AssemblyLoader(Tests) Added probing path 'C:\Users\tpeplow\AppData\Local\JetBrains\Rider2021.1\resharper-host\local\Shared\vAny\DeployedPackagesExpand\Machine.Specifications.Runner.Resharper9.2021.1.1~86516B4017' 
13:56:41.506 |V| TestRunner: AssemblyLoader(Application) Added probing path 'C:\Users\tpeplow\AppData\Local\JetBrains\Rider2021.1\resharper-host\local\Shared\vAny\DeployedPackagesExpand\Machine.Specifications.Runner.Resharper9.2021.1.1~86516B4017' 
13:56:41.555 |V| TestRunner: AssemblyLoader(Tests) Tests: Assembly 'JetBrains.ReSharper.TestRunner.Core, Version=1.3.1.55, Culture=neutral, PublicKeyToken=5c492ec4f3eccde3' resolved from 'C:\Program Files\JetBrains\JetBrains Rider 2020.1.4\lib\ReSharperHost\TestRunner\net461\JetBrains.ReSharper.TestRunner.Core.dll' 
13:56:41.555 |V| TestRunner: TestAdapterLoadContextWrapper Initialized test executor: Machine.Specifications.Runner.ReSharper.Adapters.MspecRunner, Machine.Specifications.Runner.ReSharper.Adapters.net40, Version=2021.1.1.0, Culture=neutral, PublicKeyToken=null 
13:56:41.567 |V| TestRunner: AssemblyLoader(Tests) Tests: Assembly 'Machine.Specifications.Runner.ReSharper.Tasks.net40, Version=2021.1.1.0, Culture=neutral, PublicKeyToken=null' resolved from 'C:\Users\tpeplow\AppData\Local\JetBrains\Rider2021.1\resharper-host\local\Shared\vAny\DeployedPackagesExpand\Machine.Specifications.Runner.Resharper9.2021.1.1~86516B4017\Machine.Specifications.Runner.ReSharper.Tasks.net40.dll' 
13:56:41.567 |I| TestRunner: MspecRunner Execution started 
13:56:41.568 |V| TestRunner: MspecRunner Sending discovery results to server... 
13:56:41.594 |V| Run: 805a26a2-ba84-4943-a5ae-18e30e2719b7 - Discovery result processing started
13:56:41.640 |V| Run: 805a26a2-ba84-4943-a5ae-18e30e2719b7 - Discovery result processing finished (+0 -0 ~0)
13:56:53.390 |I| TestRunner: MspecRunner Execution completed 
13:56:53.404 |V| TestRunner: AssemblyLoader(Tests) Removed probing path 'C:\Users\tpeplow\AppData\Local\JetBrains\Rider2021.1\resharper-host\local\Shared\vAny\DeployedPackagesExpand\Machine.Specifications.Runner.Resharper9.2021.1.1~86516B4017' 
13:56:53.404 |V| TestRunner: AssemblyLoader(Tests) Removed probing path '***.Tests\bin\x64\Debug\net472' 
13:56:53.453 |E| TestRunner: TestExecutionSink System.ArgumentNullException: Value cannot be null. Parameter name: task at JetBrains.ReSharper.TestRunner.Abstractions.Objects.TestOutputMessage..ctor(RemoteTask task, String text, TestOutputType outputType) in C:\BuildAgent\work\1b668fe37ef92293\ReSharperTestRunner\src\TestRunner.Abstractions\Objects\Server\TestOutputMessage.cs:line 16 at JetBrains.ReSharper.TestRunner.Implementation.TestExecutionSink.TestOutput(RemoteTask task, String text, TestOutputType outputType) in C:\BuildAgent\work\1b668fe37ef92293\ReSharperTestRunner\src\TestRunner.Merged\Implementation\UnitTestRemoteAgent.cs:line 261

--- EXCEPTION #1/1 [LoggerException]
Message = “
  TestRunner: TestExecutionSink  System.ArgumentNullException: Value cannot be null.
  Parameter name: task
     at JetBrains.ReSharper.TestRunner.Abstractions.Objects.TestOutputMessage..ctor(RemoteTask task, String text, TestOutputType outputType) in C:\BuildAgent\work\1b668fe37ef92293\ReSharperTestRunner\src\TestRunner.Abstractions\Objects\Server\TestOutputMessage.cs:line 16
     at JetBrains.ReSharper.TestRunner.Implementation.TestExecutionSink.TestOutput(RemoteTask task, String text, TestOutputType outputType) in C:\BuildAgent\work\1b668fe37ef92293\ReSharperTestRunner\src\TestRunner.Merged\Implementation\UnitTestRemoteAgent.cs:line 261
”
ExceptionPath = Root
ClassName = JetBrains.Util.LoggerException
HResult = COR_E_APPLICATION=80131600
StackTraceString = “
  at JetBrains.Util.ILoggerEx.LogMessage(ILogger this, LoggingLevel level, String message)
     at JetBrains.ReSharper.UnitTestFramework.TestRunner.ServerEndpoint.<>c__DisplayClass9_2.<TryRegisterHandler>b__3()
     at System.Threading.Tasks.Task`1.InnerInvoke()
     at System.Threading.Tasks.Task.Execute()
     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.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
     at System.Threading.Tasks.Task.ExecuteEntry(Boolean bPreventDoubleExecution)
     at System.Threading.ThreadPoolWorkQueue.Dispatch()
”

13:56:53.480 |I| Process C:\Program Files\JetBrains\JetBrains Rider 2020.1.4\lib\ReSharperHost\TestRunner\net461\ReSharperTestRunner64.exe:35016 has exited with code (0)
13:56:53.485 |I| Output stream: Searching for config 'additionalConfig.json' in '***.Tests\bin\x64\Debug\net472' and parents.

***

13:56:53.520 |T| Run: 805a26a2-ba84-4943-a5ae-18e30e2719b7 >> RunHostController.CleanupAfterRun
13:56:53.520 |T| Run: 805a26a2-ba84-4943-a5ae-18e30e2719b7 << RunHostController.CleanupAfterRun
13:56:53.536 |I| Run: 805a26a2-ba84-4943-a5ae-18e30e2719b7 - Finished
13:56:53.543 |I| RunTestsStage completed
13:56:53.544 |I| FinishLaunchStage started
13:56:53.551 |I| Finishing launch
13:56:53.565 |W| Element ****
13:56:53.579 |I| Launch is finished
13:56:53.579 |I| FinishLaunchStage completed
13:56:53.582 |T| Launch: 9812da54-105d-4347-89a4-95fe28e999ac >> RunHostController.BeforeLaunchFinished
13:56:53.582 |T| Launch: 9812da54-105d-4347-89a4-95fe28e999ac << RunHostController.BeforeLaunchFinished

robertcoltheart commented 3 years ago

Hmm, I've run my test suite and I'm not able to reproduce this. Are you able to attach a sample project or link to a repo where this problem can be reproduced?

ckragenb commented 3 years ago

Also running into this. Could these be the lines that broke it?

https://github.com/machine/machine.specifications.runner.resharper/pull/160/files#diff-7970962156a5eefe66ca8f1bde2bc4fb8b9fd354e5e4b79454f90bd48cb1edcaR13

https://github.com/machine/machine.specifications.runner.resharper/pull/160/files#diff-02b625ecca5f5e15079c346e293d8852e476ca4f5287fc8262a0242a150579a4R15

robertcoltheart commented 3 years ago

As I mentioned above, I've run this against a few code bases and can't replicate the issue you are seeing. Can you attach a solution or link to a repo that can reproduce this? At the minimum I need to know:

Versions of all the dlls
Version of the Mspec runner and R# addin
Framework version
Whether its old-style CSproj or new
Any other packages

tpeplow commented 3 years ago

I have a repo now. Sorry it took me a bit of time to get there. I will get you a sample project, but if this helps I think the issue is that we have a static ctor on a class which was throwing an exception. I found that, fixed it, and then this issue went away. @neilrees found the place in MSpec that passes along the null, I guess Jetbrains added a guard to that null now.

basically the test did: static Fred fred = new Fred(); That threw

Moving it to:

Establish context = () => 
{
   _fred = new Fred();
  // fred gets busy
}

Just bad timing, that commit came in at the same time as I decided to come back into the code base with a new rider version etc.

neilrees commented 3 years ago

The crash is caused by https://github.com/machine/machine.specifications.runner.resharper/blob/master/src/Machine.Specifications.Runner.ReSharper.Adapters/TestRunListener.cs#L43 passing a null MspecRemoteTask to server.TestOutput.

This ends up in JetBrains.ReSharper.TestRunner.Abstractions.Objects.TestOutputMessage which throws an ArgumentNullException

It repro's when a test has written console output, e.g.:

public class when_a_static_initializer_throws_an_exception_after_writing_to_console
{
    static int i = Init();

    public static int Init()
    {
        Console.WriteLine("in static initializer");
        throw new Exception("pop");
    }

    It should = () => { };
}

Repro'd using 2020.3.1 of the Resharper Runner, Machine.Specifications@1.0.0, on net472. New style csproj.

robertcoltheart commented 3 years ago

Thanks, will try and get it fixed.

robertcoltheart commented 3 years ago

Working on this here: https://github.com/machine/machine.specifications.runner.resharper/pull/161

robertcoltheart commented 3 years ago

This is released as v2021.1.2. It may take up to 2 business days for Jetbrains to approve.

machine / machine.specifications

Rider and VS test runner - value cannot be null task in TestOutputMessage..ctor #434