Debugging tests in VS Code no longer works in preview SDKs

[agocke]

Description

Up until an SDK update a few days ago, everything worked fine. Now, every time I try to debug a test in VS Code I get the error "Error processing launch options at field: program". I looked through the Omnisharp logs and it looks like they're passing the appropriate path to the target binary through the VS Test manager, and it looks like the arguments are bad when coming into the debugger (path is null). VSTest probably broke something in between and the correct arguments are no longer being passed through.

Steps to reproduce

I created a simple netcore project with a single XUnit test and the appropriate references

    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="16.6.1" />
    <PackageReference Include="xunit" Version="2.4.1" />
    <PackageReference Include="xunit.runner.visualstudio" Version="2.4.2">
      <IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
      <PrivateAssets>all</PrivateAssets>
    </PackageReference>

Then, click on "Debug test" in the CodeLens window in Omnisharp on any test. A dialog with the error message "Error processing launch options at field: program" will appear.

Diagnostic logs

Can provide more if necessary, but this should be easy to reproduce locally.

Environment

$ dotnet --info
.NET Core SDK (reflecting any global.json):
 Version:   3.1.400-preview-015178
 Commit:    60cb58d3b1

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.18363
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\3.1.400-preview-015178\

Host (useful for support):
  Version: 3.1.2
  Commit:  916b5cba26

.NET Core SDKs installed:
  3.1.100 [C:\Program Files\dotnet\sdk]
  3.1.102 [C:\Program Files\dotnet\sdk]
  3.1.400-preview-015177 [C:\Program Files\dotnet\sdk]
  3.1.400-preview-015178 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.1 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.12 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.1 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.12 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.12 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 3.1.2 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

To install additional .NET Core runtimes or SDKs:
  https://aka.ms/dotnet-download

[nohwnd]

@cvpoienaru could this be caused by the recent child process debugging changes? Only other thing I can think of is that the xunit packages got an update.

[agocke]

@nohwnd This is dogfood blocking -- could we prioritize looking into it?

[cvpoienaru]

@nohwnd, from the looks of it, this issue doesn't seem to be related to the changes you mentioned because those changes were merged in 16.7.0-preview-20200519-01 whereas the Microsoft.NET.Test.Sdk package version being used is 16.6.1.

@agocke I'll further investigate this and I'll keep you posted.

[JoeRobich]

