search

hashicorp / terraform-ls

Terraform Language Server
Mozilla Public License 2.0
997 stars 132 forks source link

OpTypeGetModuleDataFromRegistry Client.Timeout exceeded while awaiting headers #1050

Closed tpolekhin closed 2 years ago

tpolekhin commented 2 years ago

Server Version

0.29.1
platform: darwin/amd64
go: go1.17.13
compiler: gc

Terraform Version

Terraform v1.2.8
on darwin_amd64

Client Version

VSCode Hashicorp Terraform v2.24.1

Log Output

2022/08/26 13:24:26 jobs.go:90: JOBS: Enqueueing new job "9963": "OpTypeGetModuleDataFromRegistry" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: false)
2022/08/26 13:24:26 jobs.go:265: JOBS: Dispatching next job "9963" (scheduler prio: -1, job prio: -1, isDirOpen: true): "OpTypeGetModuleDataFromRegistry" for {"file:///Users/user/tf-test"}
2022/08/26 13:24:31 jobs.go:380: JOBS: Finishing job "9963": "OpTypeGetModuleDataFromRegistry" for {"file:///Users/user/tf-test"} (err = 1 error occurred:
    * Get "https://registry.terraform.io/v1/modules/terraform-google-modules/iam/google/versions": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

, deferredJobs: [])

Expected Behavior

VSCode should format terraform file on save and do it instantly

Actual Behavior

After I've upgraded my Mac to macOS Monterey a week ago I started noticing that VSCode is really slow on save when working with terraform code. I have found a couple of threads discussing the issues with tfenv which I don't use. What I did:

Nothing from the above solved the issue I started looking at the output of the plugin and saw this timeout error while getting module versions I can open this url in my browser successfully and instantly so it's not the network issue (I guess?)

dbanck commented 2 years ago

Thank you for taking the time to report this issue and providing detailed steps of what you have already tried!

I'd like to see how you configured the formatting of TF files; can you share your VS Code configuration?

Furthermore, can you share more language server logs? I'm particularly interested in the parts before and after you hit Cmd+S to save/format a file.

The timeout when getting module data from the registry is a good catch. We're currently canceling a request after 5 seconds to free up resources, but this shouldn't affect the formatting of files.

tpolekhin commented 2 years ago

Hello @dbanck Thanks for such a quick response I'm attaching vscode settings file and more output logs

settings.json

{
    "extensions.ignoreRecommendations": true,
    "editor.tabSize": 2,
    "workbench.iconTheme": "material-icon-theme",
    "material-icon-theme.showWelcomeMessage": false,
    "vsicons.dontShowNewVersionMessage": true,
    "go.toolsManagement.autoUpdate": true,
    "[terraform]": {
        "editor.defaultFormatter": "hashicorp.terraform",
        "editor.formatOnSave": true,
        "editor.formatOnSaveMode": "file"
    },
    "[terraform-vars]": {
        "editor.defaultFormatter": "hashicorp.terraform",
        "editor.formatOnSave": true,
        "editor.formatOnSaveMode": "file"
    },
    "window.zoomLevel": 1,
    "terraform.languageServer.enable": true,
    "terraform.languageServer.path": "/usr/local/bin/terraform-ls",
    "terraform.languageServer.terraform.path": "/usr/local/bin/terraform",
    "security.workspace.trust.banner": "never",
    "security.workspace.trust.enabled": false,
    "http.proxySupport": "off"
}

Logs from the VSCode output window from the moment I made a change in the code till file was saved

2022/08/26 14:34:26 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/26 14:34:26 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/26 14:34:26 rpc_logger.go:29: Incoming request for "textDocument/documentLink" (ID 17): {"textDocument":{"uri":"file:///Users/user/tf-test/main.tf"}}
2022/08/26 14:34:26 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google, ~> 3.90.0)
2022/08/26 14:34:26 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google-beta, ~> 3.90.0)
2022/08/26 14:34:26 rpc_logger.go:45: Error for "textDocument/documentLink" (ID 17): [-32098] main.tf: position 1,1 is out of range main.tf:3,34-313,1
2022/08/26 14:34:26 opts.go:218: Completed 1 requests [21.190426ms elapsed]
[Error - 2:34:26 PM] Request textDocument/documentLink failed.
  Message: main.tf: position 1,1 is out of range main.tf:3,34-313,1
  Code: -32098 
