search

tintoy / msbuild-project-tools-vscode

VS Code extension for MSBuild intellisense (including PackageReference completion).
MIT License
83 stars 17 forks source link

Initialising MSBuild project tools... #42

Closed gnimor closed 5 years ago

gnimor commented 5 years ago

I am using the extension for my build projects, now I am getting a circle icon stating that "Initialising MSBuild project tools..."

And this stays forever. Is this the expected behavior?

tintoy commented 5 years ago

No, it definitely shouldn't do that - if you go to the output window and choose MSBuild Project Tools from the drop-down are there any errors in the log?

gnimor commented 5 years ago

Hmm, there is no "MSBuild Project Tools" from the drop-down.

image

tintoy commented 5 years ago

Hmm, in that case it sounds like the language server doesn't even launch successfully. Can you try opening a command prompt and running dotnet --info, then post the output?

joergjo commented 5 years ago

Same problem here. 

.NET Core SDK (gemäß "global.json"):
 Version:   2.1.403
 Commit:    04e15494b6

Laufzeitumgebung:
 OS Name:     Windows
 OS Version:  10.0.17763
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\2.1.403\

Host (useful for support):
  Version: 2.1.5
  Commit:  290303f510

<List of SDKs redacted>
tintoy commented 5 years ago

Hmm, ok, let's try a couple of things to troubleshoot:

  1. Can you run dotnet <extension-dir>\out\language-server\MSBuildProjectTools.LanguageServer.Host.dll and see if anything is printed to the console?
  2. Enable logging to file (if you have the latest version of the extension, the setting is msbuildProjectTools.logging.file), verbose logging (setting is called msbuildProjectTools.logging.level), and try restarting VS Code. Is anything written to the log file?
tintoy commented 5 years ago
  1. Try step one again, but first set environment variable MSBUILD_PROJECT_TOOLS_LOG_FILE to the full path of the log file to write and also set MSBUILD_PROJECT_TOOLS_VERBOSE_LOGGING to 1. See if the log file is written to.
tintoy commented 5 years ago

And can you confirm what version of the extension you have installed? Should be v0.2.42 (latest version).

tintoy commented 5 years ago

Looking at your output, I think there may be a problem due to dotnet --info returning non-english section titles on your system; because Microsoft won't support a machine-readable output format (such as JSON), I have to resort to manually parsing the output of dotnet --info as text in order to find the SDK directory (etc).

This wouldn't explain why the language server process won't launch at all though.

tintoy commented 5 years ago

One more setting to enable:

tintoy commented 5 years ago

Ugh, looks like there was a bug with parsing of extension settings so the settings specified above will have no effect. I'm about to publish v0.2.44 which fixes that bug (at which point we can start troubleshooting).

joergjo commented 5 years ago

Just launched VS Code and it updated to v0.2.44. The extension works again, thanks!

tintoy commented 5 years ago

Odd, but good to hear :)

tintoy commented 5 years ago

Probably related to tintoy/msbuild-project-tools-vscode#43 (should be fixed in v0.2.45, which was published a couple of minutes ago).

joergjo commented 5 years ago

Uh uh, v0.2.45 on Code 1.29 is broken again on a localized version of Win10. Do you need the same telemetry mentioned as earlier in this thread?

tintoy commented 5 years ago

Do you need the same telemetry mentioned as earlier in this thread?

Yes, please!

tintoy commented 5 years ago

I've added the dotnet --info output you supplied as input to one of the new unit tests and it passes; could the problem be something else perhaps?

Can I just confirm the behaviour you're seeing? Is it that it gets stuck on "Initialising MSBuild Project Tools..."?

If so, then yeah I'll need you to enable logging to file so we can work out what's going on...

ltrzesniewski commented 5 years ago

In my case, the dotnet --info process doesn't seem to quit:

image

The extension is in the "Loading project..." state indefinitely.

(v0.2.46)

tintoy commented 5 years ago

Is that when you run it from the command-line?

ltrzesniewski commented 5 years ago

