Language server unable to start - `dotnet --version` failure

[tillig]

As of 0.4.7 of the plugin, it appears the detection logic for the .NET version has changed such that, at least in my environment, the detection consistently fails.

In 0.4.6 of the plugin, my output window shows the MSBuild language server starting up just fine:

Starting MSBuild language service...
MSBuild language service is running.

However, in 0.4.7, I see The 'dotnet --version' command did not return any output.

I've tried to run the language server manually and I get the same thing:

$ dotnet /Users/tillig/.vscode/extensions/tintoy.msbuild-project-tools-0.4.7/out/language-server/MSBuildProjectTools.LanguageServer.Host.dll --probe
System.InvalidOperationException: The 'dotnet --version' command did not return any output.
   at MSBuildProjectTools.LanguageServer.Utilities.DotNetRuntimeInfo.ParseDotNetVersionOutput(TextReader dotnetVersionOutput) in D:\Development\github\tintoy\msbuild-project-tools-vscode\lib\server\src\LanguageServer.Common\Utilities\DotNetRuntimeInfo.cs:line 147
   at MSBuildProjectTools.LanguageServer.Utilities.DotNetRuntimeInfo.GetCurrent(String baseDirectory, ILogger logger) in D:\Development\github\tintoy\msbuild-project-tools-vscode\lib\server\src\LanguageServer.Common\Utilities\DotNetRuntimeInfo.cs:line 69
   at MSBuildProjectTools.LanguageServer.Utilities.MSBuildHelper.DiscoverMSBuildEngine(String baseDirectory, ILogger logger) in D:\Development\github\tintoy\msbuild-project-tools-vscode\lib\server\src\LanguageServer.Common\Utilities\MSBuildHelper.cs:line 96
   at MSBuildProjectTools.LanguageServer.Program.Main() in D:\Development\github\tintoy\msbuild-project-tools-vscode\lib\server\src\LanguageServer\Program.cs:line 46

Reverting to 0.4.6, the same command is successful:

$ dotnet /Users/tillig/.vscode/extensions/tintoy.msbuild-project-tools-0.4.6/out/language-server/MSBuildProjectTools.LanguageServer.Host.dll --probe
PROBE: Yes, the language server can start.

I've cloned the language server code and, at least on the master branch, running interactively things seem to work and it can detect, say, .NET 6.0.301. There aren't easy to determine tags for individual version releases so I haven't been able to go back in time and figure out what version of the language server is attached to what version of the plugin yet.

If it helps, I'm on Mac OS Monterey 12.5.1, Intel hardware. VS Code 1.70.2.

[tintoy]

Yeah - I’m wondering if it’s some sort of race condition when waiting for the dotnet process to exit and capturing its output? I’m struggling to understand why dotnet --version would ever return no output.

[tintoy]

(thanks for taking the time to reproduce this issue!)

[tintoy]

You can set 2 environment variables before running the --probe command to enable logging of the results from dotnet --version to the console:

MSBUILD_PROJECT_TOOLS_VERBOSE_LOGGING=1 and MSBUILD_PROJECT_TOOLS_LOGGING_TO_STDERR=1

[lonix1]

Same here linux .net 6.0.400 vscode 1.70.2

Downgraded to extension 0.4.6 and problem disappeared.

[tintoy]

If either if you get a chance, can you post the output when those 2 environment variables are set? I've checked the code changes between those versions and it looks like the logic for launching the dotnet host and capturing its output has not changed (which leaves me wondering why dotnet --version sometimes produces no output and whether it has the same exit code as usual).

[tintoy]

Published v0.4.8 (may take a couple of minutes to show up in the gallery).

Note: there is now an additional environment variable you can set (MSBUILD_PROJECT_TOOLS_DOTNET_HOST_DIAGNOSTICS=1) before running the --probe command which causes the dotnet host to dump out a huge volume of diagnostic information.

So, just to summarise for anyone skipping to the end of this thread, these are the environment variables to set if you want to collect as much diagnostic information as possible:

