Failed to initialize terraform-ls with error : session is not ready to be initalized. State: initialized (confirmed)

[jk563]

Apologies in advance, I'm guessing this is a user error (possibly related to the vim-lsp config or recent breaking changes?) but I'm not quite sure what else to try. This had been working for me but I've tried a few versions of the plugin and the issue persists. Other LSes set up still work, so I'm not sure why this one isn't.

Server Version

0.29.0-dev

Terraform Version

Terraform v1.2.7
on darwin_arm64

Client Version

VIM - Vi IMproved 9.0 (2022 Jun 28, compiled Aug 13 2022 18:35:05)
vim-lsp
silent! let g:plugs['asyncomplete-lsp.vim'].commit = 'f6d6a6354ff279ba707c20292aef0dfaadc436a3'
silent! let g:plugs['asyncomplete.vim'].commit = '9c7651894c2c6d656c0dc71e87cfabbbb71b9c78'
silent! let g:plugs['terraform-ls'].commit = 'f12ab09777ac938d463a7442e03ba1a8a99e45e2'
silent! let g:plugs['vim-go'].commit = '4d6962d8e0792617f87b37b938996f44e2a54645'
silent! let g:plugs['vim-lsp'].commit = '309e9e5c8103bee69eabd152c09eaeec2e0a11f9'
silent! let g:plugs['vim-terraform'].commit = 'f0b17ac9f1bbdf3a29dba8b17ab429b1eed5d443'

vim-lsp config for terraform-ls:

if executable('terraform-ls')
    au User lsp_setup call lsp#register_server({
        \ 'name': 'terraform-ls',
        \ 'cmd': {server_info->['terraform-ls', 'serve', '-log-file=/tmp/terraform-ls.log']},
        \ 'whitelist': ['terraform'],
        \ })
endif

Terraform Configuration Files

Anything

terraform {
  required_providers {
    aws = {
      source  = "hashicorp/aws"
      version = "~> 4.0"
    }
  }
}

provider "aws" {
  region = "eu-west-2"
}

Log Output

On startup we get the first error message:

2022/08/16 21:33:08 rpc_logger.go:45: Error for "initialize" (ID 1): [-32602] invalid parameters: [-32602] invalid parameters

This line ppears after entering and exiting Insert mode:

2022/08/16 21:33:37 rpc_logger.go:45: Error for "initialize" (ID 2): [-32098] session is not ready to be initalized. State: initialized (confirmed)

Full log:

