MSBuild project tools extension doesn't work when the SDK version specified in global.json isn't installed

[DJackman123]

When I have multiple .NET SDKs installed on my machine, the MSBuild project tools extension fails to start with this output:

System.FormatException: The 'dotnet --version' command did not return valid version information ('6.0.424 [C:\Program Files\dotnet\sdk]
8.0.303 [C:\Program Files\dotnet\sdk]
8.0.400-preview.0.24324.5 [C:\Program Files\dotnet\sdk]' is not a valid semantic version).
   at MSBuildProjectTools.LanguageServer.Utilities.DotNetRuntimeInfo.ParseDotNetVersionOutput(TextReader dotnetVersionOutput)
   at MSBuildProjectTools.LanguageServer.Utilities.DotNetRuntimeInfo.GetCurrent(String baseDirectory, ILogger logger)
   at MSBuildProjectTools.LanguageServer.Utilities.MSBuildHelper.DiscoverMSBuildEngine(String baseDirectory, ILogger logger)
   at MSBuildProjectTools.LanguageServer.Program.Main()
[Error - 3:51:18 PM] Connection to server got closed. Server will not be restarted.
[Error - 3:51:18 PM] MSBuild Language Service client: couldn't create connection to server.
  Message: Pending response rejected since connection got disposed
  Code: -32097 
[Error - 3:51:18 PM] Server process exited with code 1.

This is the output from dotnet --version:

The command could not be loaded, possibly because:
  * You intended to execute a .NET application:
      The application '--version' does not exist.
  * You intended to execute a .NET SDK command:
      A compatible .NET SDK was not found.

Requested SDK version: 8.0.203
global.json file: D:\OB\svdcv2\global.json

Installed SDKs:
6.0.424 [C:\Program Files\dotnet\sdk]
8.0.303 [C:\Program Files\dotnet\sdk]
8.0.400-preview.0.24324.5 [C:\Program Files\dotnet\sdk]

Install the [8.0.203] .NET SDK or update [D:\OB\svdcv2\global.json] to match an installed SDK.

Learn about SDK resolution:
https://aka.ms/dotnet/sdk-not-found

For this repo, global.json specifies .NET SDK version 8.0.203, and that version isn't one of the three that's installed.
The extension needs to handle this situation better. Either use one of the three installed versions (it seems like it's treating the output section of "Installed SDKs" as a single version instead of three different versions) or more gracefully fail with information about what's going wrong and how to fix it.

[tintoy]

Thanks for reporting - I’ve not seen that particular error before (this scenario is definitely supposed to work including the parsing of multiple versions so I’ll try to get a repro environment going to figure out where it’s going wrong).

From memory, 6.x tooling changed how SDK versions are reported; I wonder if this is an edge case relating to that…

[tintoy]

The extension, these days, is meant to automatically acquire the required version of the .net SDK, so it’s also possible that it might be failing to see the version in global.json.

CC: @DoctorKrolic

[DJackman123]

The contents of D:\OB\svdcv2\global.json looks like this:

{
    "sdk":  {
                "version":  "8.0.203"
            }
}

[tintoy]

The parser:

https://github.com/tintoy/msbuild-project-tools-server/blob/master/src/LanguageServer.Common/Utilities/DotNetRuntimeInfo.cs

[tintoy]

We did change this a little while ago to remove some legacy parsing logic for SDK tooling before 6.x but since you’re at 8.x it shouldn’t matter. We have some tests I can plug your output into to verify how the parser would behave so I’ll have a go at that this evening after work.

What version of the extension do you have installed?

[tintoy]

The bit of the output that I find interesting is:

The command could not be loaded, possibly because:
  * You intended to execute a .NET application:
      The application '--version' does not exist.
  * You intended to execute a .NET SDK command:
      A compatible .NET SDK was not found.

From memory, that only shows up when the dotnet executable is from an install of the .net runtime rather than an install of the .net SDK.

If you run Get-Command dotnet, where does it show that executable as being located?

[DJackman123]

Get-Command for dotnet outputs this:

CommandType Name       Version       Source
----------- ----       -------       ------
Application dotnet.exe 8.0.724.31311 C:\Program Files\dotnet\dotnet.exe

I'm using v0.6.3 of the extension

[tintoy]

I suspect we may need to do a better job of respecting SDK roll-forward policy (I’d need to check what the default is when one’s not specified in global.json).

[tintoy]

When you have a moment, can you also share the output of dotnet --info when run in that directory?

I suspect the issue may be due to running a preview SDK, which does not qualify for detection under the normal rules (we only support stable versions, under normal circumstances). It's something we may be able to handle in the future but for the moment preview SDKs are invisible to us (at least until we add opt-in support for them).

[tintoy]

Maybe related: #144 (comment)

[DJackman123]

Here is the output from dotnet --info:

Host:
  Version:      8.0.7
  Architecture: x64
  Commit:       2aade6beb0
  RID:          win-x64

.NET SDKs installed:
  6.0.424 [C:\Program Files\dotnet\sdk]
  8.0.303 [C:\Program Files\dotnet\sdk]
  8.0.400-preview.0.24324.5 [C:\Program Files\dotnet\sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.App 6.0.30 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 6.0.32 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 7.0.19 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 7.0.20 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 8.0.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 8.0.7 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 6.0.30 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.32 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 7.0.19 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 7.0.20 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 8.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 8.0.7 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 6.0.30 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 6.0.32 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 7.0.19 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 7.0.20 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 8.0.5 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 8.0.7 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

Other architectures found:
  x86   [C:\Program Files (x86)\dotnet]
    registered at [HKLM\SOFTWARE\dotnet\Setup\InstalledVersions\x86\InstallLocation]

Environment variables:
  Not set

global.json file:
  D:\OB\svdcv2\global.json

Learn more:
  https://aka.ms/dotnet/info

Download .NET:
  https://aka.ms/dotnet/download

[tintoy]

Oddly, when I paste the output above into our parser tests, they have no problem parsing it.

Could you do one last test for me, please? Can you add a setting to VSCode:

msbuildProjectTools.logging.level = Verbose, set an environment variable MSBUILD_PROJECT_TOOLS_DOTNET_HOST_DIAGNOSTICS =1, and then try relaunching and opening the project again?

At that verbosity level it should log the full path to the SDK tooling that it’s using, and exact output it’s getting from dotnet --info (etc).

[tintoy]

@DoctorKrolic I think that legacy code path we removed a little while back may have handled this scenario a little better (and if nothing else it may be worth resurrecting some of the associated tests even if they need to be updated for the “modern” way of parsing the version info). I might have a go at doing that this weekend if you have no objections.

[DJackman123]

I am not seeing any difference in the output window after adding that setting (in settings.json) and setting that environment variable before launching VSCode.

[tintoy]

I am not seeing any difference in the output window after adding that setting (in settings.json) and setting that environment variable before launching VSCode

Hmm, you should be seeing something like this in the output pane titled "MSBuild Language Service" (yes there are 2 output panes but we've had trouble using the same one from the extension and language service):

dotnet-info-log.txt

[DJackman123]

That's the output pane I'm looking at:

Is that setting in settings.json (visible in the screenshot) not correct?

[tintoy]

Very strange - that does look correct and, yet, there are no verbose logs there. I don’t suppose those settings could be overridden by workspace-level settings or settings sync?

Ok, 2 additional environment variables to try:

• MSBUILD_PROJECT_TOOLS_VERBOSE_LOGGING=1
• MSBUILD_PROJECT_TOOLS_LOG_FILE=my-path-to-log-file

That should produce “raw” log that doesn’t have to first get sent back to VS Code in order to become visible…

[DJackman123]

Okay, that resulted in this log file.
mpt.log

[tintoy]

Thanks! I think I that's helped me get to the root of the problem:

https://github.com/tintoy/msbuild-project-tools-server/blob/8e5902229c3f4e25fe8226017e3aee1aa0ee79c5/src/LanguageServer.Common/Utilities/DotNetRuntimeInfo.cs#L138

It seems that our current implementation is failing to check the process exit code when running dotnet --version (the command is returning the exit code -2147450735/0x80008091, meaning it was unsuccessful, which makes sense since the output of this command is technically dependent on the implementation in the target SDK version).

Unfortunately, we can't really recover in this scenario since the output from dotnet --version cannot be trusted and so we don't know which parser logic to use; the issue is that the dotnet loader doesn't know what version of the SDK tooling to bootstrap because no installed SDK is compatible with the roll-forward policy (either the default policy or what's specified in global.json).

I do feel that we could probably look for that particular exit code and log a more useful message, however (together with suggested a solution and maybe a link to the Microsoft documentation on global.json, specifically, roll-forward policy).

@DoctorKrolic - sound reasonable to you? I may also raise an issue in Microsoft's dotnet tooling repository just to get a definitive answer regarding expected exit codes.

[tintoy]

Well-known exit codes for the dotnet host executable:

https://github.com/dotnet/runtime/blob/main/docs/design/features/host-error-codes.md