Server Not Initialized Error

[LucasBullen]

I am attempting to add your language server within Eclipse. When starting the server I only receive the following message back: {"protocolVersion":"2.0","message":{"code":-32002,"message":"Server Not Initialized"}}

To confirm, I am meant to launch the LS by following the build instructions then executing /out/language-server/MSBuildProjectTools.LanguageServer.Host.dll?

Are there any dependencies that would stop the server from initializing? Am I unaware of a required step?

[tintoy]

Hi - I shouldn't have thought so, normally if you see any LSP message at all, then I think the server is running.

There's an extended logging facility that currently sends log entries to a server called Seq which I can send you instructions for enabling. That may shed some more light on the problem. Otherwise, you might be able to attach the Visual Studio debugger to the language server process once it has been started and turn on "break on all exceptions" to see if there's some unhandled error somewhere that's crashing the server...

Are you able to use your locally-built version of the language server from within VS Code (i.e. follow instructions to run the extension by hitting F5)? If it works from within VS Code, but when called from Eclipse then perhaps there's some sort of difference in how it implements LSP (I'm using OmniSharp's LSP implementation, BTW). Until now, I've treated the LSP implementation as a black box because it simply worked for my use-case but if it's not working elsewhere then perhaps some more investigation is needed :)

[tintoy]

Ah, ok. Looking through the LSP code it sounds like the language server is being sent a request before it has been sent an Initialize request:

https://github.com/Microsoft/language-server-protocol/blob/master/protocol.md#initialize

[tintoy]

I'm not sure how the Eclipse LSP client works, but there might be some method you have to call to send the Initialize message to the language server before sending any other requests...

[LucasBullen]

Ok thanks, I will take another crack at it.

[tintoy]

Ah - is this related to aCute? If so, be aware that OmniSharp itself does not actually speak LSP (it was built before LSP was a thing) and so if you're trying to use OmniSharp client library to talk to the MSBuild service then they won't communicate correctly.

I think there's an LSP client called LSP4J that might do the trick though.

[tintoy]

BTW, if you're still having problems and have some repro code I could use, I'd be happy to try running it and capturing more detailed diagnostics from the language service.

[LucasBullen]

I have my .csproj file editor code here. Opening a .csproj file in the Generic Editor will begin the LS.

In the console you can see that an Initialize message is sent to the language server. There is also a document highlight request sent after the initialize message. This is when we get the Server Not Initialized message.

Do requests get queued or could it be that the second request is processed before the server finishes initializing?

[tintoy]

I believe the protocol says the client is supposed to wait for the server's response to Initialize before sending anything else but I could be wrong. Let me have a look at the LSP implementation library to see what the expected behaviour should be. Just out of curiosity, if you stuck a pause of, say, 5 seconds in there (to allow for start-up time) does the problem go away? Just trying to establish whether it works at all or whether there is something else at play.

[LucasBullen]

Bad news, added a 5 second delay and same result, so not a queuing problem

[tintoy]

Ok - I'll be at work in around 60 mins - will capture a trace of the messages that occur when it works correctly. Does LSP4J have a facility to trace messages?

[tintoy]

Then we can compare :)

[tintoy]

In the meanwhile would you mind passing a writer to the "trace" parameter of the Launcher and posting the resulting output? Would be good to get an idea of the exact sequence of messages being exchanged...

[tintoy]

Ok, here's the sequence of messages I see:

[Trace - 02:16:44] Received request 'client/registerCapability - (0)'.
Params: {
    "registrations": [
        {
            "id": "e5a39b0c-ddbc-483b-a911-7370caaf10f4",
            "method": "textDocument/completion",
            "registerOptions": {
                "triggerCharacters": [
                    "<"
                ],
                "resolveProvider": false,
                "documentSelector": [
                    {
                        "language": "msbuild",
                        "pattern": "**/*.*"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.*proj"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.props"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.targets"
                    }
                ]
            }
        },
        {
            "id": "0bcde790-0574-44e4-acd9-af121a3fffc1",
            "method": "textDocument/didChange",
            "registerOptions": {
                "syncKind": 1,
                "documentSelector": [
                    {
                        "language": "msbuild",
                        "pattern": "**/*.*"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.*proj"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.props"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.targets"
                    }
                ]
            }
        },
        {
            "id": "bc0249b4-d69c-46e8-9ec3-ccee5f6d280a",
            "method": "textDocument/didOpen",
            "registerOptions": {
                "documentSelector": [
                    {
                        "language": "msbuild",
                        "pattern": "**/*.*"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.*proj"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.props"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.targets"
                    }
                ]
            }
        },
        {
            "id": "3cf33804-fa2b-4169-8084-ea79ef9e8a95",
            "method": "textDocument/didClose",
            "registerOptions": {
                "documentSelector": [
                    {
                        "language": "msbuild",
                        "pattern": "**/*.*"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.*proj"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.props"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.targets"
                    }
                ]
            }
        },
        {
            "id": "4ba0578e-b6c1-474e-a6a1-859518df18e1",
            "method": "textDocument/didSave",
            "registerOptions": {
                "includeText": true,
                "documentSelector": [
                    {
                        "language": "msbuild",
                        "pattern": "**/*.*"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.*proj"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.props"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.targets"
                    }
                ]
            }
        },
        {
            "id": "15029003-4d94-4935-8737-f63b76f13754",
            "method": "textDocument/documentSymbol",
            "registerOptions": {
                "documentSelector": [
                    {
                        "language": "msbuild",
                        "pattern": "**/*.*"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.*proj"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.props"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.targets"
                    }
                ]
            }
        },
        {
            "id": "9e0bbd2b-8ea9-4325-8d9d-820a416fc66b",
            "method": "textDocument/definition",
            "registerOptions": {
                "documentSelector": [
                    {
                        "language": "msbuild",
                        "pattern": "**/*.*"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.*proj"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.props"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.targets"
                    }
                ]
            }
        },
        {
            "id": "3f4105b1-efe0-4d78-94c5-152224dbb736",
            "method": "textDocument/hover",
            "registerOptions": {
                "documentSelector": [
                    {
                        "language": "msbuild",
                        "pattern": "**/*.*"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.*proj"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.props"
                    },
                    {
                        "language": "xml",
                        "pattern": "**/*.targets"
                    }
                ]
            }
        }
    ]
}