@nohwnd @cvpoienaru I believe this issue is that OmniSharp-Roslyn expects the TestProcessStartInfo as a response to the "TestExecution.GetTestRunnerProcessStartInfoForRunSelected" message (See my comment https://github.com/OmniSharp/omnisharp-vscode/issues/3459#issuecomment-659757939). When we do not receive that message we pass an empty program argument as the debugger launch info.

These are the message we are getting in response to "TestExecution.GetTestRunnerProcessStartInfoForRunSelected"

[dbug]: OmniSharp.DotNetTest.VSTestManager
        send: {"MessageType":"TestExecution.GetTestRunnerProcessStartInfoForRunSelected","Payload":{"TestCases":[{"Properties":[{"Key":{"Id":"TestCase.FullyQualifiedName","Label":"FullyQualifiedName","Category":"","Description":"","Attributes":1,"ValueType":"System.String"},"Value":"omnisharp_vscode_repro.UnitTest1.Test1"},{"Key":{"Id":"TestCase.ExecutorUri","Label":"Executor Uri","Category":"","Description":"","Attributes":1,"ValueType":"System.Uri"},"Value":"executor://xunit/VsTestRunner2/netcoreapp"},{"Key":{"Id":"TestCase.Source","Label":"Source","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":"/Users/joeyrobichaud/Source/omnisharp_vscode_repro/artifacts/omnisharp-vscode-repro.dll"},{"Key":{"Id":"TestCase.CodeFilePath","Label":"File Path","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":"/Users/joeyrobichaud/Source/omnisharp_vscode_repro/UnitTest1.cs"},{"Key":{"Id":"TestCase.DisplayName","Label":"Name","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":"omnisharp_vscode_repro.UnitTest1.Test1"},{"Key":{"Id":"TestCase.Id","Label":"Id","Category":"","Description":"","Attributes":1,"ValueType":"System.Guid"},"Value":"59b97bed-adc2-eb3a-02dc-4b5f9bb224c5"},{"Key":{"Id":"TestCase.LineNumber","Label":"Line Number","Category":"","Description":"","Attributes":1,"ValueType":"System.Int32"},"Value":10},{"Key":{"Id":"XunitTestCase","Label":"xUnit.net Test Case","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":":F:omnisharp_vscode_repro.UnitTest1:Test1:1:0:796d4d40879548908c4ff0d4aacd1072"}]}],"DebuggingEnabled":true,"RunSettings":"\n<RunSettings>\n    <RunConfiguration>\n        <TargetFrameworkVersion>.NETCoreApp,Version=v3.1</TargetFrameworkVersion>\n    </RunConfiguration>\n</RunSettings>"}}
[dbug]: OmniSharp.DotNetTest.VSTestManager
        read: {"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:00.00] xUnit.net VSTest Adapter v2.4.1 (64-bit .NET Core 3.1.4)"}}
[dbug]: OmniSharp.DotNetTest.VSTestManager
        read: {"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:00.52]   Starting:    omnisharp-vscode-repro"}}
[dbug]: OmniSharp.DotNetTest.VSTestManager
        read: {"MessageType":"TestSession.Message","Payload":{"MessageLevel":0,"Message":"[xUnit.net 00:00:00.63]   Finished:    omnisharp-vscode-repro"}}
[dbug]: OmniSharp.DotNetTest.VSTestManager
        read: {"MessageType":"TestExecution.StatsChange","Payload":{"NewTestResults":[{"TestCase":{"Properties":[{"Key":{"Id":"TestCase.FullyQualifiedName","Label":"FullyQualifiedName","Category":"","Description":"","Attributes":1,"ValueType":"System.String"},"Value":"omnisharp_vscode_repro.UnitTest1.Test1"},{"Key":{"Id":"TestCase.ExecutorUri","Label":"Executor Uri","Category":"","Description":"","Attributes":1,"ValueType":"System.Uri"},"Value":"executor://xunit/VsTestRunner2/netcoreapp"},{"Key":{"Id":"TestCase.Source","Label":"Source","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":"/Users/joeyrobichaud/Source/omnisharp_vscode_repro/artifacts/omnisharp-vscode-repro.dll"},{"Key":{"Id":"TestCase.CodeFilePath","Label":"File Path","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":"/Users/joeyrobichaud/Source/omnisharp_vscode_repro/UnitTest1.cs"},{"Key":{"Id":"TestCase.DisplayName","Label":"Name","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":"omnisharp_vscode_repro.UnitTest1.Test1"},{"Key":{"Id":"TestCase.Id","Label":"Id","Category":"","Description":"","Attributes":1,"ValueType":"System.Guid"},"Value":"59b97bed-adc2-eb3a-02dc-4b5f9bb224c5"},{"Key":{"Id":"TestCase.LineNumber","Label":"Line Number","Category":"","Description":"","Attributes":1,"ValueType":"System.Int32"},"Value":10},{"Key":{"Id":"XunitTestCase","Label":"xUnit.net Test Case","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":":F:omnisharp_vscode_repro.UnitTest1:Test1:1:0:796d4d40879548908c4ff0d4aacd1072"}]},"Attachments":[],"Messages":[],"Properties":[{"Key":{"Id":"TestResult.Outcome","Label":"Outcome","Category":"","Description":"","Attributes":0,"ValueType":"Microsoft.VisualStudio.TestPlatform.ObjectModel.TestOutcome, Microsoft.VisualStudio.TestPlatform.ObjectModel, Version=15.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a"},"Value":1},{"Key":{"Id":"TestResult.ErrorMessage","Label":"Error Message","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":null},{"Key":{"Id":"TestResult.ErrorStackTrace","Label":"Error Stack Trace","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":null},{"Key":{"Id":"TestResult.DisplayName","Label":"TestResult Display Name","Category":"","Description":"","Attributes":1,"ValueType":"System.String"},"Value":"omnisharp_vscode_repro.UnitTest1.Test1"},{"Key":{"Id":"TestResult.ComputerName","Label":"Computer Name","Category":"","Description":"","Attributes":0,"ValueType":"System.String"},"Value":"WU2TEHPV05CX-14"},{"Key":{"Id":"TestResult.Duration","Label":"Duration","Category":"","Description":"","Attributes":0,"ValueType":"System.TimeSpan"},"Value":"00:00:00.0044550"},{"Key":{"Id":"TestResult.StartTime","Label":"Start Time","Category":"","Description":"","Attributes":0,"ValueType":"System.DateTimeOffset"},"Value":"2020-07-20T09:38:40.597015-07:00"},{"Key":{"Id":"TestResult.EndTime","Label":"End Time","Category":"","Description":"","Attributes":0,"ValueType":"System.DateTimeOffset"},"Value":"2020-07-20T09:38:40.597124-07:00"}]}],"TestRunStatistics":{"ExecutedTests":1,"Stats":{"Passed":1}},"ActiveTests":[]}}
[dbug]: OmniSharp.DotNetTest.VSTestManager
        read: {"MessageType":"TestExecution.Completed","Payload":{"TestRunCompleteArgs":{"TestRunStatistics":{"ExecutedTests":1,"Stats":{"Passed":1}},"IsCanceled":false,"IsAborted":false,"Error":null,"AttachmentSets":[],"ElapsedTimeInRunningTests":"00:00:00.6419394","Metrics":{}},"LastRunTests":null,"RunAttachments":[],"ExecutorUris":["executor://xunit/VsTestRunner2/netcoreapp"]}}

[JoeRobich]

@nohwnd @cvpoienaru Is it a valid expectation that when we send the "TestExecution.GetTestRunnerProcessStartInfoForRunSelected" message we will receive a serialized TestProcessStartInfo message in response?

[nohwnd]

I would say so, but would wait for @cvpoienaru to confirm.

[cvpoienaru]

@JoeRobich TL;DR: yes, this is a valid expectation indeed.

I tested this in VS 2019 and when we receive a TestExecution.GetTestRunnerProcessStartInfoForRunSelected message we create an ITestHostLauncher instance that's used as a callback to eventually ask the IDE to launch the testhost on behalf of the TP. When the callback is invoked we pass the following message to the caller (in this case VS Code) TestExecution.CustomTestHostLaunch that should also contain a serialized TestProcessStartInfo instance.

I was also able to replicate the issue on VS Code and I'm continuing the investigation.

[JoeRobich]

@cvpoienaru OmniSharp-Roslyn has always passed DebuggingEnabled when it requested TestProcessStartInfo - https://github.com/OmniSharp/omnisharp-roslyn/blob/master/src/OmniSharp.DotNetTest/VSTestManager.cs#L152-L158

I think the issue is that now causes us to branch around where the CustomTestHostLaunch message would be returned - https://github.com/microsoft/vstest/commit/3f18c870db1776dab9c94e7b819c0dad90ff9686#diff-92e085e9ec715b8834b83666cd69c365R421-R422

[JoeRobich]

@cvpoienaru Verified not setting DebuggingEnabled to true resolves this issue for us.

[cvpoienaru]

@JoeRobich @agocke I think I may have found the root cause for this issue. Long story short, what I previously said about the expectation being valid may no longer hold. Does VS Code use the VsTestConsoleRequestSender to send requests to vstest.console or does it maintain JSON level compatibility and implements its own handling of the test discovery/execution protocol messages ? Should it be the second option, can you please confirm that you at least get a TestExecution.EditorAttachDebugger message ? If so, as explained below, there were some changes in the way the debugging workflow works on the TestPlatform side. Would it be acceptable for you to replace your current logic relying on getting a TestProcessStartInfo and launching & attaching to the testhost process with one in which you get a PID (the testhost process has already been launched by the time you get back a reply) and you only have to attach the debugger to an already running process identified by the said PID ?

@shyamnamboodiripad @AbhitejJohn @nohwnd @pavelhorak this issue is related to our TAEF changes (the PR can be found here). I was mistaken at first to think it's not related, but I can now see that dotnet sdk >= 3.1.400 deploys the latest changes in vstest that include the above mentioned PR.

We use the new workflow (AttachDebuggerToProcess) to attach to a process specified by PID instead of the old LaunchAndAttach workflow as seen here.

This happens primarily because, as expected, the customTestHostLauncher is not null, and again, as expected, it is a debugging launcher. The unexpected thing that happens is that it's an instance of ITestHostLauncher2 as well which causes us to use the new workflow instead of the old one. The reason for this can be found here. Observe how this is implementing ITestHostLauncher2. According to our earlier discussion, our assumption was that we won't get an ITestHostLauncher2 and this assumption holds as long as the IDE uses VsTestConsoleRequestSender and implements an ITestHostLauncher that's passed to either of the variants of StartTestRunWithCustomHost as seen here, the way TestWindow does. However, this assumption doesn't hold when JSON level compatibility is maintained instead of using VsTestConsoleRequestSender.

[JoeRobich]

@cvpoienaru We implement the second option. For the time being not setting DebuggingEnabled resolves this issue for us. I will open an issue to investigate moving to the new attach debugger workflow, but, with limited resources and debugging working again, it isn't a priority for us.

Thanks for your help investigating this issue our users will be very happy to have this resolved. =)