Corrupted output from code formatting #793

timmclean · 2022-02-20T20:01:06Z

Server Version

$ terraform-ls --version
0.25.2

Terraform Version

$ terraform --version
Terraform v1.1.6
on linux_amd64

Client Version

$ nvim --version
NVIM v0.6.1
Build type: Release
LuaJIT 2.1.0-beta3
Compiled by team+vim@tracker.debian.org

Terraform Configuration Files

testcase.tf

resource "aws_lambda_function" "f" {
    environment {
        variables = {
            a = "b"
        }
    }
}

Log Output

Log file

2022/02/20 14:24:58 serve_command.go:162: Starting terraform-ls 0.25.2
2022/02/20 14:24:58 service.go:90: Preparing new session ...
2022/02/20 14:24:58 langserver.go:94: Starting server (pid 53; concurrency: 4) ...
2022/02/20 14:24:58 opts.go:254: Received request batch of size 1 (qlen=0)
2022/02/20 14:24:58 opts.go:254: Dequeued request batch of length 1 (qlen=0)
2022/02/20 14:24:58 rpc_logger.go:29: Incoming request for "initialize" (ID 1): {"trace":"off","workspaceFolders":[{"uri":"file:\/\/\/d\/testcase","name":"\/d\/testcase"}],"capabilities":{"window":{"workDoneProgress":true,"showDocument":{"support":false},"showMessage":{"messageActionItem":{"additionalPropertiesSupport":false}}},"callHierarchy":{"dynamicRegistration":false},"textDocument":{"references":{"dynamicRegistration":false},"publishDiagnostics":{"relatedInformation":true,"tagSupport":{"valueSet":[1,2]}},"typeDefinition":{"linkSupport":true},"rename":{"dynamicRegistration":false,"prepareSupport":true},"declaration":{"linkSupport":true},"codeAction":{"dataSupport":true,"resolveSupport":{"properties":["edit"]},"dynamicRegistration":false,"codeActionLiteralSupport":{"codeActionKind":{"valueSet":["","Empty","QuickFix","Refactor","RefactorExtract","RefactorInline","RefactorRewrite","Source","SourceOrganizeImports","quickfix","refactor","refactor.extract","refactor.inline","refactor.rewrite","source","source.organizeImports"]}}},"completion":{"contextSupport":false,"completionItem":{"insertReplaceSupport":true,"deprecatedSupport":true,"resolveSupport":{"properties":["documentation","detail","additionalTextEdits"]},"commitCharactersSupport":true,"tagSupport":{"valueSet":[1]},"labelDetailsSupport":true,"preselectSupport":true,"snippetSupport":true,"documentationFormat":["markdown","plaintext"]},"dynamicRegistration":false,"completionItemKind":{"valueSet":[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25]}},"signatureHelp":{"dynamicRegistration":false,"signatureInformation":{"parameterInformation":{"labelOffsetSupport":true},"activeParameterSupport":true,"documentationFormat":["markdown","plaintext"]}},"documentHighlight":{"dynamicRegistration":false},"definition":{"linkSupport":true},"documentSymbol":{"hierarchicalDocumentSymbolSupport":true,"dynamicRegistration":false,"symbolKind":{"valueSet":[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26]}},"hover":{"dynamicRegistration":false,"contentFormat":["markdown","plaintext"]},"implementation":{"linkSupport":true},"synchronization":{"didSave":true,"willSave":false,"dynamicRegistration":false,"willSaveWaitUntil":false}},"workspace":{"workspaceFolders":true,"symbol":{"hierarchicalWorkspaceSymbolSupport":true,"dynamicRegistration":false,"symbolKind":{"valueSet":[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26]}},"workspaceEdit":{"resourceOperations":["rename","create","delete"]},"applyEdit":true,"configuration":true}},"processId":51,"initializationOptions":{},"rootUri":"file:\/\/\/d\/testcase","clientInfo":{"name":"Neovim","version":"0.6.1"},"rootPath":"\/d\/testcase"}
2022/02/20 14:25:01 watcher.go:283: watching for changes ...
2022/02/20 14:25:01 walker.go:191: asynchronously walking through /d/testcase
2022/02/20 14:25:01 walker.go:240: skipping /d/testcase/.git
2022/02/20 14:25:01 rpc_logger.go:50: Response to "initialize" (ID 1): {"capabilities":{"textDocumentSync":{"openClose":true,"change":2,"save":{}},"completionProvider":{"triggerCharacters":[".","["],"completionItem":{}},"hoverProvider":true,"signatureHelpProvider":{},"declarationProvider":{},"definitionProvider":true,"referencesProvider":true,"documentSymbolProvider":true,"codeActionProvider":{"codeActionKinds":["source.formatAll.terraform"]},"codeLensProvider":{},"documentLinkProvider":{},"workspaceSymbolProvider":true,"documentFormattingProvider":true,"documentOnTypeFormattingProvider":{"firstTriggerCharacter":""},"executeCommandProvider":{"commands":["terraform-ls.module.callers","terraform-ls.module.calls","terraform-ls.module.providers","terraform-ls.rootmodules","terraform-ls.terraform.init","terraform-ls.terraform.validate"],"workDoneProgress":true},"semanticTokensProvider":{"legend":{"tokenTypes":[],"tokenModifiers":[]},"full":false},"workspace":{"workspaceFolders":{"supported":true,"changeNotifications":"workspace/didChangeWorkspaceFolders"}}},"serverInfo":{"name":"terraform-ls","version":"0.25.2"}}
2022/02/20 14:25:01 opts.go:254: Completed 1 requests [2.995581692s elapsed]
2022/02/20 14:25:01 walker.go:321: walking of /d/testcase finished
2022/02/20 14:25:01 walker.go:197: async walking through /d/testcase finished
2022/02/20 14:25:01 opts.go:254: Received request batch of size 1 (qlen=0)
2022/02/20 14:25:01 opts.go:254: Dequeued request batch of length 1 (qlen=0)
2022/02/20 14:25:01 rpc_logger.go:29: Incoming notification for "initialized": {}
2022/02/20 14:25:01 opts.go:254: Received request batch of size 1 (qlen=0)
2022/02/20 14:25:01 opts.go:254: Dequeued request batch of length 1 (qlen=0)
2022/02/20 14:25:01 rpc_logger.go:29: Incoming notification for "textDocument/didOpen": {"textDocument":{"uri":"file:\/\/\/d\/testcase\/testcase.tf","languageId":"terraform","version":0,"text":"resource \"aws_lambda_function\" \"f\" {\n    environment {\n        variables = {\n            a = \"b\"\n        }\n    }\n}\n"}}
2022/02/20 14:25:01 module_manager.go:66: MM: adding new module: /d/testcase
2022/02/20 14:25:01 did_open.go:44: opened module: /d/testcase
2022/02/20 14:25:01 module_loader.go:185: ML: enqueing "OpTypeParseModuleConfiguration" module operation: "/d/testcase"
2022/02/20 14:25:01 module_loader.go:185: ML: enqueing "OpTypeParseVariables" module operation: "/d/testcase"
2022/02/20 14:25:01 module_loader.go:185: ML: enqueing "OpTypeLoadModuleMetadata" module operation: "/d/testcase"
2022/02/20 14:25:01 module_loader.go:120: ML: executing "OpTypeParseModuleConfiguration" for "/d/testcase"
2022/02/20 14:25:01 module_loader.go:120: ML: executing "OpTypeParseVariables" for "/d/testcase"
2022/02/20 14:25:01 module_loader.go:185: ML: enqueing "OpTypeDecodeReferenceTargets" module operation: "/d/testcase"
2022/02/20 14:25:01 opts.go:254: Received request batch of size 1 (qlen=0)
2022/02/20 14:25:01 module_loader.go:185: ML: enqueing "OpTypeDecodeReferenceOrigins" module operation: "/d/testcase"
2022/02/20 14:25:01 module_loader.go:172: ML: finished "OpTypeParseVariables" for "/d/testcase"
2022/02/20 14:25:01 opts.go:254: Dequeued request batch of length 1 (qlen=0)
2022/02/20 14:25:01 opts.go:254: Request check error for "rust-analyzer/inlayHints" (params "{\"textDocument\":{\"uri\":\"file:\\/\\/\\/d\\/testcase\\/testcase.tf\"}}"): [-32601] no such method "rust-analyzer/inlayHints"
2022/02/20 14:25:01 module_loader.go:185: ML: enqueing "OpTypeGetTerraformVersion" module operation: "/d/testcase"
2022/02/20 14:25:01 module_loader.go:172: ML: finished "OpTypeParseModuleConfiguration" for "/d/testcase"
2022/02/20 14:25:01 watcher.go:75: adding module for watching: /d/testcase
2022/02/20 14:25:01 module_loader.go:120: ML: executing "OpTypeDecodeReferenceTargets" for "/d/testcase"
2022/02/20 14:25:01 rpc_logger.go:45: Error for "rust-analyzer/inlayHints" (ID 2): [-32601] no such method "rust-analyzer/inlayHints"
2022/02/20 14:25:01 opts.go:254: Completed 1 requests [101.02193ms elapsed]
2022/02/20 14:25:01 module_loader.go:120: ML: executing "OpTypeDecodeReferenceOrigins" for "/d/testcase"
2022/02/20 14:25:01 module_loader.go:172: ML: finished "OpTypeDecodeReferenceTargets" for "/d/testcase"
2022/02/20 14:25:01 module_loader.go:172: ML: finished "OpTypeDecodeReferenceOrigins" for "/d/testcase"
2022/02/20 14:25:01 module_loader.go:120: ML: executing "OpTypeLoadModuleMetadata" for "/d/testcase"
2022/02/20 14:25:01 module_loader.go:120: ML: executing "OpTypeGetTerraformVersion" for "/d/testcase"
2022/02/20 14:25:01 module_loader.go:172: ML: finished "OpTypeLoadModuleMetadata" for "/d/testcase"
2022/02/20 14:25:01 module_loader.go:172: ML: finished "OpTypeGetTerraformVersion" for "/d/testcase"
2022/02/20 14:25:10 opts.go:254: Received request batch of size 1 (qlen=0)
2022/02/20 14:25:10 opts.go:254: Dequeued request batch of length 1 (qlen=0)
2022/02/20 14:25:10 rpc_logger.go:29: Incoming request for "textDocument/formatting" (ID 3): {"options":{"tabSize":8,"insertSpaces":false},"textDocument":{"uri":"file:\/\/\/d\/testcase\/testcase.tf"}}
2022/02/20 14:25:10 formatting.go:41: formatting document via "/usr/bin/terraform"
2022/02/20 14:25:10 rpc_logger.go:50: Response to "textDocument/formatting" (ID 3): [{"range":{"start":{"line":1,"character":0},"end":{"line":5,"character":0}},"newText":"  environment {\n    variables = {\n      a = \"b\"\n"},{"range":{"start":{"line":6,"character":0},"end":{"line":7,"character":0}},"newText":"  }\n"}]
2022/02/20 14:25:10 opts.go:254: Completed 1 requests [47.253852ms elapsed]
2022/02/20 14:25:10 opts.go:254: Received request batch of size 1 (qlen=0)
2022/02/20 14:25:10 opts.go:254: Dequeued request batch of length 1 (qlen=0)
2022/02/20 14:25:10 rpc_logger.go:29: Incoming notification for "textDocument/didChange": {"contentChanges":[{"rangeLength":1,"range":{"start":{"line":6,"character":0},"end":{"line":6,"character":1}},"text":"  }\n"},{"rangeLength":73,"range":{"start":{"line":1,"character":2},"end":{"line":5,"character":5}},"text":"environment {\n    variables = {\n      a = \"b\"\n    }"},{"rangeLength":1,"range":{"start":{"line":6,"character":0},"end":{"line":7,"character":0}},"text":""}],"textDocument":{"uri":"file:\/\/\/d\/testcase\/testcase.tf","version":6}}
2022/02/20 14:25:10 module_loader.go:185: ML: enqueing "OpTypeParseModuleConfiguration" module operation: "/d/testcase"
2022/02/20 14:25:10 module_loader.go:185: ML: enqueing "OpTypeParseVariables" module operation: "/d/testcase"
2022/02/20 14:25:10 module_loader.go:185: ML: enqueing "OpTypeLoadModuleMetadata" module operation: "/d/testcase"
2022/02/20 14:25:10 module_loader.go:120: ML: executing "OpTypeParseModuleConfiguration" for "/d/testcase"
2022/02/20 14:25:10 module_loader.go:185: ML: enqueing "OpTypeDecodeReferenceTargets" module operation: "/d/testcase"
2022/02/20 14:25:10 module_loader.go:185: ML: enqueing "OpTypeDecodeReferenceOrigins" module operation: "/d/testcase"
2022/02/20 14:25:10 module_loader.go:120: ML: executing "OpTypeParseVariables" for "/d/testcase"
2022/02/20 14:25:10 module_loader.go:172: ML: finished "OpTypeParseModuleConfiguration" for "/d/testcase"
2022/02/20 14:25:10 module_loader.go:172: ML: finished "OpTypeParseVariables" for "/d/testcase"
2022/02/20 14:25:10 opts.go:254: Posting server notification "textDocument/publishDiagnostics" {"uri":"file:///d/testcase","diagnostics":[]}
2022/02/20 14:25:10 opts.go:254: Posting server notification "textDocument/publishDiagnostics" {"uri":"file:///d/testcase/testcase.tf","diagnostics":[{"range":{"start":{"line":0,"character":35},"end":{"line":0,"character":36}},"severity":1,"source":"HCL","message":"Unclosed configuration block: There is no closing brace for this block before the end of the file. This may be caused by incorrect brace nesting elsewhere in this file."}]}
2022/02/20 14:25:10 opts.go:254: Posting server notification "textDocument/publishDiagnostics" {"uri":"file:///d/testcase","diagnostics":[]}
2022/02/20 14:25:10 opts.go:254: Posting server notification "textDocument/publishDiagnostics" {"uri":"file:///d/testcase/testcase.tf","diagnostics":[{"range":{"start":{"line":0,"character":35},"end":{"line":0,"character":36}},"severity":1,"source":"HCL","message":"Unclosed configuration block: There is no closing brace for this block before the end of the file. This may be caused by incorrect brace nesting elsewhere in this file."}]}
2022/02/20 14:25:10 module_loader.go:120: ML: executing "OpTypeDecodeReferenceTargets" for "/d/testcase"
2022/02/20 14:25:10 module_loader.go:120: ML: executing "OpTypeDecodeReferenceOrigins" for "/d/testcase"
2022/02/20 14:25:10 provider_schema.go:196: PSS: getting provider schema (/d/testcase, registry.terraform.io/-/aws, )
2022/02/20 14:25:10 provider_schema.go:196: PSS: getting provider schema (/d/testcase, registry.terraform.io/-/aws, )
2022/02/20 14:25:10 module_loader.go:172: ML: finished "OpTypeDecodeReferenceOrigins" for "/d/testcase"
2022/02/20 14:25:10 module_loader.go:172: ML: finished "OpTypeDecodeReferenceTargets" for "/d/testcase"
2022/02/20 14:25:10 module_loader.go:120: ML: executing "OpTypeLoadModuleMetadata" for "/d/testcase"
2022/02/20 14:25:10 module_loader.go:172: ML: finished "OpTypeLoadModuleMetadata" for "/d/testcase"
2022/02/20 14:25:10 opts.go:254: Posting server notification "textDocument/publishDiagnostics" {"uri":"file:///d/testcase/testcase.tf","diagnostics":[{"range":{"start":{"line":0,"character":35},"end":{"line":0,"character":36}},"severity":1,"source":"HCL","message":"Unclosed configuration block: There is no closing brace for this block before the end of the file. This may be caused by incorrect brace nesting elsewhere in this file."}]}
2022/02/20 14:25:10 opts.go:254: Posting server notification "textDocument/publishDiagnostics" {"uri":"file:///d/testcase","diagnostics":[]}
2022/02/20 14:25:12 opts.go:254: Received request batch of size 1 (qlen=0)
2022/02/20 14:25:12 opts.go:254: Dequeued request batch of length 1 (qlen=0)
2022/02/20 14:25:12 rpc_logger.go:29: Incoming request for "shutdown" (ID 4): 
2022/02/20 14:25:12 service.go:513: stopping walker for session ...
2022/02/20 14:25:12 walker.go:103: stopping walker
2022/02/20 14:25:12 service.go:515: walker stopped
2022/02/20 14:25:12 service.go:519: stopping watcher for session ...
2022/02/20 14:25:12 service.go:524: watcher stopped
2022/02/20 14:25:12 service.go:529: cancelling any module loading ...
2022/02/20 14:25:12 service.go:531: module loading cancelled
2022/02/20 14:25:12 module_loader.go:61: Cancelling module loader...
2022/02/20 14:25:12 rpc_logger.go:50: Response to "shutdown" (ID 4): null
2022/02/20 14:25:12 opts.go:254: Completed 1 requests [14.417358ms elapsed]
2022/02/20 14:25:12 opts.go:254: Received request batch of size 1 (qlen=0)
2022/02/20 14:25:12 opts.go:254: Dequeued request batch of length 1 (qlen=0)
2022/02/20 14:25:12 rpc_logger.go:29: Incoming notification for "exit": 
2022/02/20 14:25:12 opts.go:254: Server signaled to stop with err=EOF
2022/02/20 14:25:12 opts.go:254: Error reading from client: EOF
2022/02/20 14:25:12 service.go:504: session stopped unexpectedly (err: <nil>)
2022/02/20 14:25:12 service.go:513: stopping walker for session ...
2022/02/20 14:25:12 service.go:515: walker stopped
2022/02/20 14:25:12 service.go:519: stopping watcher for session ...
2022/02/20 14:25:12 service.go:524: watcher stopped
2022/02/20 14:25:12 service.go:529: cancelling any module loading ...
2022/02/20 14:25:12 service.go:531: module loading cancelled
2022/02/20 14:25:12 langserver.go:107: Stopping server (pid 53) ...
2022/02/20 14:25:12 langserver.go:111: Server (pid 53) stopped.