[Trace - 02:16:44] Sending notification 'textDocument/didOpen'.
Params: {
    "textDocument": {
        "uri": "file:///c%3A/Users/tintoy/Desktop/temp.csproj",
        "languageId": "xml",
        "version": 1,
        "text": "<Project Sdk=\"Microsoft.NET.Sdk\">\r\n    <PropertyGroup>\r\n        <TargetFramework>netstandard1.3</TargetFramework>\r\n        <SomePackage>MyPackage</SomePackage>\r\n        <SomePackage>AnotherPackage</SomePackage>\r\n        <AnotherPackage> '$(SomePackage)' </AnotherPackage>\r\n        <AnotherPackage> $(SomePackage) </AnotherPackage>\r\n        <YetAnotherProperty>false</YetAnotherProperty>\r\n        <AnotherProperty Condition=\" '$(YetAnotherProperty)' == 'true' \">Hello</AnotherProperty>\r\n    </PropertyGroup>\r\n\r\n    <Target Name=\"SomeTarget\" BeforeTargets=\"AfterBuild;AfterClean;;AfterPublish\">\r\n        \r\n    </Target>\r\n    \r\n    \r\n    <ItemGroup>\r\n        <PackageReference Include=\"Newtonsoft.Json\" Version=\"10.0.3\" />\r\n        <PackageReference Include=\"$(SomePackage)\" Version=\"1.0.0\" />\r\n        <Foo Include=\"A;B;C;D;E;F\" Diddly=\"Hello%(Identity)\" Mo=\"$(AllowUnsafeBlocks)\" />\r\n        <Foo Include=\"G;H;I;J\" Diddly=\"Dee\" Mo=\"\" />\r\n        <Foo Include=\"K;L;M\" Diddly=\"Dee\" ExtensionsPath=\"$(MSBuildExtensionsPath)\" Condition=\" '$(AnotherProperty)' == 'Hello' \" />\r\n        <Bar Include=\"A;@(Foo->'%(Diddly)')\">\r\n            \r\n        </Bar>\r\n        <Compile Include=\"Mo.cs\">\r\n            \r\n        </Compile>\r\n    </ItemGroup>\r\n</Project>"
    }
}

[Trace - 02:16:44] Sending response 'client/registerCapability - (0)'. Processing request took 2ms
[Trace - 02:16:44] Received notification 'msbuild/busy'.
Params: {
    "isBusy": true,
    "message": "Loading project..."
}

[Trace - 02:16:47] Received notification 'textDocument/publishDiagnostics'.
Params: {
    "uri": "file:///c%3A/Users/tintoy/Desktop/temp.csproj",
    "diagnostics": []
}

[Trace - 02:16:47] Received notification 'msbuild/busy'.
Params: {
    "isBusy": false,
    "message": "Project loaded."
}

[Trace - 02:16:47] Received notification 'window/logMessage'.
Params: {
    "type": 3,
    "message": "Successfully loaded project \"c:\\Users\\tintoy\\Desktop\\temp.csproj\"."
}

Unfortunately, it doesn't show the initialize message or its response which is slightly annoying. I've been treating the LSP library I'm using as a bit of a black-box so far because it just works for my use-case, but I can see that perhaps I should extend it with server-side tracing :-/

[LucasBullen]

The output of the input/output from the MSBuildStreamConnectionProvider. Is this what you are looking for / expected?

13:22:26 Output:Content-Length: 674

13:22:26 Output:Content-Length: 674

13:22:26 Output:{
  "jsonrpc":"2.0",
  "id":"1",
  "method":"initialize",
  "params":{
    "rootPath":"/home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1",
    "rootUri":"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/",
    "capabilities":{
      "workspace":{
        "applyEdit":true,
        "symbol":{ },
        "executeCommand":{ }
      },
      "textDocument":{
        "synchronization":{
          "willSave":true,
          "willSaveWaitUntil":true,
          "didSave":true
        },
        "completion":{
          "completionItem":{
            "snippetSupport":true
          }
        },
        "hover":{ },
        "signatureHelp":{ },
        "references":{ },
        "documentHighlight":{ },
        "documentSymbol":{ },
        "formatting":{ },
        "rangeFormatting":{ },
        "definition":{ },
        "codeAction":{ },
        "codeLens":{ },
        "documentLink":{ },
        "rename":{ }
      }
    },
    "clientName":"Eclipse SDK"
  }
}