2022/08/26 14:34:48 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/26 14:34:48 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/26 14:34:48 rpc_logger.go:29: Incoming notification for "textDocument/didChange": {"textDocument":{"uri":"file:///Users/user/tf-test/main.tf","version":15},"contentChanges":[{"range":{"start":{"line":214,"character":16},"end":{"line":214,"character":17}},"rangeLength":1,"text":""}]}
2022/08/26 14:34:48 jobs.go:90: JOBS: Enqueueing new job "113": "OpTypeParseModuleConfiguration" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:34:48 jobs.go:90: JOBS: Enqueueing new job "114": "OpTypeLoadModuleMetadata" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:34:48 jobs.go:90: JOBS: Enqueueing new job "115": "OpTypeDecodeReferenceTargets" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:34:48 jobs.go:90: JOBS: Enqueueing new job "116": "OpTypeDecodeReferenceOrigins" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:34:48 jobs.go:90: JOBS: Enqueueing new job "117": "OpTypeGetModuleDataFromRegistry" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: false)
2022/08/26 14:34:48 jobs.go:90: JOBS: Enqueueing new job "118": "OpTypeParseVariables" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:34:48 jobs.go:90: JOBS: Enqueueing new job "119": "OpTypeDecodeVarsReferences" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:34:48 jobs.go:265: JOBS: Dispatching next job "113" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeParseModuleConfiguration" for {"file:///Users/user/tf-test"}
2022/08/26 14:34:48 jobs.go:265: JOBS: Dispatching next job "117" (scheduler prio: -1, job prio: -1, isDirOpen: true): "OpTypeGetModuleDataFromRegistry" for {"file:///Users/user/tf-test"}
2022/08/26 14:34:48 jobs.go:380: JOBS: Finishing job "113": "OpTypeParseModuleConfiguration" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:34:48 jobs.go:265: JOBS: Dispatching next job "114" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeLoadModuleMetadata" for {"file:///Users/user/tf-test"}
2022/08/26 14:34:48 jobs.go:380: JOBS: Finishing job "114": "OpTypeLoadModuleMetadata" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:34:48 jobs.go:265: JOBS: Dispatching next job "115" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeDecodeReferenceTargets" for {"file:///Users/user/tf-test"}
2022/08/26 14:34:48 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google-beta, ~> 3.90.0)
2022/08/26 14:34:48 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google, ~> 3.90.0)
2022/08/26 14:34:48 jobs.go:380: JOBS: Finishing job "115": "OpTypeDecodeReferenceTargets" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:34:48 jobs.go:265: JOBS: Dispatching next job "116" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeDecodeReferenceOrigins" for {"file:///Users/user/tf-test"}
2022/08/26 14:34:48 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google-beta, ~> 3.90.0)
2022/08/26 14:34:48 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google, ~> 3.90.0)
2022/08/26 14:34:48 jobs.go:380: JOBS: Finishing job "116": "OpTypeDecodeReferenceOrigins" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:34:48 jobs.go:265: JOBS: Dispatching next job "118" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeParseVariables" for {"file:///Users/user/tf-test"}
2022/08/26 14:34:48 jobs.go:380: JOBS: Finishing job "118": "OpTypeParseVariables" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:34:48 jobs.go:265: JOBS: Dispatching next job "119" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeDecodeVarsReferences" for {"file:///Users/user/tf-test"}
2022/08/26 14:34:48 jobs.go:380: JOBS: Finishing job "119": "OpTypeDecodeVarsReferences" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:34:48 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/26 14:34:48 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/26 14:34:49 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/26 14:34:49 opts.go:218: Posting server call "client.refreshModuleProviders" 
2022/08/26 14:34:49 opts.go:218: Received response for callback "33"
2022/08/26 14:34:49 opts.go:218: Posting server call "client.refreshModuleCalls" 
2022/08/26 14:34:49 opts.go:218: Received response for callback "34"
2022/08/26 14:34:49 opts.go:218: Received request batch of size 1 (qlen=1)
2022/08/26 14:34:52 opts.go:218: Received request batch of size 1 (qlen=2)
2022/08/26 14:34:53 jobs.go:380: JOBS: Finishing job "117": "OpTypeGetModuleDataFromRegistry" for {"file:///Users/user/tf-test"} (err = 1 error occurred:
    * Get "https://registry.terraform.io/v1/modules/terraform-google-modules/iam/google/versions": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

, deferredJobs: [])
2022/08/26 14:34:53 opts.go:218: Dequeued request batch of length 1 (qlen=2)
2022/08/26 14:34:53 opts.go:218: Dequeued request batch of length 1 (qlen=1)
2022/08/26 14:34:53 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/26 14:34:53 rpc_logger.go:29: Incoming notification for "$/cancelRequest": {"id":19}
2022/08/26 14:34:53 opts.go:218: Cancelled request 19 by client order
2022/08/26 14:34:53 rpc_logger.go:29: Incoming request for "textDocument/semanticTokens/full" (ID 18): {"textDocument":{"uri":"file:///Users/user/tf-test/main.tf"}}
2022/08/26 14:34:53 rpc_logger.go:29: Incoming request for "textDocument/documentLink" (ID 20): {"textDocument":{"uri":"file:///Users/user/tf-test/main.tf"}}
2022/08/26 14:34:53 rpc_logger.go:29: Incoming request for "textDocument/hover" (ID 19): {"textDocument":{"uri":"file:///Users/user/tf-test/main.tf"},"position":{"line":227,"character":30}}
2022/08/26 14:34:53 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google, ~> 3.90.0)
2022/08/26 14:34:53 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google, ~> 3.90.0)
2022/08/26 14:34:53 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google, ~> 3.90.0)
2022/08/26 14:34:53 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google-beta, ~> 3.90.0)
2022/08/26 14:34:53 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google-beta, ~> 3.90.0)
2022/08/26 14:34:53 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google-beta, ~> 3.90.0)
2022/08/26 14:34:53 rpc_logger.go:45: Error for "textDocument/documentLink" (ID 20): [-32098] main.tf: position 1,1 is out of range main.tf:3,34-313,1
2022/08/26 14:34:53 hover.go:32: Looking for hover data at "main.tf" -> hcl.Pos{Line:228, Column:31, Byte:12606}
2022/08/26 14:34:53 hover.go:34: received hover data: (*lang.HoverData)(nil)
2022/08/26 14:34:53 opts.go:218: Completed 1 requests [10.788782ms elapsed]
2022/08/26 14:34:53 rpc_logger.go:45: Error for "textDocument/hover" (ID 19): [-32800] error code -32800: main.tf (228,31): unknown attribute "ayo_backend_env"
2022/08/26 14:34:53 opts.go:218: Completed 1 requests [10.927206ms elapsed]
[Error - 2:34:53 PM] Request textDocument/documentLink failed.
  Message: main.tf: position 1,1 is out of range main.tf:3,34-313,1
  Code: -32098 