No, that's VS Code running it. When I run it from the command line, it exits just fine. Also, my system language is English, so this may actually be unrelated to the localization issue.

tintoy commented 5 years ago

Ok, can you try enabling the logging (etc) mentioned above and post the resulting log file (if any)?

joergjo commented 5 years ago

OK, now running at v0.2.46, VS Code 1.29.1, and .NET Core SDK 2.1.500, but it's still stuck at "Initialising…".

dotnet .\tintoy.msbuild-project-tools-0.2.46\out\language-server\MSBuildProjectTools.LanguageServer.Host.dll doesn't create any output

I also don't see any log file being written. Should msbuildProjectTools.logging.file point to a directory or a file?

tintoy commented 5 years ago

It should point to a file (the file does not have to exist before running).

tintoy commented 5 years ago

BTW, I'm publishing a new version of the extension (v0.2.47) which has more logging during language server startup which may help when troubleshooting.

@joergjo when you try it out, can you also make sure that msbuildProjectTools.logging.level is set to Verbose?

joergjo commented 5 years ago

OK, so after updating to v0.2.47 the extension works again. Was that expected?

tintoy commented 5 years ago

Nope, only changes were some extra logging statements during start-up :)

Perhaps it's something environmental?

tintoy commented 5 years ago

It's definitely odd...

joergjo commented 5 years ago

OK, so it's one particular machine out of two I use regularly, although both have a very similar setup (OS, locale, .NET Core SDKs, IDEs, …). I'll follow up with the logs later.

joergjo commented 5 years ago

So, after setting MSBUILD_PROJECT_TOOLS_LOG_FILE=<logpath> and MSBUILD_PROJECT_TOOLS_VERBOSE_LOGGING=1 I get the following output when running the language server host:

2018-11-19 21:10:44.337 +01:00 [Verbose/] Logger initialised.
2018-11-19 21:10:44.422 +01:00 [Debug/] Creating language server...
2018-11-19 21:10:44.423 +01:00 [Debug/] Waiting for client to initialise language server...

I'm still unable to get the extension to write a logfile.

{
    "msbuildProjectTools.logging.level": "Verbose",
    "msbuildProjectTools.logging.trace": true,
    "msbuildProjectTools.logging.file": "C:\\Users\\joergjo\\Downloads\\msbuildext.log"
}

has no visible effect.

ltrzesniewski commented 5 years ago

Sorry for the delay. The issue still happens on v0.2.47 for me. Here's the log file:

2018-11-20 00:53:32.899 +01:00 [Verbose/] Logger initialised.
2018-11-20 00:53:32.964 +01:00 [Debug/] Creating language server...
2018-11-20 00:53:32.965 +01:00 [Debug/] Waiting for client to initialise language server...
2018-11-20 00:53:33.038 +01:00 [Debug/] Finding descriptor for "initialize"
2018-11-20 00:53:33.382 +01:00 [Debug/] Starting: Routing Request (0) "initialize"
2018-11-20 00:53:33.402 +01:00 [Debug/] Converting params for Request (0) "initialize" to "OmniSharp.Extensions.LanguageServer.Protocol.Models.InitializeParams"
2018-11-20 00:53:33.418 +01:00 [Debug/] Result was "System.Threading.Tasks.Task`1[[OmniSharp.Extensions.LanguageServer.Protocol.Models.InitializeResult, OmniSharp.Extensions.LanguageProtocol, Version=0.7.9.0, Culture=neutral, PublicKeyToken=null]]"
2018-11-20 00:53:33.421 +01:00 [Debug/] Response value was "OmniSharp.Extensions.LanguageServer.Protocol.Models.InitializeResult"
2018-11-20 00:53:33.423 +01:00 [Debug/] Finished: Routing Request (0) "initialize" in 35ms
2018-11-20 00:53:33.456 +01:00 [Debug/] Finding descriptor for "initialized"
2018-11-20 00:53:33.458 +01:00 [Debug/] Finding descriptor for "workspace/didChangeConfiguration"
2018-11-20 00:53:33.461 +01:00 [Debug/] Starting: Routing Notification "initialized"
2018-11-20 00:53:33.462 +01:00 [Debug/] Finished: Routing Notification "initialized" in 0ms
2018-11-20 00:53:33.464 +01:00 [Debug/] Starting: Routing Notification "workspace/didChangeConfiguration"
2018-11-20 00:53:33.465 +01:00 [Debug/] Converting params for Notification "workspace/didChangeConfiguration" to "MSBuildProjectTools.LanguageServer.CustomProtocol.DidChangeConfigurationObjectParams"
2018-11-20 00:53:33.497 +01:00 [Debug/] Finished: Routing Notification "workspace/didChangeConfiguration" in 33ms
2018-11-20 00:53:33.584 +01:00 [Debug/] Finding descriptor for "textDocument/didOpen"
2018-11-20 00:53:33.587 +01:00 [Verbose/] Created attribute "xml::file:///c:/Dev/Projects/InlineIL.Fody/src/Directory.Build.props"
2018-11-20 00:53:33.588 +01:00 [Verbose/] Looking for handler for method ["OmniSharp.Extensions.LanguageServer.Server.HandlerDescriptor"]
2018-11-20 00:53:33.589 +01:00 [Verbose/] Checking handler ["OmniSharp.Extensions.LanguageServer.Server.HandlerDescriptor"]:"MSBuildProjectTools.LanguageServer.Handlers.DocumentSyncHandler"
2018-11-20 00:53:33.589 +01:00 [Verbose/] Registration options "OmniSharp.Extensions.LanguageServer.Protocol.Models.TextDocumentRegistrationOptions"
2018-11-20 00:53:33.592 +01:00 [Verbose/] Document Selector "[msbuild, file, **/*.*], [xml, file, **/*.*proj], [xml, file, **/*.props], [xml, file, **/*.targets]"
2018-11-20 00:53:33.593 +01:00 [Debug/] Starting: Routing Notification "textDocument/didOpen"
2018-11-20 00:53:33.593 +01:00 [Debug/] Converting params for Notification "textDocument/didOpen" to "OmniSharp.Extensions.LanguageServer.Protocol.Models.DidOpenTextDocumentParams"
2018-11-20 00:53:33.598 +01:00 [Debug/] Language server initialised by client.
2018-11-20 00:53:33.598 +01:00 [Debug/] Finding descriptor for "textDocument/documentSymbol"
2018-11-20 00:53:33.603 +01:00 [Verbose/] Found attributes 1, ["plaintext::file:///c:/Dev/Projects/InlineIL.Fody/src/Directory.Build.props"]
2018-11-20 00:53:33.603 +01:00 [Verbose/] Looking for handler for method ["OmniSharp.Extensions.LanguageServer.Server.HandlerDescriptor"]
2018-11-20 00:53:33.603 +01:00 [Verbose/] Checking handler ["OmniSharp.Extensions.LanguageServer.Server.HandlerDescriptor"]:"MSBuildProjectTools.LanguageServer.Handlers.DocumentSymbolHandler"
2018-11-20 00:53:33.603 +01:00 [Verbose/] Registration options "OmniSharp.Extensions.LanguageServer.Protocol.Models.TextDocumentRegistrationOptions"
2018-11-20 00:53:33.603 +01:00 [Verbose/] Document Selector "[msbuild, file, **/*.*], [xml, file, **/*.*proj], [xml, file, **/*.props], [xml, file, **/*.targets]"
2018-11-20 00:53:33.713 +01:00 [Information/OnDidOpenTextDocument] 1 package sources configured for project "c:\Dev\Projects\InlineIL.Fody\src\Directory.Build.props".
2018-11-20 00:53:33.714 +01:00 [Information/OnDidOpenTextDocument]   Locally-configured package source "nuget.org" (v3) => https://api.nuget.org/v3/index.json