13:22:26 Output:{
  "jsonrpc":"2.0",
  "id":"1",
  "method":"initialize",
  "params":{
    "rootPath":"/home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1",
    "rootUri":"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/",
    "capabilities":{
      "workspace":{
        "applyEdit":true,
        "symbol":{ },
        "executeCommand":{ }
      },
      "textDocument":{
        "synchronization":{
          "willSave":true,
          "willSaveWaitUntil":true,
          "didSave":true
        },
        "completion":{
          "completionItem":{
            "snippetSupport":true
          }
        },
        "hover":{ },
        "signatureHelp":{ },
        "references":{ },
        "documentHighlight":{ },
        "documentSymbol":{ },
        "formatting":{ },
        "rangeFormatting":{ },
        "definition":{ },
        "codeAction":{ },
        "codeLens":{ },
        "documentLink":{ },
        "rename":{ }
      }
    },
    "clientName":"Eclipse SDK"
  }
}

13:22:28 Output:Content-Length: 234

13:22:28 Output:Content-Length: 234

13:22:28 Output:{
  "jsonrpc":"2.0",
  "id":"2",
  "method":"textDocument/documentHighlight",
  "params":{
    "textDocument":{
      "uri":"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/NewDotnetProject1.csproj"
    },
    "position":{
      "line":0,
      "character":0
    }
  }
}

13:22:28 Output:{
  "jsonrpc":"2.0",
  "id":"2",
  "method":"textDocument/documentHighlight",
  "params":{
    "textDocument":{
      "uri":"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/NewDotnetProject1.csproj"
    },
    "position":{
      "line":0,
      "character":0
    }
  }
}

13:22:40 Input:{
  "protocolVersion":"2.0",
  "message":{
    "code":-32002,
    "message":"Server Not Initialized"
  }
}

[tintoy]

Thanks - ok, so it looks to me like the server hasn't sent the response to the initial initialize request (yet?)...

Let me add a little logging to the server to capture that stuff. Give me 10 or 15 minutes?

[tintoy]

Ok, @LucasBullen, would you mind pulling the latest code from master? If you then republish the language server, you can enable logging-to-file by setting the MSBUILD_PROJECT_TOOLS_LOG_FILE environment variable to the full path of the desired log file before starting the server. I've added some extra diagnostic stuff, but if this still doesn't shed enough light I may need to create a custom build of the LSP library that is capable of logging raw requests and responses.

[tintoy]

BTW, if you are able to put your client code into a console app, I can run it and attach a debugger to the language service to see if anything is causing the server to die (since it looks like you never receive any responses from it at all).

[LucasBullen]

Another question, on the build instructions it says dotnet publish src/LanguageServer/LanguageServer.Host.csproj -o $PWD/out/language-server Is the Host supposed to be there or is that a mistake as there is no LanguageServer.Host.csproj?

[tintoy]

Oops! Sorry, I renamed that project to just LanguageServer\LanguageServer.csproj. I'll fix the readme.

[tintoy]