2022/08/26 14:34:53 rpc_logger.go:45: Error for "textDocument/semanticTokens/full" (ID 18): [-32098] main.tf: position 1,1 is out of range main.tf:3,34-313,1
2022/08/26 14:34:53 opts.go:218: Completed 1 requests [4.593145213s elapsed]
[Error - 2:34:53 PM] Request textDocument/semanticTokens/full failed.
  Message: main.tf: position 1,1 is out of range main.tf:3,34-313,1
  Code: -32098 
2022/08/26 14:35:01 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/26 14:35:01 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/26 14:35:01 rpc_logger.go:29: Incoming request for "textDocument/formatting" (ID 21): {"textDocument":{"uri":"file:///Users/user/tf-test/main.tf"},"options":{"tabSize":2,"insertSpaces":true}}
2022/08/26 14:35:01 formatting.go:42: formatting document via "/usr/local/bin/terraform"
2022/08/26 14:35:01 formatting.go:50: Finished 'terraform fmt' in 495.980836ms
2022/08/26 14:35:01 rpc_logger.go:50: Response to "textDocument/formatting" (ID 21): []
2022/08/26 14:35:01 opts.go:218: Completed 1 requests [501.32879ms elapsed]
2022/08/26 14:35:01 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/26 14:35:01 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/26 14:35:01 rpc_logger.go:29: Incoming notification for "textDocument/didSave": {"textDocument":{"uri":"file:///Users/user/tf-test/main.tf"}}
2022/08/26 14:35:02 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/26 14:35:02 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/26 14:35:02 rpc_logger.go:29: Incoming notification for "workspace/didChangeWatchedFiles": {"changes":[{"uri":"file:///Users/user/tf-test/main.tf","type":2}]}
2022/08/26 14:35:02 jobs.go:90: JOBS: Enqueueing new job "120": "OpTypeParseModuleConfiguration" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:35:02 jobs.go:90: JOBS: Enqueueing new job "121": "OpTypeLoadModuleMetadata" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:35:02 jobs.go:90: JOBS: Enqueueing new job "122": "OpTypeDecodeReferenceTargets" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:35:02 jobs.go:90: JOBS: Enqueueing new job "123": "OpTypeDecodeReferenceOrigins" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:35:02 jobs.go:90: JOBS: Enqueueing new job "124": "OpTypeGetModuleDataFromRegistry" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: false)
2022/08/26 14:35:02 jobs.go:90: JOBS: Enqueueing new job "125": "OpTypeParseVariables" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:35:02 jobs.go:90: JOBS: Enqueueing new job "126": "OpTypeDecodeVarsReferences" for {"file:///Users/user/tf-test"} (IsDirOpen: true, IgnoreState: true)
2022/08/26 14:35:02 jobs.go:265: JOBS: Dispatching next job "120" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeParseModuleConfiguration" for {"file:///Users/user/tf-test"}
2022/08/26 14:35:02 jobs.go:265: JOBS: Dispatching next job "124" (scheduler prio: -1, job prio: -1, isDirOpen: true): "OpTypeGetModuleDataFromRegistry" for {"file:///Users/user/tf-test"}
2022/08/26 14:35:02 jobs.go:380: JOBS: Finishing job "120": "OpTypeParseModuleConfiguration" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:35:02 jobs.go:265: JOBS: Dispatching next job "121" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeLoadModuleMetadata" for {"file:///Users/user/tf-test"}
2022/08/26 14:35:02 jobs.go:380: JOBS: Finishing job "121": "OpTypeLoadModuleMetadata" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:35:02 jobs.go:265: JOBS: Dispatching next job "122" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeDecodeReferenceTargets" for {"file:///Users/user/tf-test"}
2022/08/26 14:35:02 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google-beta, ~> 3.90.0)
2022/08/26 14:35:02 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google, ~> 3.90.0)
2022/08/26 14:35:02 jobs.go:380: JOBS: Finishing job "122": "OpTypeDecodeReferenceTargets" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:35:02 jobs.go:265: JOBS: Dispatching next job "123" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeDecodeReferenceOrigins" for {"file:///Users/user/tf-test"}
2022/08/26 14:35:02 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google-beta, ~> 3.90.0)
2022/08/26 14:35:02 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google, ~> 3.90.0)
2022/08/26 14:35:02 jobs.go:380: JOBS: Finishing job "123": "OpTypeDecodeReferenceOrigins" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:35:02 jobs.go:265: JOBS: Dispatching next job "125" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeParseVariables" for {"file:///Users/user/tf-test"}
2022/08/26 14:35:02 jobs.go:380: JOBS: Finishing job "125": "OpTypeParseVariables" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:35:02 jobs.go:265: JOBS: Dispatching next job "126" (scheduler prio: 1, job prio: 0, isDirOpen: true): "OpTypeDecodeVarsReferences" for {"file:///Users/user/tf-test"}
2022/08/26 14:35:02 jobs.go:380: JOBS: Finishing job "126": "OpTypeDecodeVarsReferences" for {"file:///Users/user/tf-test"} (err = %!s(<nil>), deferredJobs: [])
2022/08/26 14:35:03 opts.go:218: Posting server call "client.refreshModuleProviders" 
2022/08/26 14:35:03 opts.go:218: Received response for callback "35"
2022/08/26 14:35:03 opts.go:218: Posting server call "client.refreshModuleCalls" 
2022/08/26 14:35:03 opts.go:218: Received response for callback "36"
2022/08/26 14:35:07 jobs.go:380: JOBS: Finishing job "124": "OpTypeGetModuleDataFromRegistry" for {"file:///Users/user/tf-test"} (err = 1 error occurred:
    * Get "https://registry.terraform.io/v1/modules/terraform-google-modules/iam/google/versions": context deadline exceeded (Client.Timeout exceeded while awaiting headers)

, deferredJobs: [])
2022/08/26 14:35:20 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/26 14:35:20 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/26 14:35:20 rpc_logger.go:29: Incoming request for "textDocument/codeLens" (ID 22): {"textDocument":{"uri":"file:///Users/user/tf-test/main.tf"}}
2022/08/26 14:35:20 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google-beta, ~> 3.90.0)
2022/08/26 14:35:20 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google, ~> 3.90.0)
2022/08/26 14:35:20 rpc_logger.go:50: Response to "textDocument/codeLens" (ID 22): []
2022/08/26 14:35:20 opts.go:218: Completed 1 requests [10.949694ms elapsed]
2022/08/26 14:35:20 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/26 14:35:20 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/26 14:35:20 rpc_logger.go:29: Incoming request for "textDocument/documentSymbol" (ID 23): {"textDocument":{"uri":"file:///Users/user/tf-test/main.tf"}}
2022/08/26 14:35:20 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google-beta, ~> 3.90.0)
2022/08/26 14:35:20 provider_schema.go:256: PSS: getting provider schema (/Users/user/tf-test, registry.terraform.io/hashicorp/google, ~> 3.90.0)
2022/08/26 14:35:20 rpc_logger.go:50: Response to "textDocument/documentSymbol" (ID 23): <redacted>
2022/08/26 14:35:20 opts.go:218: Completed 1 requests [22.251511ms elapsed]
tpolekhin commented 2 years ago