2022/08/16 21:33:08 serve_command.go:101: Starting terraform-ls 0.29.0-dev
2022/08/16 21:33:08 service.go:100: Preparing new session ...
2022/08/16 21:33:08 langserver.go:94: Starting server (pid 52315; concurrency: 4) ...
2022/08/16 21:33:08 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/16 21:33:08 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/16 21:33:08 rpc_logger.go:29: Incoming request for "initialize" (ID 1): {"rootUri":"file:///Users/jamie/bug","capabilities":{"workspace":{"workspaceFolders":false,"configuration":true,"applyEdit":true},"window":{"workDoneProgress":false},"textDocument":{"codeAction":{"isPreferredSupport":true,"disabledSupport":true,"codeActionLiteralSupport":{"codeActionKind":{"valueSet":["","quickfix","refactor","refactor.extract","refactor.inline","refactor.rewrite","source","source.organizeImports"]}},"dynamicRegistration":false},"completion":{"completionItem":{"snippetSupport":false,"resolveSupport":{"properties":["additionalTextEdits"]},"documentationFormat":["markdown","plaintext"]},"dynamicRegistration":false,"completionItemKind":{"valueSet":[10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,1,2,3,4,5,6,7,8,9]}},"formatting":{"dynamicRegistration":false},"codeLens":{"dynamicRegistration":false},"hover":{"dynamicRegistration":false,"contentFormat":["markdown","plaintext"]},"rangeFormatting":{"dynamicRegistration":false},"declaration":{"dynamicRegistration":false,"linkSupport":true},"references":{"dynamicRegistration":false},"typeHierarchy":false,"foldingRange":{"rangeLimit":5000,"dynamicRegistration":false,"lineFoldingOnly":true},"documentSymbol":{"symbolKind":{"valueSet":[10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,1,2,3,4,5,6,7,8,9]},"dynamicRegistration":false,"labelSupport":false,"hierarchicalDocumentSymbolSupport":false},"publishDiagnostics":{"relatedInformation":true},"synchronization":{"dynamicRegistration":false,"willSaveWaitUntil":false,"willSave":false,"didSave":true},"documentHighlight":{"dynamicRegistration":false},"implementation":{"dynamicRegistration":false,"linkSupport":true},"typeDefinition":{"dynamicRegistration":false,"linkSupport":true},"semanticTokens":{"serverCancelSupport":false,"requests":{"full":false,"range":false},"multilineTokenSupport":false,"dynamicRegistration":false,"overlappingTokenSupport":false,"tokenTypes":["type","class","enum","interface","struct","typeParameter","parameter","variable","property","enumMember","event","function","method","macro","keyword","modifier","comment","string","number","regexp","operator"],"tokenModifiers":[],"formats":["relative"]},"definition":{"dynamicRegistration":false,"linkSupport":true}}},"rootPath":"/Users/jamie/bug","clientInfo":{"name":"vim-lsp"},"processId":52314,"trace":"off"}
2022/08/16 21:33:08 rpc_logger.go:45: Error for "initialize" (ID 1): [-32602] invalid parameters: [-32602] invalid parameters
2022/08/16 21:33:08 opts.go:218: Completed 1 requests [502µs elapsed]
2022/08/16 21:33:08 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/16 21:33:08 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/16 21:33:08 rpc_logger.go:29: Incoming notification for "initialized": {}
2022/08/16 21:33:08 initialized.go:24: Client doesn't support dynamic watched files registration, provider and module changes may not be reflected at runtime
2022/08/16 21:33:37 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/16 21:33:37 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/16 21:33:37 rpc_logger.go:29: Incoming request for "initialize" (ID 2): {"rootUri":"file:///Users/jamie/bug","capabilities":{"workspace":{"workspaceFolders":false,"configuration":true,"applyEdit":true},"window":{"workDoneProgress":false},"textDocument":{"codeAction":{"isPreferredSupport":true,"disabledSupport":true,"codeActionLiteralSupport":{"codeActionKind":{"valueSet":["","quickfix","refactor","refactor.extract","refactor.inline","refactor.rewrite","source","source.organizeImports"]}},"dynamicRegistration":false},"completion":{"completionItem":{"snippetSupport":false,"resolveSupport":{"properties":["additionalTextEdits"]},"documentationFormat":["markdown","plaintext"]},"dynamicRegistration":false,"completionItemKind":{"valueSet":[10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,1,2,3,4,5,6,7,8,9]}},"formatting":{"dynamicRegistration":false},"codeLens":{"dynamicRegistration":false},"hover":{"dynamicRegistration":false,"contentFormat":["markdown","plaintext"]},"rangeFormatting":{"dynamicRegistration":false},"declaration":{"dynamicRegistration":false,"linkSupport":true},"references":{"dynamicRegistration":false},"typeHierarchy":false,"foldingRange":{"rangeLimit":5000,"dynamicRegistration":false,"lineFoldingOnly":true},"documentSymbol":{"symbolKind":{"valueSet":[10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,1,2,3,4,5,6,7,8,9]},"dynamicRegistration":false,"labelSupport":false,"hierarchicalDocumentSymbolSupport":false},"publishDiagnostics":{"relatedInformation":true},"synchronization":{"dynamicRegistration":false,"willSaveWaitUntil":false,"willSave":false,"didSave":true},"documentHighlight":{"dynamicRegistration":false},"implementation":{"dynamicRegistration":false,"linkSupport":true},"typeDefinition":{"dynamicRegistration":false,"linkSupport":true},"semanticTokens":{"serverCancelSupport":false,"requests":{"full":false,"range":false},"multilineTokenSupport":false,"dynamicRegistration":false,"overlappingTokenSupport":false,"tokenTypes":["type","class","enum","interface","struct","typeParameter","parameter","variable","property","enumMember","event","function","method","macro","keyword","modifier","comment","string","number","regexp","operator"],"tokenModifiers":[],"formats":["relative"]},"definition":{"dynamicRegistration":false,"linkSupport":true}}},"rootPath":"/Users/jamie/bug","clientInfo":{"name":"vim-lsp"},"processId":52314,"trace":"off"}
2022/08/16 21:33:37 rpc_logger.go:45: Error for "initialize" (ID 2): [-32098] session is not ready to be initalized. State: initialized (confirmed)
2022/08/16 21:33:37 opts.go:218: Completed 1 requests [298.166µs elapsed]
2022/08/16 21:33:37 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/16 21:33:37 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/16 21:33:37 rpc_logger.go:29: Incoming notification for "initialized": {}
2022/08/16 21:33:37 opts.go:218: Discarding error from notification to "initialized": session was already confirmed as initalized at 2022-08-16 21:33:08.129027 +0100 BST m=+0.005257084 via request 
2022/08/16 21:33:45 signal_cancel.go:20: Cancellation signal (terminated) received
2022/08/16 21:33:45 langserver.go:107: Stopping server (pid 52315) ...
2022/08/16 21:33:45 opts.go:218: Server signaled to stop with err=the server has been stopped
2022/08/16 21:33:45 langserver.go:111: Server (pid 52315) stopped.
2022/08/16 21:33:45 opts.go:218: Error reading from client: the server has been stopped