BTW, sorry about this but you may need to fetch the master branch again (it's now 5am here, but was 3am when I made the change, and I forgot to push one of the changes required to make logging work). Last time, I promise :)

[LucasBullen]

Thanks for all the help you are putting in.

[tintoy]

No worries - I'd love to see it being used in other editors; the more people find it useful, the better

[LucasBullen]

Got the logging output:

2017-09-19 09:48:31.293 -04:00 [Verbose/] Logger initialised.
2017-09-19 09:48:32.661 -04:00 [Verbose/] Logger initialised.
2017-09-19 09:48:34.169 -04:00 [Verbose/] Logger initialised.

Not too much going on, but at least we can see that the logger was initialised.

[tintoy]

Heh, ok - I've been writing an LSP client over the last couple of days and have fully instrumented versions of the LSP assemblies lying around somewhere (they dump the STDIN and STDOUT streams to the log). Give me an hour or so and I'll dig them up and post them here.

[tintoy]

Even better I have a (simplified) dummy language server with extended logging - will dig that up, too.

[tintoy]

Ok, @LucasBullen, would you mind trying to build and use this language server instead? It has lots of extended logging and a simplified design (but is built using the same LSP framework):

https://github.com/tintoy/dotnet-language-client

To get it running:

1. dotnet restore
2. dotnet build

Then use samples/Server/bin/Debug/netcoreapp2.0/Server.dll instead of the MSBuild server assembly.

You'll need to set the LSP_LOG_FILE environment variable to the full path of the desired log file, and set LSP_VERBOSE_LOGGING to 1.

Here's a sample of what the log should contain:

2017-09-20 02:19:39.618 +10:00 [Information] Initialising language server...
2017-09-20 02:19:39.681 +10:00 [Information] Starting language server...
2017-09-20 02:19:39.683 +10:00 [Information] Opening LSP connection...
2017-09-20 02:19:39.684 +10:00 [Information] Starting input handler...
2017-09-20 02:19:39.684 +10:00 [Information] Starting output handler...
2017-09-20 02:19:39.688 +10:00 [Information] Started output handler.
2017-09-20 02:19:39.693 +10:00 [Information] Started input handler.
2017-09-20 02:19:39.693 +10:00 [Information] LSP connection is open.
2017-09-20 02:19:39.695 +10:00 [Information] Language server initialised; waiting for shutdown.
2017-09-20 02:19:40.178 +10:00 [Information] Handle request "{\"jsonrpc\":\"2.0\",\"id\":1,\"method\":\"initialize\",\"params\":{\"processId\":null,\"rootPath\":\"C:/Foo\",\"rootUri\":\"file://C:\\Foo\",\"initializationOptions\":null,\"capabilities\":{\"workspace\":{\"applyEdit\":false,\"workspaceEdit\":false,\"didChangeConfiguration\":false,\"didChangeWatchedFiles\":false,\"symbol\":false,\"executeCommand\":false},\"textDocument\":{\"synchronization\":false,\"completion\":false,\"hover\":false,\"signatureHelp\":false,\"references\":false,\"documentHighlight\":false,\"documentSymbol\":false,\"formatting\":false,\"rangeFormatting\":false,\"onTypeFormatting\":false,\"definition\":false,\"codeAction\":false,\"codeLens\":false,\"documentLink\":false,\"rename\":false},\"experimental\":{}},\"trace\":\"off\"}}"
2017-09-20 02:19:40.228 +10:00 [Information] Schedule "initialize" request 1.
2017-09-20 02:19:40.476 +10:00 [Information] Sending item from output queue...
2017-09-20 02:19:40.530 +10:00 [Information] Sending content "{\"protocolVersion\":\"2.0\",\"id\":1,\"result\":{\"capabilities\":{\"textDocumentSync\":{\"openClose\":false,\"change\":0,\"willSave\":false,\"willSaveWaitUntil\":false,\"save\":{\"includeText\":false}},\"hoverProvider\":false,\"definitionProvider\":false,\"referencesProvider\":false,\"documentHighlightProvider\":false,\"documentSymbolProvider\":false,\"workspaceSymbolProvider\":false,\"codeActionProvider\":false,\"documentFormattingProvider\":false,\"documentRangeFormattingProvider\":false,\"renameProvider\":false,\"experimental\":{}}}}" with headers "Content-Length: 498

" from output queue...
2017-09-20 02:19:40.530 +10:00 [Information] Sent item from output queue (498 bytes).
2017-09-20 02:19:40.643 +10:00 [Information] Handle request "{\"jsonrpc\":\"2.0\",\"id\":2,\"method\":\"dummy\",\"params\":{\"message\":\"Hello, world!\"}}"
2017-09-20 02:19:40.643 +10:00 [Information] Schedule "dummy" request 2.
2017-09-20 02:19:40.652 +10:00 [Information] DummyHandler got request DummyParams { Message: "Hello, world!" }
2017-09-20 02:19:40.653 +10:00 [Information] Sending item from output queue...
2017-09-20 02:19:40.655 +10:00 [Information] Sending content "{\"protocolVersion\":\"2.0\",\"method\":\"dummy/notify\",\"params\":{\"message\":\"Hello, world!\"}}" with headers "Content-Length: 86

" from output queue...
2017-09-20 02:19:40.655 +10:00 [Information] Sent item from output queue (86 bytes).
2017-09-20 02:19:40.655 +10:00 [Information] Sending item from output queue...
2017-09-20 02:19:40.655 +10:00 [Information] Sending content "{\"protocolVersion\":\"2.0\",\"id\":2,\"result\":null}" with headers "Content-Length: 46

" from output queue...
2017-09-20 02:19:40.655 +10:00 [Information] Sent item from output queue (46 bytes).
2017-09-20 02:19:40.752 +10:00 [Information] Handle request "{\"jsonrpc\":\"2.0\",\"id\":null,\"method\":\"shutdown\",\"params\":{}}"
2017-09-20 02:19:40.752 +10:00 [Information] Schedule "shutdown" request null.

[LucasBullen]

From the Server log:

2017-09-19 14:50:54.851 -04:00 [Information] Initialising language server...
2017-09-19 14:50:54.882 -04:00 [Information] Starting language server...
2017-09-19 14:50:54.886 -04:00 [Information] Language server initialised; waiting for shutdown.

To get it working I did have to download JsonRpc.1.0.0.nupkg and Lsp.1.0.0.nupkg and replace the dependencies to 1.0.0 instead of 1.0.1 if you think that is what caused the issue.

[tintoy]

1.0.1 did not work? Or was the package missing?

[tintoy]

Ok, sorry for wasting your time - I'm a moron, the packages were excluded by .gitignore. Give me 5 and I'll add them :)

[tintoy]

Can you pull down the latest source and try again (dotnet restore then dotnet build)?

Should be using 1.0.5 of the JsonRpc and Lsp packages now.

[tintoy]

(have added even more logging)

[LucasBullen]