Nothing more, and the dotnet --info is still here. Closing VS at this points just adds this:

2018-11-20 00:56:35.602 +01:00 [Debug/] Finding descriptor for "shutdown"
tintoy commented 5 years ago

@ltrzesniewski - this is quite odd, the log messages you posted indicate that as far as the language server is concerned it's all configured correctly and the extension is communicating with it :-/

What version of VS Code are you running?

ltrzesniewski commented 5 years ago

It's up to date:

Version: 1.29.1 (user setup) Commit: bc24f98b5f70467bc689abf41cc5550ca637088e Date: 2018-11-15T19:13:36.375Z Electron: 2.0.12 Chrome: 61.0.3163.100 Node.js: 8.9.3 V8: 6.1.534.41 Architecture: x64

tintoy commented 5 years ago

Ok, I'm at work so I can't look further into this until later this evening but I'll try again tonight and see if I can do anything to improve the extension-side logging / error reporting.

Can I just confirm - are you on Windows, Linux, or Mac?

ltrzesniewski commented 5 years ago

I'm on Windows.

BTW here's my dotnet --info output in case it helps (I have a couple preview SDKs, maybe it plays a role):

.NET Core SDK (reflecting any global.json):
 Version:   3.0.100-preview-009744
 Commit:    f1b5e95981

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.17134
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\3.0.100-preview-009744\

Host (useful for support):
  Version: 3.0.0-preview-27109-05
  Commit:  2eee399494