I made a new terraform folder with just google-iam module inside This is the output.log gist from the start of the vscode till file was saved and output flow stopped https://gist.github.com/tpolekhin/d6b5e42e0ba64bb747cc10d5c29f1472

dbanck commented 2 years ago

Thank you for the additional information!

The provided log contains a formatting request and a response after ~500ms:

2022/08/26 14:35:01 rpc_logger.go:29: Incoming request for "textDocument/formatting" (ID 21): {"textDocument":{"uri":"file:///Users/user/tf-test/main.tf"},"options":{"tabSize":2,"insertSpaces":true}}
2022/08/26 14:35:01 formatting.go:42: formatting document via "/usr/local/bin/terraform"
2022/08/26 14:35:01 formatting.go:50: Finished 'terraform fmt' in 495.980836ms
2022/08/26 14:35:01 rpc_logger.go:50: Response to "textDocument/formatting" (ID 21): []

The empty ([]) response usually indicates that no text edits are needed and that the file is already formatted. Is this in line with your expectations? Are there unformatted parts in your main.tf?

Does saving feels slow? Like a 5 seconds delay?

I was not expecting out of range errors here and those might be an indication of another bug.

[Error - 2:34:26 PM] Request textDocument/documentLink failed.
  Message: main.tf: position 1,1 is out of range main.tf:3,34-313,1
  Code: -32098 