2017-09-19 15:09:56.186 -04:00 [Information] Initialising language server...
2017-09-19 15:09:56.267 -04:00 [Information] Starting language server...
2017-09-19 15:09:56.268 -04:00 [Information] Opening LSP connection...
2017-09-19 15:09:56.269 -04:00 [Information] Starting input handler...
2017-09-19 15:09:56.269 -04:00 [Information] Starting output handler...
2017-09-19 15:09:56.279 -04:00 [Information] Started output handler.
2017-09-19 15:09:56.289 -04:00 [Verbose] Starting read from input stream...
2017-09-19 15:09:56.299 -04:00 [Information] Started input handler.
2017-09-19 15:09:56.299 -04:00 [Information] LSP connection is open.
2017-09-19 15:09:56.301 -04:00 [Information] Language server initialised; waiting for shutdown.
2017-09-19 15:09:56.359 -04:00 [Verbose] Read 21 bytes from input stream.
2017-09-19 15:09:56.362 -04:00 [Verbose] Reading additional data from input stream...
2017-09-19 15:09:56.362 -04:00 [Verbose] Read 1 bytes of additional data from input stream.
2017-09-19 15:09:56.363 -04:00 [Verbose] Reading additional data from input stream...
2017-09-19 15:09:56.363 -04:00 [Verbose] Read 1 bytes of additional data from input stream.
2017-09-19 15:09:56.363 -04:00 [Verbose] Got raw headers: "Content-Length: 674

"
2017-09-19 15:09:56.364 -04:00 [Verbose] Parsed headers (ContentLength = 674).
2017-09-19 15:09:56.365 -04:00 [Verbose] Reading incoming request body (674 bytes expected)...
2017-09-19 15:09:56.365 -04:00 [Verbose] Reading segment of incoming request body (0 of 674 bytes so far)...
2017-09-19 15:09:56.366 -04:00 [Verbose] Read segment of incoming request body (0 of 674 bytes so far).
2017-09-19 15:09:56.366 -04:00 [Verbose] Received entire payload (674 bytes).
2017-09-19 15:09:56.367 -04:00 [Verbose] Read incoming request body (674 bytes, total): "{\"jsonrpc\":\"2.0\",\"id\":\"1\",\"method\":\"initialize\",\"params\":{\"rootPath\":\"/home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1\",\"rootUri\":\"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/\",\"capabilities\":{\"workspace\":{\"applyEdit\":true,\"symbol\":{},\"executeCommand\":{}},\"textDocument\":{\"synchronization\":{\"willSave\":true,\"willSaveWaitUntil\":true,\"didSave\":true},\"completion\":{\"completionItem\":{\"snippetSupport\":true}},\"hover\":{},\"signatureHelp\":{},\"references\":{},\"documentHighlight\":{},\"documentSymbol\":{},\"formatting\":{},\"rangeFormatting\":{},\"definition\":{},\"codeAction\":{},\"codeLens\":{},\"documentLink\":{},\"rename\":{}}},\"clientName\":\"Eclipse SDK\"}}".
2017-09-19 15:09:56.376 -04:00 [Information] Handle request "{\"jsonrpc\":\"2.0\",\"id\":\"1\",\"method\":\"initialize\",\"params\":{\"rootPath\":\"/home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1\",\"rootUri\":\"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/\",\"capabilities\":{\"workspace\":{\"applyEdit\":true,\"symbol\":{},\"executeCommand\":{}},\"textDocument\":{\"synchronization\":{\"willSave\":true,\"willSaveWaitUntil\":true,\"didSave\":true},\"completion\":{\"completionItem\":{\"snippetSupport\":true}},\"hover\":{},\"signatureHelp\":{},\"references\":{},\"documentHighlight\":{},\"documentSymbol\":{},\"formatting\":{},\"rangeFormatting\":{},\"definition\":{},\"codeAction\":{},\"codeLens\":{},\"documentLink\":{},\"rename\":{}}},\"clientName\":\"Eclipse SDK\"}}"
2017-09-19 15:09:56.472 -04:00 [Verbose] GetRenor: Identify JSON "{
  \"jsonrpc\": \"2.0\",
  \"id\": \"1\",
  \"method\": \"initialize\",
  \"params\": {
    \"rootPath\": \"/home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1\",
    \"rootUri\": \"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/\",
    \"capabilities\": {
      \"workspace\": {
        \"applyEdit\": true,
        \"symbol\": {},
        \"executeCommand\": {}
      },
      \"textDocument\": {
        \"synchronization\": {
          \"willSave\": true,
          \"willSaveWaitUntil\": true,
          \"didSave\": true
        },
        \"completion\": {
          \"completionItem\": {
            \"snippetSupport\": true
          }
        },
        \"hover\": {},
        \"signatureHelp\": {},
        \"references\": {},
        \"documentHighlight\": {},
        \"documentSymbol\": {},
        \"formatting\": {},
        \"rangeFormatting\": {},
        \"definition\": {},
        \"codeAction\": {},
        \"codeLens\": {},
        \"documentLink\": {},
        \"rename\": {}
      }
    },
    \"clientName\": \"Eclipse SDK\"
  }
}"
2017-09-19 15:09:56.476 -04:00 [Verbose] GetRenor: RequestId="1" (HasRequestId=True).
2017-09-19 15:09:56.477 -04:00 [Verbose] GetRenor: JSON represents a request (RequestId="1", Params="{
  \"rootPath\": \"/home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1\",
  \"rootUri\": \"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/\",
  \"capabilities\": {
    \"workspace\": {
      \"applyEdit\": true,
      \"symbol\": {},
      \"executeCommand\": {}
    },
    \"textDocument\": {
      \"synchronization\": {
        \"willSave\": true,
        \"willSaveWaitUntil\": true,
        \"didSave\": true
      },
      \"completion\": {
        \"completionItem\": {
          \"snippetSupport\": true
        }
      },
      \"hover\": {},
      \"signatureHelp\": {},
      \"references\": {},
      \"documentHighlight\": {},
      \"documentSymbol\": {},
      \"formatting\": {},
      \"rangeFormatting\": {},
      \"definition\": {},
      \"codeAction\": {},
      \"codeLens\": {},
      \"documentLink\": {},
      \"rename\": {}
    }
  },
  \"clientName\": \"Eclipse SDK\"
}").
2017-09-19 15:09:56.483 -04:00 [Information] Schedule "initialize" request "1".
2017-09-19 15:09:56.486 -04:00 [Verbose] Starting read from input stream...
2017-09-19 15:09:56.673 -04:00 [Information] ConfigurationHandler recieved capability: null
2017-09-19 15:09:56.679 -04:00 [Information] Sending item from output queue...
2017-09-19 15:09:56.721 -04:00 [Information] Sending content "{\"protocolVersion\":\"2.0\",\"id\":\"1\",\"result\":{\"capabilities\":{\"textDocumentSync\":{\"openClose\":false,\"change\":0,\"willSave\":false,\"willSaveWaitUntil\":false,\"save\":{\"includeText\":false}},\"hoverProvider\":false,\"definitionProvider\":false,\"referencesProvider\":false,\"documentHighlightProvider\":false,\"documentSymbolProvider\":false,\"workspaceSymbolProvider\":false,\"codeActionProvider\":false,\"documentFormattingProvider\":false,\"documentRangeFormattingProvider\":false,\"renameProvider\":false,\"experimental\":{}}}}" with headers "Content-Length: 500