Expected Behavior

Running the LSP code formatter on the current buffer using :lua vim.lsp.buf.formatting() should not add syntax errors.

Actual Behavior

The code formatter removes a closing brace, causing a syntax error:

resource "aws_lambda_function" "f" {    
  environment {    
    variables = {    
      a = "b"        
    }    
  }

Error text: Unclosed configuration block: There is no closing brace for this block before the end of the file.

Steps to Reproduce

Create testcase.tf as above
Open in nvim 0.6.1 with nvim-lspconfig
Run :lua vim.lsp.buf.formatting()

Additional info

When running terraform fmt on the same file, the output seems to be correct. I couldn't reproduce the problem using terraform fmt.

Here is the JSONRPC response to the formatting request:

{
  "jsonrpc": "2.0",
  "id": 3,
  "result": [
    {
      "range": {
        "start": {
          "line": 1,
          "character": 0
        },
        "end": {
          "line": 5,
          "character": 0
        }
      },
      "newText": "  environment {\n    variables = {\n      a = \"b\"\n"
    },
    {
      "range": {
        "start": {
          "line": 6,
          "character": 0
        },
        "end": {
          "line": 7,
          "character": 0
        }
      },
      "newText": "  }\n"
    }
  ]
}

The text was updated successfully, but these errors were encountered:

danishprakash · 2022-04-10T12:59:15Z

@radeksimko I got some time to look into this a while back and these are the findings:

For starters, we're actually getting the expected response from terraform exec:

terraform-ls/internal/langserver/handlers/formatting.go

Line 32 in f29eb8c

edits, err = formatDocument(ctx, tfExec, doc.Text, dh)

The problem seems to be with how we're converting the diff to changes i.e go-difflib -> document.Changes. We're actually also returning the right response from go-difflib. But the set of changes that we return with respect to the particular erroneous snippet(s) shared by @timmclean is that the first and last line don't actually contain a diff. So although we are not making any changes to the first line, we are actually overwriting the last line with a new addition i.e. the second last closing brace with 1 indent and essentially losing out on the last line.

This is an insertion because, as shown in the image below, we're actually removing the brace in the 5th line and inserting it anew. The brace on the 6th line then automatically falls into its right place. But, again, somehow that insertion overwrites the last not-to-be-touched brace.

Not sure if the above seems relevant but If you think it sounds right, I can dig deeper to find a fix for this. Let me know what you think. Thanks

radeksimko · 2022-04-11T09:17:31Z

@timmclean Thanks for the detailed report. I managed to reproduce it using your example above, in the VS Code extension.

@danishprakash Thanks for the debugging efforts here and sharing your findings. I'd like to get this fixed in the next release which we pre-emptively planned for the upcoming Thursday, so if you have the time to dig deeper in the next few days that would be great! Otherwise I'd likely pick it up on Tuesday or Wednesday.

danishprakash · 2022-04-13T13:48:16Z

Hey @radeksimko, I might not be able to look at it before next weekend, unfortunately.

github-actions · 2022-04-14T16:26:06Z

This functionality has been released in v0.27.0 of the language server.

For further feature requests or bug reports with this functionality, please create a new GitHub issue following the template. Thank you!

timmclean · 2022-04-14T18:23:53Z

Confirmed fixed. Thank you!

github-actions · 2022-05-15T03:22:37Z

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.

radeksimko added bug Something isn't working textDocument/formatting labels Feb 21, 2022

radeksimko added this to the v0.27.0 milestone Apr 11, 2022

radeksimko self-assigned this Apr 13, 2022

radeksimko mentioned this issue Apr 14, 2022

Fix corrupted diffs in formatting responses #876

Merged

radeksimko closed this as completed in #876 Apr 14, 2022

github-actions bot locked as resolved and limited conversation to collaborators May 15, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Corrupted output from code formatting #793

Corrupted output from code formatting #793

timmclean commented Feb 20, 2022

danishprakash commented Apr 10, 2022

radeksimko commented Apr 11, 2022

danishprakash commented Apr 13, 2022

github-actions bot commented Apr 14, 2022

timmclean commented Apr 14, 2022

github-actions bot commented May 15, 2022

Corrupted output from code formatting #793

Corrupted output from code formatting #793

Comments

timmclean commented Feb 20, 2022

Server Version

Terraform Version

Client Version

Terraform Configuration Files

Log Output

Expected Behavior

Actual Behavior

Steps to Reproduce

Additional info

danishprakash commented Apr 10, 2022

radeksimko commented Apr 11, 2022

danishprakash commented Apr 13, 2022

github-actions bot commented Apr 14, 2022

timmclean commented Apr 14, 2022

github-actions bot commented May 15, 2022