[Error - 2:34:53 PM] Request textDocument/documentLink failed.
  Message: main.tf: position 1,1 is out of range main.tf:3,34-313,1
  Code: -32098 

[Error - 2:34:53 PM] Request textDocument/semanticTokens/full failed.
  Message: main.tf: position 1,1 is out of range main.tf:3,34-313,1
  Code: -32098

Can you share the first ~5 lines of your main.tf including whitespaces and empty lines?

dbanck commented 2 years ago

Coming back to the failed registry HTTP calls. Are you behind some proxy? You have "http.proxySupport": "off" in your VS Code config?

The lack of proxy support and failing HTTP calls shouldn't slow down the language server since it should process everything asynchronously. This leads me to assume that there is some kind of bug here.

tpolekhin commented 2 years ago

This is the start of the main.tf file:

/********************************
 Data ETL Process Components
********************************/

data "google_project" "project" {
  project_id = var.project_id
}

Coming back to the failed registry HTTP calls. Are you behind some proxy? You have "http.proxySupport": "off" in your VS Code config?

No, I don't use a proxy, this was just a sanity check when I saw timeout but it didn't help

Does saving feels slow? Like a 5 seconds delay?

This is NOT the original code I posted the logs from - I created a test folder to be able to share it

When I hit Cmd+S there's a progress bar at the bottom of the VSCode that can go away in 5-10 seconds, or stay there until I hit cancel. In this particular case formatting did eventually happened and file was saved, but it took around 30 seconds it feels like. This is the updated gist log with the save showed in the screenshot https://gist.github.com/tpolekhin/899f6e8078b84e8b43807709bb75b999