" from output queue...
2017-09-19 15:09:56.721 -04:00 [Verbose] Writing 523 bytes to output stream...
2017-09-19 15:09:56.721 -04:00 [Verbose] Wrote 523 bytes to output stream.
2017-09-19 15:09:56.721 -04:00 [Information] Sent item from output queue (500 bytes).
2017-09-19 15:09:56.739 -04:00 [Verbose] Read 21 bytes from input stream.
2017-09-19 15:09:56.739 -04:00 [Verbose] Reading additional data from input stream...
2017-09-19 15:09:56.739 -04:00 [Verbose] Read 1 bytes of additional data from input stream.
2017-09-19 15:09:56.739 -04:00 [Verbose] Reading additional data from input stream...
2017-09-19 15:09:56.739 -04:00 [Verbose] Read 1 bytes of additional data from input stream.
2017-09-19 15:09:56.739 -04:00 [Verbose] Got raw headers: "Content-Length: 728

"
2017-09-19 15:09:56.739 -04:00 [Verbose] Parsed headers (ContentLength = 728).
2017-09-19 15:09:56.739 -04:00 [Verbose] Reading incoming request body (728 bytes expected)...
2017-09-19 15:09:56.739 -04:00 [Verbose] Reading segment of incoming request body (0 of 728 bytes so far)...
2017-09-19 15:09:56.739 -04:00 [Verbose] Read segment of incoming request body (0 of 728 bytes so far).
2017-09-19 15:09:56.739 -04:00 [Verbose] Received entire payload (728 bytes).
2017-09-19 15:09:56.739 -04:00 [Verbose] Read incoming request body (728 bytes, total): "{\"jsonrpc\":\"2.0\",\"method\":\"textDocument/didOpen\",\"params\":{\"textDocument\":{\"uri\":\"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/NewDotnetProject1.csproj\",\"languageId\":\"csproj\",\"version\":1,\"text\":\"\u003cProject Sdk\u003d\\"Microsoft.NET.Sdk.Web\\"\u003e\r\n\r\n  \u003cPropertyGroup\u003e\r\n    \u003cTargetFramework\u003enetcoreapp2.0\u003c/TargetFramework\u003e\r\n  \u003c/PropertyGroup\u003e\r\n\r\n  \u003cItemGroup\u003e\r\n    \u003cFolder Include\u003d\\"wwwroot\\\\" /\u003e\r\n  \u003c/ItemGroup\u003e\r\n\r\n  \u003cItemGroup\u003e\r\n    \u003cPackageReference Include\u003d\\"Microsoft.AspNetCore.All\\" Version\u003d\\"2.0.0\\" /\u003e\r\n  \u003c/ItemGroup\u003e\r\n\r\n\u003c/Project\u003e\r\n\"}}}".
2017-09-19 15:09:56.739 -04:00 [Information] Handle request "{\"jsonrpc\":\"2.0\",\"method\":\"textDocument/didOpen\",\"params\":{\"textDocument\":{\"uri\":\"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/NewDotnetProject1.csproj\",\"languageId\":\"csproj\",\"version\":1,\"text\":\"\u003cProject Sdk\u003d\\"Microsoft.NET.Sdk.Web\\"\u003e\r\n\r\n  \u003cPropertyGroup\u003e\r\n    \u003cTargetFramework\u003enetcoreapp2.0\u003c/TargetFramework\u003e\r\n  \u003c/PropertyGroup\u003e\r\n\r\n  \u003cItemGroup\u003e\r\n    \u003cFolder Include\u003d\\"wwwroot\\\\" /\u003e\r\n  \u003c/ItemGroup\u003e\r\n\r\n  \u003cItemGroup\u003e\r\n    \u003cPackageReference Include\u003d\\"Microsoft.AspNetCore.All\\" Version\u003d\\"2.0.0\\" /\u003e\r\n  \u003c/ItemGroup\u003e\r\n\r\n\u003c/Project\u003e\r\n\"}}}"
2017-09-19 15:09:56.745 -04:00 [Verbose] GetRenor: Identify JSON "{
  \"jsonrpc\": \"2.0\",
  \"method\": \"textDocument/didOpen\",
  \"params\": {
    \"textDocument\": {
      \"uri\": \"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/NewDotnetProject1.csproj\",
      \"languageId\": \"csproj\",
      \"version\": 1,
      \"text\": \"<Project Sdk=\\"Microsoft.NET.Sdk.Web\\">\r\n\r\n  <PropertyGroup>\r\n    <TargetFramework>netcoreapp2.0</TargetFramework>\r\n  </PropertyGroup>\r\n\r\n  <ItemGroup>\r\n    <Folder Include=\\"wwwroot\\\\" />\r\n  </ItemGroup>\r\n\r\n  <ItemGroup>\r\n    <PackageReference Include=\\"Microsoft.AspNetCore.All\\" Version=\\"2.0.0\\" />\r\n  </ItemGroup>\r\n\r\n</Project>\r\n\"
    }
  }
}"
2017-09-19 15:09:56.746 -04:00 [Verbose] GetRenor: RequestId=null (HasRequestId=False).
2017-09-19 15:09:56.746 -04:00 [Verbose] GetRenor: JSON represents a notification (Params="{
  \"textDocument\": {
    \"uri\": \"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/NewDotnetProject1.csproj\",
    \"languageId\": \"csproj\",
    \"version\": 1,
    \"text\": \"<Project Sdk=\\"Microsoft.NET.Sdk.Web\\">\r\n\r\n  <PropertyGroup>\r\n    <TargetFramework>netcoreapp2.0</TargetFramework>\r\n  </PropertyGroup>\r\n\r\n  <ItemGroup>\r\n    <Folder Include=\\"wwwroot\\\\" />\r\n  </ItemGroup>\r\n\r\n  <ItemGroup>\r\n    <PackageReference Include=\\"Microsoft.AspNetCore.All\\" Version=\\"2.0.0\\" />\r\n  </ItemGroup>\r\n\r\n</Project>\r\n\"
  }
}").
2017-09-19 15:09:56.746 -04:00 [Information] Schedule "textDocument/didOpen" notification.
2017-09-19 15:09:56.747 -04:00 [Verbose] Starting read from input stream...
2017-09-19 15:11:37.292 -04:00 [Verbose] Read 21 bytes from input stream.
2017-09-19 15:11:37.293 -04:00 [Verbose] Reading additional data from input stream...
2017-09-19 15:11:37.293 -04:00 [Verbose] Read 1 bytes of additional data from input stream.
2017-09-19 15:11:37.293 -04:00 [Verbose] Reading additional data from input stream...
2017-09-19 15:11:37.293 -04:00 [Verbose] Read 1 bytes of additional data from input stream.
2017-09-19 15:11:37.293 -04:00 [Verbose] Got raw headers: "Content-Length: 180