.NET Core SDKs installed:
  1.0.0 [C:\Program Files\dotnet\sdk]
  1.0.4 [C:\Program Files\dotnet\sdk]
  1.1.0 [C:\Program Files\dotnet\sdk]
  2.1.2 [C:\Program Files\dotnet\sdk]
  2.1.103 [C:\Program Files\dotnet\sdk]
  2.1.104 [C:\Program Files\dotnet\sdk]
  2.1.201 [C:\Program Files\dotnet\sdk]
  2.1.202 [C:\Program Files\dotnet\sdk]
  2.1.300-preview2-008533 [C:\Program Files\dotnet\sdk]
  2.1.302 [C:\Program Files\dotnet\sdk]
  2.1.400 [C:\Program Files\dotnet\sdk]
  2.1.401 [C:\Program Files\dotnet\sdk]
  2.1.402 [C:\Program Files\dotnet\sdk]
  2.1.403 [C:\Program Files\dotnet\sdk]
  2.1.500 [C:\Program Files\dotnet\sdk]
  2.2.100-preview3-009430 [C:\Program Files\dotnet\sdk]
  3.0.100-preview-009744 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.0-preview2-final [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.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.6 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.2.0-preview3-35497 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 3.0.0-alpha1-10663 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.0-preview2-final [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.4 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.5 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.6 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.2.0-preview3-35497 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.0.0-alpha1-10663 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.DesktopUI.App 3.0.0-alpha-27106-4 [C:\Program Files\dotnet\shared\Microsoft.DesktopUI.App]
  Microsoft.NETCore.App 1.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.1.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.6 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.7 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.9 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0-preview2-26406-04 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.3-servicing-26724-03 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.6 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.2.0-preview3-27014-02 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.0.0-preview-27109-05 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs:
  https://aka.ms/dotnet-download
tintoy commented 5 years ago

Thanks! I'll take a look as soon as I can :)

tintoy commented 5 years ago

Just as a quick experiment, if you temporarily move the directory C:\Program Files\dotnet\sdk\3.0.100-preview-009744 outside the C:\Program Files\dotnet\sdk directory, do you still see this problem while initialising? I'm just trying to work out whether it's trying to use a newer version of the .NET Core SDK that it doesn't understand...

If not, I'll try installing the latest 3.x preview SDK when I get home and give it a try myself.

tintoy commented 5 years ago

I have found and fixed an issue where dotnet --info hangs because its STDOUT buffer fills up (because the command now produces longer output than before).

But it has exposed a separate issue; if you have a .NET Core v3.x preview SDK installed, you won't be able to load projects unless you have a global.json that locks your SDK to v2.x in the same directory as your solution file (the structure of the SDK directory has changed, and MSBuild project tools can't automatically determine where the correct .props and .targets files live when they are included by loaded projects).

You may be able to work around the issue (once I've released a new build of the extension) by setting the MSBuildSDKsPath environment variable to something like C:\Program Files\dotnet\sdk\2.1.401.

tintoy commented 5 years ago

Published v0.2.49 - can you give it a try and see how far you get?

ltrzesniewski commented 5 years ago

Thanks! This works fine on my work computer (where I don't have the v3 SDK installed). The previous version didn't work. I'll tell you how it goes on my home computer tonight.

joergjo commented 5 years ago

Good news, it works for me as well and I also found why logging didn't before.

It seems that at some point I've accidentally created an invalid user setting section for msbuildProjectTools.* which silently broke the extension--the log settings I had created ath the workspace level were simply ignored. After removing the invalid section, everything started working again, and a logfile was written.

ltrzesniewski commented 5 years ago

I tested it a bit on my home PC with the v3 SDK. Evaluation works fine, but completion inside Condition attributes doesn't seem to produce useful results. As I haven't really used this extension until now I can't tell if it's normal or not. I'll use it at work a bit so I will be able to tell if it's an issue or if I was just expecting too much. Thanks for the fix! 😄

tintoy commented 5 years ago

No problem glad it's working now :)

Do other completions work for you, or none at all? Support for expression completions should work so if it's not, feel free to open a new issue. If possible, post the project file you're working with and where you're expecting a completion (line and column).

tintoy commented 5 years ago

Just remembered - if you want intellisense for expressions make sure the editor language is "MSBuild", not "XML".

tintoy commented 5 years ago

Closing this issue for now, since it seems to be resolved. Feel free to reopen if the problem occurs again :)

ltrzesniewski commented 5 years ago

facepalm

Yeah, the file mode was XML actually, but I didn't pay attention since I still got the tooltips from the extension. I didn't expect this extension to be active in XML mode at all.

So yeah, completion works fine now, thanks! 😉

randre70 commented 5 years ago

Good news, it works for me as well and I also found why logging didn't before.

It seems that at some point I've accidentally created an invalid user setting section for msbuildProjectTools.* which silently broke the extension--the log settings I had created ath the workspace level were simply ignored. After removing the invalid section, everything started working again, and a logfile was written.

Still applies today (v0.2.54), check your settings for an invalid section.

dmitry64 commented 5 years ago

I'm running Linux, and I have the same issue after upgrading my dotnet core to 3.0. I tried 

MSBuildSDKsPath=/usr/share/dotnet/sdk/3.0.100 code

But that did not help. Is there any other way to fix that or should I just wait for the update?

tintoy commented 5 years ago

I’m still having trouble making this happen on demand for some reason - can you tell which distro and version of Linux you are running? And can you post the output of dotnet —info?

I’m going to see if I can get you to capture a dump of the hung process (but I’m not sure how to do this for Linux yet).

dmitry64 commented 4 years ago

Here is my dotnet --info

.NET Core SDK (reflecting any global.json):
 Version:   3.0.100
 Commit:    04339c3a26

Runtime Environment:
 OS Name:     ubuntu
 OS Version:  19.04
 OS Platform: Linux
 RID:         ubuntu.19.04-x64
 Base Path:   /usr/share/dotnet/sdk/3.0.100/

Host (useful for support):
  Version: 3.0.0
  Commit:  95a0a61858

.NET Core SDKs installed:
  3.0.100 [/usr/share/dotnet/sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.App 3.0.0 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 3.0.0 [/usr/share/dotnet/shared/Microsoft.NETCore.App]
tintoy commented 4 years ago

Note to self: give dotnet-dump a try (via WSL).

dmitry64 commented 4 years ago

You can try installing Ubuntu in virtual machine and installing dotnet core 3.0 + vscode there.