Screenshot 2022-08-26 at 15 14 22

dbanck commented 2 years ago

Thank you for sharing that screenshot and describing the behavior.

I'm confident that the hanging HTTP requests to the registry lead to a degraded language server performance. However, that isn't the expected behavior and is a bug on our side.

On the other hand, something odd about your system or connection leads to hanging/failing HTTP requests. Can you try using time curl to make a request:

$ time curl -I https://registry.terraform.io/v1/modules/terraform-google-modules/iam/google/versions
HTTP/2 200
content-type: application/json
cache-control: public, max-age=30, stale-while-revalidate=1800, stale-if-error=31536000
last-modified: Thu, 17 Mar 2022 16:01:45 GMT
server: terraform-registry/85602ba436c23028e1cd74b518d2309682b41ca2
strict-transport-security: max-age=31536000; includeSubDomains; preload
via: 1.1 varnish, 1.1 varnish
accept-ranges: bytes
date: Fri, 26 Aug 2022 13:51:32 GMT
age: 10
x-served-by: cache-iad-kiad7000114-IAD, cache-hhn4082-HHN
x-cache: HIT, HIT
x-cache-hits: 1, 2
vary: Accept-Encoding
content-length: 36151

________________________________________________________
Executed in   91.50 millis    fish           external
   usr time   18.95 millis  143.00 micros   18.80 millis
   sys time    7.40 millis  634.00 micros    6.76 millis
tpolekhin commented 2 years ago

To be honest I never experienced such issues with network As I said before this issue with save started after I've upgraded to macOS Monterey Before I was on macOS Catalina for couple years using the same WiFi at home and in the office and never saw this behaviour

$ time curl -I https://registry.terraform.io/v1/modules/terraform-google-modules/iam/google/versions
HTTP/2 200
content-type: application/json
cache-control: public, max-age=30, stale-while-revalidate=1800, stale-if-error=31536000
last-modified: Thu, 17 Mar 2022 16:01:45 GMT
server: terraform-registry/85602ba436c23028e1cd74b518d2309682b41ca2
strict-transport-security: max-age=31536000; includeSubDomains; preload
via: 1.1 varnish, 1.1 varnish
accept-ranges: bytes
date: Fri, 26 Aug 2022 14:00:59 GMT
age: 578
x-served-by: cache-iad-kiad7000105-IAD, cache-fra19177-FRA
x-cache: HIT, MISS
x-cache-hits: 1, 0
vary: Accept-Encoding
content-length: 36151

________________________________________________________
Executed in  275.66 millis    fish           external
   usr time   15.05 millis    0.13 millis   14.92 millis
   sys time   17.83 millis    1.09 millis   16.74 millis
dbanck commented 2 years ago

Do you run any local application firewalls, like Little Snitch or Lulu? These could block traffic for specific binaries.

tpolekhin commented 2 years ago

Not that I'm aware of. This is a corporate laptop so I have AV and JAMF, but I never had any issues like that before

radeksimko commented 2 years ago

One more question: The -I flag of curl makes a HEAD request. Can you try reproducing this with GET request by avoiding -I and pass -o /dev/null instead?

echo "%{time_total}s\n" | curl -w '@-' -o /dev/null https://registry.terraform.io/v1/modules/terraform-google-modules/iam/google/versions
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 36151  100 36151    0     0   205k      0 --:--:-- --:--:-- --:--:--  211k
0.171544s

^ I still get the response within 200ms in my environment