"
2017-09-19 15:11:37.293 -04:00 [Verbose] Parsed headers (ContentLength = 180).
2017-09-19 15:11:37.293 -04:00 [Verbose] Reading incoming request body (180 bytes expected)...
2017-09-19 15:11:37.293 -04:00 [Verbose] Reading segment of incoming request body (0 of 180 bytes so far)...
2017-09-19 15:11:37.293 -04:00 [Verbose] Read segment of incoming request body (0 of 180 bytes so far).
2017-09-19 15:11:37.293 -04:00 [Verbose] Received entire payload (180 bytes).
2017-09-19 15:11:37.293 -04:00 [Verbose] Read incoming request body (180 bytes, total): "{\"jsonrpc\":\"2.0\",\"method\":\"textDocument/didClose\",\"params\":{\"textDocument\":{\"uri\":\"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/NewDotnetProject1.csproj\"}}}".
2017-09-19 15:11:37.293 -04:00 [Information] Handle request "{\"jsonrpc\":\"2.0\",\"method\":\"textDocument/didClose\",\"params\":{\"textDocument\":{\"uri\":\"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/NewDotnetProject1.csproj\"}}}"
2017-09-19 15:11:37.293 -04:00 [Verbose] GetRenor: Identify JSON "{
  \"jsonrpc\": \"2.0\",
  \"method\": \"textDocument/didClose\",
  \"params\": {
    \"textDocument\": {
      \"uri\": \"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/NewDotnetProject1.csproj\"
    }
  }
}"
2017-09-19 15:11:37.293 -04:00 [Verbose] GetRenor: RequestId=null (HasRequestId=False).
2017-09-19 15:11:37.293 -04:00 [Verbose] GetRenor: JSON represents a notification (Params="{
  \"textDocument\": {
    \"uri\": \"file:///home/lbullen/runtime-EclipseApplication(1)/NewDotnetProject1/NewDotnetProject1.csproj\"
  }
}").
2017-09-19 15:11:37.293 -04:00 [Information] Schedule "textDocument/didClose" notification.
2017-09-19 15:11:37.293 -04:00 [Verbose] Starting read from input stream...
2017-09-19 15:11:37.293 -04:00 [Verbose] Read 21 bytes from input stream.
2017-09-19 15:11:37.293 -04:00 [Verbose] Reading additional data from input stream...
2017-09-19 15:11:37.293 -04:00 [Verbose] Read 1 bytes of additional data from input stream.
2017-09-19 15:11:37.293 -04:00 [Verbose] Got raw headers: "Content-Length: 46