Expected Behavior

I should be able to go to definitions, autocomplete attributes on resources, and generally use terraform-ls

Actual Behavior

It appears that the LS doesn't successfully start.

Steps to Reproduce

• Open a terraform configuration

[radeksimko]

@jk563 It appears that the initialize request is sent twice by the client to the server, according to the log. This would be a violation of the LSP (protocol), although I admit the error message may not be the most helpful.

Were you able to reproduce this reliably?

If so, then unless it's a misconfiguration error (which seems unlikely in this case) I would recommend raising it with the maintainer(s) of that vim client integration.

[jk563]

It'll reliably give that error on every enter->exit of insert mode.

However, even if I don't drop in and out of insert mode, I still get:

Error for "initialize" (ID 1): [-32602] invalid parameters: [-32602] invalid parameters

on startup and I can't do things such as going to a definition of a resource. Not sure if that's likely the same issue or if the multiple initialization attempts are a red herring?

[radeksimko]

Ah, that is something I missed - thank you for pointing it out - there may still be a bug on the server side, then. 🤔
[-32602] invalid parameters is admittedly not a very descriptive error either.

I think we'd need to add some debug log statements around here https://github.com/hashicorp/terraform-ls/blob/main/internal/langserver/handlers/initialize.go to get to the bottom of it.

I will try to reproduce it myself with vim-lsp.

Thanks for the report and patience.

[jk563]

Let me know if I can help further / if you want more details on my setup. Thanks for looking in to this.

[radeksimko]

I managed to reproduce this.

It has to do with the initialize request body, in particular this part of it:

  "typeHierarchy": false,

which the Go JSON decoder attempts to decode into https://github.com/golang/tools/blob/587a15310bddfc939d37cfaa8be8ea4c3808c3f1/internal/lsp/protocol/tsprotocol.go#L5214-L5224

i.e. boolean into struct.

The LSP spec defines typeHierarchy as an object, so I would say this is a bug in vim-lsp's reporting of typeHierarchy as nothing suggests that it's allowed to be a boolean. It's possible that other language servers you use either use some form of weaker JSON decoding, or the client side plugin actually implements the type hierarchy - in which case it doesn't default to false.

The corresponding server capability can be boolean | TypeHierarchyOptions | TypeHierarchyRegistrationOptions but as per log, it never gets to the point of server responding since the server fails to decode the invalid request body, and even if it did, this doesn't matter since it's server's concern to marshal that response into JSON.

I'm assuming the easiest fix would be for vim-lsp to avoid sending the typeHierarchy field entirely or send it as "typeHierarchy": {}, "typeHierachy": { "dynamicRegistration": false } or something along these lines.

For context, this was essentially triggered by #947 which added the corresponding capability representation. vim-lsp seemed to have supported this capability for some time now, according to git log pointing to prabirshrestha/vim-lsp#641

[radeksimko]

I have proposed the mentioned fix upstream in prabirshrestha/vim-lsp#1350

[radeksimko]

I would also say that vim-lsp probably shouldn't be attempting to resend initialize request when the server responds -32602 (InvalidParams) error code as it's highly unlikely that the server would just respond successfully on any following attempt, but I don't have the capacity to propose a fix for that myself.

[jk563]

Thanks for the effort of replicating, figuring this out, writing it up in great detail, and proposing the upstream fix. Really appreciate this.

Thank you.

[radeksimko]

I have filed prabirshrestha/vim-lsp#1351 upstream to capture the retry problem.
The latest revision of vim-lsp should now send correct initialize request. Let us know if you are still experiencing issue after upgrading.

Thanks for the report.

[jk563]

After a moment of disappointment before realising I'd pinned the vim-lsp version, I unpinned, upgraded, and it now works again in all it's glory.

Thanks again for resolving this, and for the speed of resolution.

[github-actions]

I'm going to lock this issue because it has been closed for 30 days ⏳. This helps our maintainers find and focus on the active issues.
If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.