In case you have Go installed on your machine, you can also run this snippet of code, which is practically identical to what we ship as part of LS: https://gist.github.com/radeksimko/3bfc1537291ff8ca67aa527b6507caef

btw. We both run JAMF on our work machines with Daniel. I did experience some random slowdown in the past which was pretty hard to reproduce repeatedly, but it was usually related to process execution rather than network. I wouldn't rule out JAMF as the root cause though.

tpolekhin commented 2 years ago

Hello, @radeksimko 

$ go run main.go
21 versions obtained in 1.251509048s
[7.4.1 7.4.0 7.3.0 7.2.0 7.1.0 7.0.0 6.4.1 6.4.0 6.3.1 6.3.0 6.2.0 6.1.0 6.0.0 5.1.0 5.0.0 4.0.0 3.0.0 2.0.0 1.1.1 1.1.0 1.0.0]
$ echo "%{time_total}s\n" | curl -w '@-' -o /dev/null https://registry.terraform.io/v1/modules/terraform-google-modules/iam/google/versions
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 36151  100 36151    0     0   108k      0 --:--:-- --:--:-- --:--:--  111k
0.325402s
radeksimko commented 2 years ago

1.2s is still pretty far from 5 seconds, but I can repeatedly get under 200ms on my machine (MacBook Pro 14-inch, 2021, 32GB RAM).

If you have a moment, I have updated the snippet to output elapsed time for each stage: https://gist.github.com/radeksimko/3bfc1537291ff8ca67aa527b6507caef

That could tell us what takes the majority of those 1.2 seconds in your case - as that still looks quite slow to me.

I'm assuming the answer is yes, but just for any avoidance of doubt - are you still able to reproduce the 5 second timeout now in LS, while the snippet suggests it takes 1.2 seconds?

tpolekhin commented 2 years ago

Yes, I just checked and timeout is there

$ go run main.go
2022/08/30 11:12:47 request took 1.203497294s
2022/08/30 11:12:47 response body reading took 298ns
2022/08/30 11:12:47 decoding response took 1.409251ms
21 versions obtained in 1.205318835s
[7.4.1 7.4.0 7.3.0 7.2.0 7.1.0 7.0.0 6.4.1 6.4.0 6.3.1 6.3.0 6.2.0 6.1.0 6.0.0 5.1.0 5.0.0 4.0.0 3.0.0 2.0.0 1.1.1 1.1.0 1.0.0]
tpolekhin commented 2 years ago

I've also tried to download the latest release from GitHub and put it in /usr/local/bin as terraform-ls-github Pointed VSCode to this binary instead but the issue still present I'm honestly out of ideas why this can happen

dbanck commented 2 years ago

To check one more thing: the extension bundles the language server, so a user usually doesn't have to download/install it manually. Does the error still occur if you remove the "terraform.languageServer.path" entry from VS Code settings?

dbanck commented 2 years ago

Another idea: maybe something is blocking network requests for processes spawned by another process. But if a user directly spawns the LS process, it might work. We have an experimental TCP mode in the LS, which isn't indented for day-to-day use but could be helpful to debug this issue.

You can launch the standalone language server binary by running terraform-ls serve -port 3333 and point VS Code to connect to it via TCP "terraform.languageServer.tcp.port": 3333,. You can find the LS log output inside your terminal instead of VS Code. Are the network requests now working?

tpolekhin commented 2 years ago

I had the same idea so I went and deleted all parameters from settings.json related to terraform Restarted VSCode and the issue is still present

Last resort - I have Falcon AV installed on the system Maybe it's somehow blocks this specific binary with false positive signature check?

tpolekhin commented 2 years ago

Another idea: maybe something is blocking network requests for processes spawned by another process. But if a user directly spawns the LS process, it might work. We have an experimental TCP mode in the LS, which isn't indented for day-to-day use but could be helpful to debug this issue.

You can launch the standalone language server binary by running terraform-ls serve -port 3333 and point VS Code to connect to it via TCP "terraform.languageServer.tcp.port": 3333,. You can find the LS log output inside your terminal instead of VS Code. Are the network requests now working?

No, same timeout even if I run LS myself Log: https://gist.github.com/tpolekhin/387674f7efec7cf23d5bbde3c7846e4e