"
2017-09-19 15:11:37.293 -04:00 [Verbose] Parsed headers (ContentLength = 46).
2017-09-19 15:11:37.294 -04:00 [Verbose] Reading incoming request body (46 bytes expected)...
2017-09-19 15:11:37.294 -04:00 [Verbose] Reading segment of incoming request body (0 of 46 bytes so far)...
2017-09-19 15:11:37.294 -04:00 [Verbose] Read segment of incoming request body (0 of 46 bytes so far).
2017-09-19 15:11:37.294 -04:00 [Verbose] Received entire payload (46 bytes).
2017-09-19 15:11:37.294 -04:00 [Verbose] Read incoming request body (46 bytes, total): "{\"jsonrpc\":\"2.0\",\"id\":\"2\",\"method\":\"shutdown\"}".
2017-09-19 15:11:37.294 -04:00 [Information] Handle request "{\"jsonrpc\":\"2.0\",\"id\":\"2\",\"method\":\"shutdown\"}"
2017-09-19 15:11:37.294 -04:00 [Verbose] GetRenor: Identify JSON "{
  \"jsonrpc\": \"2.0\",
  \"id\": \"2\",
  \"method\": \"shutdown\"
}"
2017-09-19 15:11:37.294 -04:00 [Verbose] GetRenor: RequestId="2" (HasRequestId=True).

[tintoy]

Good, so it looks like the server's getting useful info there.

Would you mind using those package versions in the MSBuild language server to see if it's behaving the same way? Should at least show what it's receiving and maybe that will indicate where the problem lies. I can create a branch for you and reference the packages myself if it'd be a hassle :)

[LucasBullen]

I'll give it a try with the 1.0.5 packages

[LucasBullen]

Unfortunately not much change:

2017-09-19 15:46:46.923 -04:00 [Verbose/] Logger initialised.
2017-09-19 15:46:47.985 -04:00 [Verbose/] Logger initialised.
2017-09-19 15:46:49.030 -04:00 [Verbose/] Logger initialised.
2017-09-19 15:46:50.075 -04:00 [Verbose/] Logger initialised.

[tintoy]

Is that the latest source for the msbuild language service? I have a feeling I took that message out at some stage...

[tintoy]

Thanks for sticking with this BTW!

[tintoy]

Message still in there but code was changed :)

https://github.com/tintoy/msbuild-project-tools-vscode/commit/c7f3dd4b9f0df44d2c54cb22da4eafb4d573a09b

[LucasBullen]

I unpack https://github.com/tintoy/msbuild-project-tools-vscode/archive/master.zip so I'd believe so

[LucasBullen]

Sorry to waste your time there, was incorrect. Changing the packages did result in useful output: http://www.heypasteit.com/clip/0IITET

[tintoy]

Ah! Good - now we're making progress :-D

Ok, so are you actually passing a value for client capabilities? If so, perhaps it's a serialisation problem...

[tintoy]

One thing I've noticed in the LSP server implementation is a bug where any operation that throws an exception will break the dispatch loop so all further messages are silently ignored. I'll raise an issue in the upstream repository so they can deal with that.

[tintoy]

BTW, if you unzip these symbols into the directory where the MSBuild language service assembly lives, we can get line info for those exceptions:

Symbols.zip

[tintoy]

Ok, looking through the code, I think my language service is being too unforgiving about missing capabilities (null means capability not available, which I didn't expect, but is valid according to the protocol docs). Give me 5 mins and I can get a new build out.

[tintoy]

Ready to go - can you pull down the latest source, re-run dotnet publish and then try again?

[LucasBullen]

Whoot!!!

[tintoy]

I'm waiting for the new colouriser API for LSP to stabilise and then I can give you syntax highlighting too :)

[tintoy]

BTW are the line and column positions you're passing 0-based or 1-based? It looks like it thinks it's outside the quotes based on the completions but the cursor appears to be inside them.

[tintoy]

(for LSP, line and column are 0-based)

[LucasBullen]

0-based: {"line":11,"character":31} When I go outside the quotes it only shows Condition, Exclude, and Update