MSBUILD_PROJECT_TOOLS_VERBOSE_LOGGING=1 MSBUILD_PROJECT_TOOLS_LOGGING_TO_STDERR=1 MSBUILD_PROJECT_TOOLS_DOTNET_HOST_DIAGNOSTICS=1

🙂

[lonix1]

How do I use --probe? That doesn't seem to be a dotnet switch?

[tintoy]

Here's example output:

probe-output.txt

[tintoy]

How do I use --probe? That doesn't seem to be a dotnet switch?

Oops! Sorry, that was in a post on the other issue (tintoy/msbuild-project-tools-server#28) and I forgot to copy it over to here 🙂

It should be:

MSBUILD_PROJECT_TOOLS_VERBOSE_LOGGING=1 MSBUILD_PROJECT_TOOLS_LOGGING_TO_STDERR=1 MSBUILD_PROJECT_TOOLS_DOTNET_HOST_DIAGNOSTICS=1 "/usr/bin/dotnet" "/root/.vscode-server/extensions/tintoy.msbuild-project-tools-0.4.6/out/language-server/MSBuildProjectTools.LanguageServer.Host.dll" --probe

(you may need to update the paths for your local system to match the ones you see in the error message)

[lonix1]

$ MSBUILD_PROJECT_TOOLS_VERBOSE_LOGGING=1 MSBUILD_PROJECT_TOOLS_LOGGING_TO_STDERR=1 MSBUILD_PROJECT_TOOLS_DOTNET_HOST_DIAGNOSTICS=1 /usr/bin/dotnet ~/.vscode/extensions/tintoy.msbuild-project-tools-0.4.6/out/language-server/MSBuildProjectTools.LanguageServer.Host.dll --probe
PROBE: Yes, the language server can start.

[tintoy]

Would you be able to try that on v0.4.8? The additional diagnostic info logging has only just been added to this latest version.

[lonix1]

I installed 0.4.8, restarted vscode, and the problem disappeared!

[tintoy]

I had this sneaking feeling that was going to be the case (gotta love heisenbugs!) 😂

[lonix1]

If you're right and it's a heisenbug, you know it'll reappear as soon as you close this issue...

[tillig]

Under 0.4.8, if I have the environment variables in place to log things, it all works; if I don't have the environment variables, it fails to start up. That makes me think the theory there's a race condition going on is possibly right on - the added logging provides just enough delay for the I/O buffer to finish writing the data and work.

Looking at the area where dotnet is invoked, I wonder if this might be the issue

From that comment:

---

I suspect you might be seeing a known problem where there is a race condition between Process.Exited and Process.OutputDataReceived events.

See the remarks here:

https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.process.waitforexit?redirectedfrom=MSDN&view=netcore-3.1#System_Diagnostics_Process_WaitForExit_System_Int32

When standard output has been redirected to asynchronous event handlers, it is possible that output processing will not have completed when this method returns. To ensure that asynchronous event handling has been completed, call the WaitForExit() overload that takes no parameter after receiving a true from this overload.

If you are calling Process.WaitForExit(int timeout), you actually have to call it again without the timeout to ensure that stdout has been flushed e.g. change this:

return Process.WaitForExit(timeout);

to this:

bool result = Process.WaitForExit(timeout);
if (result)
{
    Process.WaitForExit();
}
return result;

---

Perhaps adding the second Process.WaitForExit() would flush the buffer and achieve the desired result consistently?

[tintoy]

Ooh nice find! Thanks, I’ll give this a try tomorrow 🙂

[lonix1]

Heisenbug is back. I'll guinea pig the next version for you when it's ready.

[tintoy]

Published v0.4.9 🙂

You can also install from this VSIX package: msbuild-project-tools-0.4.9.zip

[lonix1]

Works! ...for me. Thanks.

The question is whether it works for @tillig as he seems able to collapse the wave function just by thinking about it.

[tillig]

I'm back in business! 0.4.9 does appear to resolve the issue. Thanks for the quick turnaround!