tpolekhin commented 2 years ago

So, some new information

dbanck commented 2 years ago

Thanks for being so responsive and trying all our suggestions ❤️

I'm slowly running out of ideas, but one other thing we could do is obtain more debug logs. Can you run the LS in TCP mode with GODEBUG=http2debug=2 set and paste the logs? That would tell us where exactly it hangs.

GODEBUG=http2debug=2 terraform-ls serve -port 3333
tpolekhin commented 2 years ago

@dbanck I have tried both direct env var and via export but it doesn't seem like it changes the output https://gist.github.com/tpolekhin/1741762179adb02b4d10b56b76752cb7

tpolekhin commented 2 years ago

@dbanck breakthrough! I've downloaded previous release of terraform-ls from GitHub https://github.com/hashicorp/terraform-ls/releases/tag/v0.28.0 and pointed VSCode to this binary

File save and formatting is now almost instant and no timeouts in the output logs! https://gist.github.com/tpolekhin/62f58d757edab93481f158e7d83c4563

UPDATE: I've also tried v0.29.0 and it has the issue so something in the v0.29.0 release causes this behaviour

tpolekhin commented 2 years ago

@dbanck another interesting development

I've contacted our company IT support to check if Falcon is blocking terraform-ls binary somehow They suggested to add for registry.terraform.io in the /etc/hosts and try again They had issues similar to that before and it was because of IPv6

I went ahead and removed custom terraform-ls path from the vscode config to use embedded one and added 151.101.2.49 registry.terraform.io to my /etc/hosts file

Now I can confirm that using this approach terraform-ls v0.29.1 works fine with almost instant format and save I don't see any Timeouts in the output logs of the terraform-ls and requests now seems to be working

2022/08/30 15:36:23 opts.go:218: Received request batch of size 1 (qlen=0)
2022/08/30 15:36:23 opts.go:218: Dequeued request batch of length 1 (qlen=0)
2022/08/30 15:36:23 rpc_logger.go:29: Incoming request for "textDocument/documentLink" (ID 76): {"textDocument":{"uri":"file:///Users/tpol/Work/personal/tf-test2/main.tf"}}
2022/08/30 15:36:23 provider_schema.go:256: PSS: getting provider schema (/Users/tpol/Work/personal/tf-test2, registry.terraform.io/-/google, )
2022/08/30 15:36:23 rpc_logger.go:50: Response to "textDocument/documentLink" (ID 76): [{"range":{"start":{"line":8,"character":12},"end":{"line":8,"character":59}},"target":"https://registry.terraform.io/modules/terraform-google-modules/cloud-storage/google/3.2.0?utm_content=documentLink\u0026utm_medium=Visual+Studio+Code\u0026utm_source=terraform-ls"}]
2022/08/30 15:36:23 opts.go:218: Completed 1 requests [3.269863ms elapsed]
dbanck commented 2 years ago

Exciting find and fix via the /etc/hosts file. Thanks for confirming that everything works now. Make sure to remember to update the entry the next time fastly decides to update their DNS record ;)

We introduced completion, hover, and docs links for uninitialized registry modules in https://github.com/hashicorp/terraform-ls/pull/924. This change was part of the 0.29.0 release. Before that release, we didn't make any HTTP requests to the Terraform registry. So that's why 0.28.0 was working for you.

The remaining unsolved part is why hanging HTTP requests block the language server when a file is formatted. A missing, slow, or unstable network connection shouldn't affect the formatting of files. But that's for us to solve.

tpolekhin commented 2 years ago

I guess there's another question remaining - why this golang snippet worked fine when talking to registry.terraform.io? https://github.com/hashicorp/terraform-ls/issues/1050#issuecomment-1231380763

Maybe timeout is too small in the terraform-ls?

dbanck commented 2 years ago

I guess there's another question remaining - why this golang snippet worked fine when talking to registry.terraform.io? #1050 (comment)

Maybe timeout is too small in the terraform-ls?

That is an interesting question to solve but out of scope for us. Both are using the same (5s) timeout.

I'm closing this issue in favor of #1063, which condenses all information about the slow/blocked RPC requests.

Thank you again for the fantastic collaboration!

github-actions[bot] commented 2 years ago

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.