golang / vscode-go

Go extension for Visual Studio Code
https://marketplace.visualstudio.com/items?itemName=golang.Go
Other
3.85k stars 738 forks source link

Remote extension host keep restarting upon enabling gopls #2986

Closed yiminmv closed 11 months ago

yiminmv commented 1 year ago

What version of Go, VS Code & VS Code Go extension are you using?

Version Information
* Run `go version` to get version of Go from _the VS Code integrated terminal_. - go version go1.19.7 linux/amd64 * Run `gopls -v version` to get version of Gopls from _the VS Code integrated terminal_. ``` Build info ---------- golang.org/x/tools/gopls v0.13.2 golang.org/x/tools/gopls@v0.13.2 h1:Pyvx6MKvatbX3zzZmdGiFRfQZl0ohPlt2sFxO/5j6Ro= github.com/BurntSushi/toml@v1.2.1 h1:9F2/+DoOYIOksmaJFPw1tGFy1eDnIJXg+UHjuD8lTak= github.com/google/go-cmp@v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38= github.com/sergi/go-diff@v1.1.0 h1:we8PVUC3FE2uYfodKH/nBHMSetSfHDR6scGdBi+erh0= golang.org/x/exp@v0.0.0-20220722155223-a9213eeb770e h1:+WEEuIdZHnUeJJmEUjyYC2gfUMj69yZXw17EnHg/otA= golang.org/x/exp/typeparams@v0.0.0-20221212164502-fae10dda9338 h1:2O2DON6y3XMJiQRAS1UWU+54aec2uopH3x7MAiqGW6Y= golang.org/x/mod@v0.12.0 h1:rmsUpXtvNzj340zd98LZ4KntptpfRHwpFOHG188oHXc= golang.org/x/sync@v0.3.0 h1:ftCYgMx6zT/asHUrPw8BLLscYtGznsLAnjq5RH9P66E= golang.org/x/sys@v0.10.0 h1:SqMFp9UcQJZa+pmYuAKjd9xq1f0j5rLcDIk0mj4qAsA= golang.org/x/text@v0.11.0 h1:LAntKIrcmeSKERyiOh0XMV39LXS8IE9UL2yP7+f5ij4= golang.org/x/tools@v0.11.2-0.20230810185051-cc6b5804b8cf h1:Oush7UwPamr2/iNeNFBuNFj89YyHn0YY69EKDdvANnk= golang.org/x/vuln@v0.0.0-20230110180137-6ad3e3d07815 h1:A9kONVi4+AnuOr1dopsibH6hLi1Huy54cbeJxnq4vmU= honnef.co/go/tools@v0.4.2 h1:6qXr+R5w+ktL5UkwEbPp+fEvfyoMPche6GkOpGHZcLc= mvdan.cc/gofumpt@v0.4.0 h1:JVf4NN1mIpHogBj7ABpgOyZc65/UUOkKQFkoURsz4MM= mvdan.cc/xurls/v2@v2.4.0 h1:tzxjVAj+wSBmDcF6zBB7/myTy3gX9xvi8Tyr28AuQgc= go: go1.19.7 ``` * Run `code -v` or `code-insiders -v` to get version of VS Code or VS Code Insiders. ``` Version: 1.82.2 (Universal) Commit: abd2f3db4bdb28f9e95536dfa84d8479f1eb312d Date: 2023-09-14T05:59:47.790Z Electron: 25.8.1 ElectronBuildId: 23779380 Chromium: 114.0.5735.289 Node.js: 18.15.0 V8: 11.4.183.29-electron.0 OS: Darwin arm64 22.6.0 ``` * Check your installed extensions to get the version of the VS Code Go extension - v0.39.1 * Run Ctrl+Shift+P (Cmd+Shift+P on Mac OS) > `Go: Locate Configured Go Tools` command. ``` Checking configured tools.... GOBIN: undefined toolsGopath: gopath: /go GOROOT: /root/sdk/go1.19.7 PATH: /root/sdk/go1.19.7/bin:/root/.vscode-server/bin/abd2f3db4bdb28f9e95536dfa84d8479f1eb312d/bin/remote-cli:/root/.yarn/bin:/opt/google-cloud-sdk/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/.cargo/bin:/opt/memverge/sbin:/go/bin:/code/kubernetes/third_party/etcd:/root/.cargo/bin:/opt/memverge/sbin:/go/bin:/code/kubernetes/third_party/etcd PATH (vscode launched with): /root/.vscode-server/bin/abd2f3db4bdb28f9e95536dfa84d8479f1eb312d/bin/remote-cli:/root/.yarn/bin:/opt/google-cloud-sdk/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/.cargo/bin:/opt/memverge/sbin:/go/bin:/code/kubernetes/third_party/etcd:/root/.cargo/bin:/opt/memverge/sbin:/go/bin:/code/kubernetes/third_party/etcd go: /root/sdk/go1.19.7/bin/go: go version go1.19.7 linux/amd64 gotests: /go/bin/gotests (version: v1.6.0 built with go: go1.20.6) gomodifytags: /go/bin/gomodifytags (version: v1.16.0 built with go: go1.20.6) impl: /go/bin/impl (version: v1.1.0 built with go: go1.20.6) goplay: /go/bin/goplay (version: v1.0.0 built with go: go1.20.6) dlv: /go/bin/dlv (version: v1.21.0 built with go: go1.20.6) golangci-lint: /go/bin/golangci-lint (version: v1.54.2 built with go: go1.20.6) gopls: not installed (gopls is missing because when it installed, go extension will crash...) go env Workspace Folder (float): /code/float GO111MODULE="on" GOARCH="amd64" GOBIN="" GOCACHE="/root/.cache/go-build" GOENV="/root/.config/go/env" GOEXE="" GOEXPERIMENT="" GOFLAGS="" GOHOSTARCH="amd64" GOHOSTOS="linux" GOINSECURE="" GOMODCACHE="/go/pkg/mod" GONOPROXY="" GONOSUMDB="" GOOS="linux" GOPATH="/go" GOPRIVATE="" GOPROXY="https://proxy.golang.org,direct" GOROOT="/root/sdk/go1.19.7" GOSUMDB="sum.golang.org" GOTMPDIR="" GOTOOLDIR="/root/sdk/go1.19.7/pkg/tool/linux_amd64" GOVCS="" GOVERSION="go1.19.7" GCCGO="gccgo" GOAMD64="v1" AR="ar" CC="gcc" CXX="g++" CGO_ENABLED="1" GOMOD="/code/float/go.mod" GOWORK="" CGO_CFLAGS="-g -O2" CGO_CPPFLAGS="" CGO_CXXFLAGS="-g -O2" CGO_FFLAGS="-g -O2" CGO_LDFLAGS="-g -O2" PKG_CONFIG="pkg-config" GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build670871236=/tmp/go-build -gno-record-gcc-switches" ```

Share the Go related settings you have added/edited

Run Preferences: Open Settings (JSON) command to open your settings.json file. Share all the settings with the go. or ["go"] or gopls prefixes.

    "go.toolsManagement.autoUpdate": true,
    "go.formatTool": "goimports",
    "go.lintTool": "golangci-lint",
    "go.useLanguageServer": true,
    "go.testFlags": [
        "-v"
    ],
    "go.toolsManagement.checkForUpdates": "off",
    "go.alternateTools": {},
    "go.testTimeout": "2m",
    "go.languageServerFlags": [
        "-rpc.trace"
    ],
    "gopls": {
        "verboseOutput": true
    },

Describe the bug

The core issue arises when enabling the Go extension in VSCode; the remote extension host continuously restarts, behaving as though it's constantly crashing. I isolated this issue by removing all dependencies and observed that the problem resurfaces upon installing gopls and godef. Although I attempted to collect log content by following the troubleshooting wiki, no output was available from either go or gopls (server) due to the Go extension crashing. Uninstalling gopls or relocating it resolves the crashing issue. Functionalities such as Find All References and Choose Go Environment can work normally because they don't rely on the gopls.

This issue initially appeared in vscode-insiders. Due to I unable to identify the root cause in a short time, I switched to using the standard vscode, about a few month later, I encounter the same problem again.

Steps to reproduce the behavior:

  1. no perticular setups, just open vscode.

Screenshots or recordings

If applicable, add screenshots or recordings to help explain your problem. image

Some log output from Extension Host(remote) with debug log level set, it looks like no further output after doActivateExtension golang.go

2023-09-21 15:17:30.411 [info] Extension host with pid 88457 started
2023-09-21 15:17:30.411 [error] Error: EEXIST: file already exists, open '/root/.vscode-server/data/User/workspaceStorage/068738d732eb87df7fac493cf6f6d7cd/vscode.lock'
2023-09-21 15:17:30.416 [info] Lock '/root/.vscode-server/data/User/workspaceStorage/068738d732eb87df7fac493cf6f6d7cd/vscode.lock': Could not acquire lock, checking if the file is stale.
2023-09-21 15:17:30.418 [info] Lock '/root/.vscode-server/data/User/workspaceStorage/068738d732eb87df7fac493cf6f6d7cd/vscode.lock': The pid 88280 appears to be gone.
2023-09-21 15:17:30.418 [info] Lock '/root/.vscode-server/data/User/workspaceStorage/068738d732eb87df7fac493cf6f6d7cd/vscode.lock': Deleting a stale lock.
2023-09-21 15:17:30.428 [info] Lock '/root/.vscode-server/data/User/workspaceStorage/068738d732eb87df7fac493cf6f6d7cd/vscode.lock': Lock acquired.
2023-09-21 15:17:30.502 [info] ExtensionService#_doActivateExtension vscode.emmet, startup: false, activationEvent: 'onLanguage'
2023-09-21 15:17:30.503 [info] ExtensionService#_doActivateExtension vscode.extension-editing, startup: false, activationEvent: 'onLanguage:json'
2023-09-21 15:17:30.503 [info] ExtensionService#_doActivateExtension vscode.json-language-features, startup: false, activationEvent: 'onLanguage:json'
2023-09-21 15:17:30.503 [info] ExtensionService#_doActivateExtension vscode.npm, startup: false, activationEvent: 'onLanguage:json'
2023-09-21 15:17:30.503 [info] ExtensionService#_doActivateExtension vscode.typescript-language-features, startup: false, activationEvent: 'onLanguage:jsonc'
2023-09-21 15:17:30.742 [debug] ProxyResolver#getCaCertificates count 143
2023-09-21 15:17:30.742 [debug] ProxyResolver#getCaCertificates parse error Error: error:0480006C:PEM routines::no start line
    at new X509Certificate (node:internal/crypto/x509:119:21)
    at /root/.vscode-server/bin/abd2f3db4bdb28f9e95536dfa84d8479f1eb312d/node_modules/@vscode/proxy-agent/out/index.js:473:44
    at Array.filter (<anonymous>)
    at /root/.vscode-server/bin/abd2f3db4bdb28f9e95536dfa84d8479f1eb312d/node_modules/@vscode/proxy-agent/out/index.js:471:22
2023-09-21 15:17:30.770 [debug] ProxyResolver#getCaCertificates count filtered 140
2023-09-21 15:17:30.771 [debug] ProxyResolver#resolveProxy unconfigured https://default.exp-tas.com/vscode/ab DIRECT 
2023-09-21 15:17:30.874 [debug] ExtHostSearch /root/.vscode-server/bin/abd2f3db4bdb28f9e95536dfa84d8479f1eb312d/node_modules/@vscode/ripgrep/bin/rg --files --hidden --case-sensitive --no-require-git -g '**/package.json' -g '!**/.git' -g '!**/.svn' -g '!**/.hg' -g '!**/CVS' -g '!**/.DS_Store' -g '!**/Thumbs.db' --no-ignore --follow --no-config --no-ignore-global
 - cwd: /code/float
 - Sibling clauses: {}
2023-09-21 15:17:30.952 [info] ExtensionService#_doActivateExtension vscode.git-base, startup: true, activationEvent: '*', root cause: vscode.git
2023-09-21 15:17:30.972 [info] ExtensionService#_doActivateExtension vscode.git, startup: true, activationEvent: '*'
2023-09-21 15:17:30.972 [info] ExtensionService#_doActivateExtension vscode.github, startup: true, activationEvent: '*'
2023-09-21 15:17:31.086 [debug] ExtHostSearch /root/.vscode-server/bin/abd2f3db4bdb28f9e95536dfa84d8479f1eb312d/node_modules/@vscode/ripgrep/bin/rg --files --hidden --case-sensitive --no-require-git -g '/*.go' -g '/*/*.go' -g '/*/*/*.go' -g '!**/.git' -g '!**/.svn' -g '!**/.hg' -g '!**/CVS' -g '!**/.DS_Store' -g '!**/Thumbs.db' -g '!**/node_modules' -g '!**/bower_components' -g '!**/*.code-search' --no-ignore-parent --follow --quiet --no-config --no-ignore-global
 - cwd: /code/float
 - Sibling clauses: {}
2023-09-21 15:17:31.358 [info] ExtensionService#_doActivateExtension golang.go, startup: true, activationEvent: 'workspaceContains:*.go,*/*.go,*/*/*.go'

I recorded a short video to illustrate this issue, the GOPATH is /go/bin/, when I move gopls into this folder, then reload, the go extension crashed; when I move it out of GOPATH, the go extension works again. The outline in the side bar can comfirm the go extension status.

https://github.com/golang/vscode-go/assets/51390919/aa153a8e-aeb3-4ca3-8070-7010dabf1bb0

amitroshin commented 1 year ago

I have the same thing on remote host Ubuntu 22.04.3 and Oracle linux 9. VS Code running on Windows 11 22H2 with OpenSSH_for_Windows_8.6p1, LibreSSL 3.4.3. The only one available action to avoid remote host crashes is to switch off using language server by option "go.useLanguageServer": false

findleyr commented 1 year ago

Interesting, thanks for pointing out that this used to occur in VS Code insiders, I wonder what changed.

Does this occur on smaller projects, for example a simple hello world?

@hyangah any idea for how to investigate this?

yiminmv commented 1 year ago

@findleyr, the issue also appears in a minimal hello world project.

findleyr commented 1 year ago

Thanks @yiminmv, I missed your final paragraph (which @hyangah caught) where you talk about how the location of the gopls binary matters. This is a critical observation (thanks!) that indicates some sort of security hardening that we were unaware of. Hana filed microsoft/vscode-remote-release#9011 to escalate this to the VS Code team.

yiminmv commented 1 year ago

Hi, I think there may have some misunderstandings, I'd like to highlight the main point of my video:

  1. When gopls is located within my GOPATH (/go/bin/), allowing the Go extension to detect it, the extension crashes.
  2. Moving gopls outside of the GOPATH results in the Go extension working again but with the warning 'gopls not found'.

I'm not certain this is related to a security issue, but the behavior with gopls positioning and the Go extension's response is consistently reproducible based on my tests. The video was intended to demonstrate these specific behaviors.

Besides, specifying an alternative path for gopls using go.alternativeTools leads to a longer delay before the extension crashes and I've also observed installing godef (no gopls installed) makes the Go extension unstable, leading it to crash eventually.

findleyr commented 12 months ago

Hi @yiminmv thanks for clarifying, and sorry for the misunderstanding.

Could you try running gopls as a daemon from a terminal? This will help us narrow down whether the problem is related to resource usage of the gopls subprocess (and will also make it easier to see any output produced by gopls).

This will make the gopls subprocess started by VS Code a thin proxy that sends requests to the gopls daemon. I am curious if that resolves the issue, and if you see any additional output from your terminal.

amitroshin commented 12 months ago

Hi @findleyr. I'm not @yiminmv but I've tried this trick. Nothing changed.

On the remote machine:

#gopls -listen=localhost:8091 -vv
serve.go:132: Gopls daemon: listening on tcp network, address localhost:58091...
lsprpc.go:104: Session 1: connected
lsprpc.go:482: Session 1: got handshake. Logfile: "", Debug addr: ""
lsprpc.go:108: Session 1: exited
lsprpc.go:104: Session 2: connected
lsprpc.go:482: Session 2: got handshake. Logfile: "", Debug addr: ""
lsprpc.go:108: Session 2: exited
lsprpc.go:104: Session 3: connected
lsprpc.go:482: Session 3: got handshake. Logfile: "", Debug addr: ""
lsprpc.go:108: Session 3: exited

The settings.json:

{
    "remote.SSH.useExecServer": true,
    "go.useLanguageServer": true,
    "go.languageServerFlags": [
        "-remote=localhost:8091"
    ]
}

Earlier I tried to use a log file with -logfile= and -rpc.trace flag. I've get log file and it seems gopls stops immediately after the first response to it`s first message.

hyangah commented 11 months ago

Unfortunately I could not reproduce the issue myself :-( - I tried with the devcontainer (built by microsoft 13days ago) and with remote vscode server (Remote-SSH, freshly setup & started). Is there anyway for us to reproduce this?

Another thing to try is to restart the remote server (to rule out version skew, ...) e.g. "Remote-SSH: Kill Current VS Code Server". And, are there any other logs (visible from the output channel, or $HOME/.vscode-server/data/logs?

hyangah commented 11 months ago

@yiminmv @amitroshin Did the console page in the developer tools ("Developer: Toggle Developer Tools" from the command palette) show any error messages when the extension host crashed?

amitroshin commented 11 months ago

Yes. It shows some error messages. Here is on the screenshot.

image image

I'm sorry but I couldn't find an option to save the console log as a file.

yiminmv commented 11 months ago
INFO [remote-connection][ExtensionHost][006d0…][reconnect] received socket timeout event (unacknowledgedMsgCount: 41, timeSinceOldestUnacknowledgedMsg: 20005, timeSinceLastReceivedSomeData: 20005).
log.ts:421  INFO [remote-connection][ExtensionHost][006d0…][reconnect] starting reconnecting loop. You can get more information with the trace log level.
log.ts:421  INFO [remote-connection][ExtensionHost][006d0…][reconnect] resolving connection...
log.ts:421  INFO [remote-connection][ExtensionHost][006d0…][reconnect] connecting to Managed(1)...
log.ts:401 TRACE [remote-connection][ExtensionHost][006d0…][reconnect][Managed(1)] 1/6. invoking socketFactory.connect().
log.ts:421  INFO Creating a socket (renderer-ExtensionHost-006d0ba2-2481-4512-9c50-9f3510822394)...
log.ts:421  INFO Creating a socket (renderer-ExtensionHost-006d0ba2-2481-4512-9c50-9f3510822394) was successful after 43 ms.
log.ts:401 TRACE [remote-connection][ExtensionHost][006d0…][reconnect][Managed(1)] 2/6. socketFactory.connect() was successful.
log.ts:401 TRACE [remote-connection][ExtensionHost][006d0…][reconnect][Managed(1)] 3/6. sending AuthRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][006d0…][reconnect][Managed(1)] 4/6. received SignRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][006d0…][reconnect][Managed(1)] 5/6. sending ConnectionTypeRequest control message.
log.ts:441   ERR [remote-connection][ExtensionHost][006d0…][reconnect][Managed(1)] received error control message when negotiating connection. Error:
log.ts:441   ERR Error: Connection error: Unknown reconnection token (seen before)
    at x (remoteAgentConnection.ts:785:17)
    at u.value (remoteAgentConnection.ts:328:17)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at b.z (ipc.net.ts:1021:28)
    at u.value (ipc.net.ts:955:72)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at u.acceptChunk (ipc.net.ts:394:21)
    at u.value (ipc.net.ts:350:51)
    at l.z (event.ts:1138:13)
    at l.fire (event.ts:1169:9)
    at l.fire (event.ts:1335:11)
    at u.value (managedSocket.ts:108:69)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at C.$onDidManagedSocketHaveData (mainThreadManagedSockets.ts:77:45)
    at m.S (rpcProtocol.ts:456:17)
    at m.Q (rpcProtocol.ts:441:32)
    at m.M (rpcProtocol.ts:371:19)
    at m.L (rpcProtocol.ts:306:10)
    at u.value (rpcProtocol.ts:161:42)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at Y.onmessage (localProcessExtensionHost.ts:581:40)
log.ts:441   ERR [remote-connection][ExtensionHost][006d0…][reconnect] A permanent error occurred in the reconnecting loop! Will give up now! Error:
log.ts:441   ERR Error: Connection error: Unknown reconnection token (seen before)
    at x (remoteAgentConnection.ts:785:17)
    at u.value (remoteAgentConnection.ts:328:17)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at b.z (ipc.net.ts:1021:28)
    at u.value (ipc.net.ts:955:72)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at u.acceptChunk (ipc.net.ts:394:21)
    at u.value (ipc.net.ts:350:51)
    at l.z (event.ts:1138:13)
    at l.fire (event.ts:1169:9)
    at l.fire (event.ts:1335:11)
    at u.value (managedSocket.ts:108:69)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at C.$onDidManagedSocketHaveData (mainThreadManagedSockets.ts:77:45)
    at m.S (rpcProtocol.ts:456:17)
    at m.Q (rpcProtocol.ts:441:32)
    at m.M (rpcProtocol.ts:371:19)
    at m.L (rpcProtocol.ts:306:10)
    at u.value (rpcProtocol.ts:161:42)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at Y.onmessage (localProcessExtensionHost.ts:581:40)
abstractExtensionService.ts:784 Extension host (Remote) terminated unexpectedly. Code: 0, Signal: 006d0ba2-2481-4512-9c50-9f3510822394
yb @ abstractExtensionService.ts:784
yb @ nativeExtensionService.ts:166
xb @ abstractExtensionService.ts:776
(anonymous) @ abstractExtensionService.ts:754
z @ event.ts:1138
fire @ event.ts:1169
D @ remoteExtensionHost.ts:199
(anonymous) @ remoteExtensionHost.ts:133
z @ event.ts:1138
fire @ event.ts:1169
fire @ ipc.net.ts:650
acceptDisconnect @ ipc.net.ts:979
U @ remoteAgentConnection.ts:774
D @ remoteAgentConnection.ts:729
C @ remoteAgentConnection.ts:723
z @ remoteAgentConnection.ts:677
await in z (async)
y @ remoteAgentConnection.ts:628
(anonymous) @ remoteAgentConnection.ts:600
z @ event.ts:1138
fire @ event.ts:1169
fire @ ipc.net.ts:650
B @ ipc.net.ts:1144
(anonymous) @ ipc.net.ts:1162
setTimeout (async)
B @ ipc.net.ts:1160
(anonymous) @ ipc.net.ts:1162
log.ts:441   ERR Extension host (Remote) terminated unexpectedly with code null.
log.ts:441   ERR Extension host (Remote) terminated unexpectedly. The following extensions were running: golang.go, vscode.emmet
log.ts:421  INFO Automatically restarting the remote extension host.
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][initial][Managed(1)] 1/6. invoking socketFactory.connect().
log.ts:421  INFO Creating a socket (renderer-ExtensionHost-56a131cc-4645-41fe-bf3a-03d1c8f24aac)...
log.ts:421  INFO Creating a socket (renderer-ExtensionHost-56a131cc-4645-41fe-bf3a-03d1c8f24aac) was successful after 40 ms.
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][initial][Managed(1)] 2/6. socketFactory.connect() was successful.
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][initial][Managed(1)] 3/6. sending AuthRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][initial][Managed(1)] 4/6. received SignRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][initial][Managed(1)] 5/6. sending ConnectionTypeRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][initial][Managed(1)] 6/6. handshake finished, connection is up and running after 81 ms!
log.ts:401 TRACE CommandService#executeCommand _setContext
log.ts:421  INFO [remote-connection][ExtensionHost][56a13…][reconnect] received socket timeout event (unacknowledgedMsgCount: 1, timeSinceOldestUnacknowledgedMsg: 20005, timeSinceLastReceivedSomeData: 66402).
log.ts:421  INFO [remote-connection][ExtensionHost][56a13…][reconnect] starting reconnecting loop. You can get more information with the trace log level.
log.ts:421  INFO [remote-connection][ExtensionHost][56a13…][reconnect] resolving connection...
log.ts:421  INFO [remote-connection][ExtensionHost][56a13…][reconnect] connecting to Managed(1)...
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][reconnect][Managed(1)] 1/6. invoking socketFactory.connect().
log.ts:421  INFO Creating a socket (renderer-ExtensionHost-56a131cc-4645-41fe-bf3a-03d1c8f24aac)...
log.ts:421  INFO Creating a socket (renderer-ExtensionHost-56a131cc-4645-41fe-bf3a-03d1c8f24aac) was successful after 45 ms.
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][reconnect][Managed(1)] 2/6. socketFactory.connect() was successful.
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][reconnect][Managed(1)] 3/6. sending AuthRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][reconnect][Managed(1)] 4/6. received SignRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][56a13…][reconnect][Managed(1)] 5/6. sending ConnectionTypeRequest control message.
log.ts:441   ERR [remote-connection][ExtensionHost][56a13…][reconnect][Managed(1)] received error control message when negotiating connection. Error:
log.ts:441   ERR Error: Connection error: Unknown reconnection token (seen before)
    at x (remoteAgentConnection.ts:785:17)
    at u.value (remoteAgentConnection.ts:328:17)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at b.z (ipc.net.ts:1021:28)
    at u.value (ipc.net.ts:955:72)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at u.acceptChunk (ipc.net.ts:394:21)
    at u.value (ipc.net.ts:350:51)
    at l.z (event.ts:1138:13)
    at l.fire (event.ts:1169:9)
    at l.fire (event.ts:1335:11)
    at u.value (managedSocket.ts:108:69)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at C.$onDidManagedSocketHaveData (mainThreadManagedSockets.ts:77:45)
    at m.S (rpcProtocol.ts:456:17)
    at m.Q (rpcProtocol.ts:441:32)
    at m.M (rpcProtocol.ts:371:19)
    at m.L (rpcProtocol.ts:306:10)
    at u.value (rpcProtocol.ts:161:42)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at Y.onmessage (localProcessExtensionHost.ts:581:40)
log.ts:441   ERR [remote-connection][ExtensionHost][56a13…][reconnect] A permanent error occurred in the reconnecting loop! Will give up now! Error:
log.ts:441   ERR Error: Connection error: Unknown reconnection token (seen before)
    at x (remoteAgentConnection.ts:785:17)
    at u.value (remoteAgentConnection.ts:328:17)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at b.z (ipc.net.ts:1021:28)
    at u.value (ipc.net.ts:955:72)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at u.acceptChunk (ipc.net.ts:394:21)
    at u.value (ipc.net.ts:350:51)
    at l.z (event.ts:1138:13)
    at l.fire (event.ts:1169:9)
    at l.fire (event.ts:1335:11)
    at u.value (managedSocket.ts:108:69)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at C.$onDidManagedSocketHaveData (mainThreadManagedSockets.ts:77:45)
    at m.S (rpcProtocol.ts:456:17)
    at m.Q (rpcProtocol.ts:441:32)
    at m.M (rpcProtocol.ts:371:19)
    at m.L (rpcProtocol.ts:306:10)
    at u.value (rpcProtocol.ts:161:42)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at Y.onmessage (localProcessExtensionHost.ts:581:40)
abstractExtensionService.ts:784 Extension host (Remote) terminated unexpectedly. Code: 0, Signal: 56a131cc-4645-41fe-bf3a-03d1c8f24aac
yb @ abstractExtensionService.ts:784
yb @ nativeExtensionService.ts:166
xb @ abstractExtensionService.ts:776
(anonymous) @ abstractExtensionService.ts:754
z @ event.ts:1138
fire @ event.ts:1169
D @ remoteExtensionHost.ts:199
(anonymous) @ remoteExtensionHost.ts:133
z @ event.ts:1138
fire @ event.ts:1169
fire @ ipc.net.ts:650
acceptDisconnect @ ipc.net.ts:979
U @ remoteAgentConnection.ts:774
D @ remoteAgentConnection.ts:729
C @ remoteAgentConnection.ts:723
z @ remoteAgentConnection.ts:677
await in z (async)
y @ remoteAgentConnection.ts:628
(anonymous) @ remoteAgentConnection.ts:600
z @ event.ts:1138
fire @ event.ts:1169
fire @ ipc.net.ts:650
B @ ipc.net.ts:1144
(anonymous) @ ipc.net.ts:1162
setTimeout (async)
B @ ipc.net.ts:1160
send @ ipc.net.ts:1071
U @ rpcProtocol.ts:492
A.<computed>.V.charCodeAt.A.<computed> @ rpcProtocol.ts:254
z @ event.ts:1138
A @ event.ts:1149
fire @ event.ts:1173
(anonymous) @ userActivityService.ts:43
h @ async.ts:979
g @ async.ts:974
setTimeout (async)
schedule @ async.ts:946
(anonymous) @ userActivityService.ts:76
(anonymous) @ lifecycle.ts:351
(anonymous) @ functional.ts:20
set value @ lifecycle.ts:525
clear @ lifecycle.ts:536
i @ domActivityTracker.ts:42
(anonymous) @ async.ts:903
log.ts:441   ERR Extension host (Remote) terminated unexpectedly with code null.
log.ts:441   ERR Extension host (Remote) terminated unexpectedly. The following extensions were running: golang.go, vscode.emmet
log.ts:421  INFO Automatically restarting the remote extension host.
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][initial][Managed(1)] 1/6. invoking socketFactory.connect().
log.ts:421  INFO Creating a socket (renderer-ExtensionHost-6b39bf1e-7f02-4007-a526-691b59ac8836)...
log.ts:421  INFO Creating a socket (renderer-ExtensionHost-6b39bf1e-7f02-4007-a526-691b59ac8836) was successful after 42 ms.
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][initial][Managed(1)] 2/6. socketFactory.connect() was successful.
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][initial][Managed(1)] 3/6. sending AuthRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][initial][Managed(1)] 4/6. received SignRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][initial][Managed(1)] 5/6. sending ConnectionTypeRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][initial][Managed(1)] 6/6. handshake finished, connection is up and running after 100 ms!
log.ts:401 TRACE CommandService#executeCommand _setContext
log.ts:421  INFO [remote-connection][ExtensionHost][6b39b…][reconnect] received socket timeout event (unacknowledgedMsgCount: 1, timeSinceOldestUnacknowledgedMsg: 20049, timeSinceLastReceivedSomeData: 39935).
log.ts:421  INFO [remote-connection][ExtensionHost][6b39b…][reconnect] starting reconnecting loop. You can get more information with the trace log level.
log.ts:421  INFO [remote-connection][ExtensionHost][6b39b…][reconnect] resolving connection...
log.ts:421  INFO [remote-connection][ExtensionHost][6b39b…][reconnect] connecting to Managed(1)...
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][reconnect][Managed(1)] 1/6. invoking socketFactory.connect().
log.ts:421  INFO Creating a socket (renderer-ExtensionHost-6b39bf1e-7f02-4007-a526-691b59ac8836)...
log.ts:421  INFO Creating a socket (renderer-ExtensionHost-6b39bf1e-7f02-4007-a526-691b59ac8836) was successful after 39 ms.
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][reconnect][Managed(1)] 2/6. socketFactory.connect() was successful.
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][reconnect][Managed(1)] 3/6. sending AuthRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][reconnect][Managed(1)] 4/6. received SignRequest control message.
log.ts:401 TRACE [remote-connection][ExtensionHost][6b39b…][reconnect][Managed(1)] 5/6. sending ConnectionTypeRequest control message.
log.ts:441   ERR [remote-connection][ExtensionHost][6b39b…][reconnect][Managed(1)] received error control message when negotiating connection. Error:
log.ts:441   ERR Error: Connection error: Unknown reconnection token (seen before)
    at x (remoteAgentConnection.ts:785:17)
    at u.value (remoteAgentConnection.ts:328:17)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at b.z (ipc.net.ts:1021:28)
    at u.value (ipc.net.ts:955:72)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at u.acceptChunk (ipc.net.ts:394:21)
    at u.value (ipc.net.ts:350:51)
    at l.z (event.ts:1138:13)
    at l.fire (event.ts:1169:9)
    at l.fire (event.ts:1335:11)
    at u.value (managedSocket.ts:108:69)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at C.$onDidManagedSocketHaveData (mainThreadManagedSockets.ts:77:45)
    at m.S (rpcProtocol.ts:456:17)
    at m.Q (rpcProtocol.ts:441:32)
    at m.M (rpcProtocol.ts:371:19)
    at m.L (rpcProtocol.ts:306:10)
    at u.value (rpcProtocol.ts:161:42)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at Y.onmessage (localProcessExtensionHost.ts:581:40)
log.ts:441   ERR [remote-connection][ExtensionHost][6b39b…][reconnect] A permanent error occurred in the reconnecting loop! Will give up now! Error:
log.ts:441   ERR Error: Connection error: Unknown reconnection token (seen before)
    at x (remoteAgentConnection.ts:785:17)
    at u.value (remoteAgentConnection.ts:328:17)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at b.z (ipc.net.ts:1021:28)
    at u.value (ipc.net.ts:955:72)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at u.acceptChunk (ipc.net.ts:394:21)
    at u.value (ipc.net.ts:350:51)
    at l.z (event.ts:1138:13)
    at l.fire (event.ts:1169:9)
    at l.fire (event.ts:1335:11)
    at u.value (managedSocket.ts:108:69)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at C.$onDidManagedSocketHaveData (mainThreadManagedSockets.ts:77:45)
    at m.S (rpcProtocol.ts:456:17)
    at m.Q (rpcProtocol.ts:441:32)
    at m.M (rpcProtocol.ts:371:19)
    at m.L (rpcProtocol.ts:306:10)
    at u.value (rpcProtocol.ts:161:42)
    at c.z (event.ts:1138:13)
    at c.fire (event.ts:1169:9)
    at r.fire (ipc.net.ts:650:19)
    at Y.onmessage (localProcessExtensionHost.ts:581:40)
abstractExtensionService.ts:784 Extension host (Remote) terminated unexpectedly. Code: 0, Signal: 6b39bf1e-7f02-4007-a526-691b59ac8836
yb @ abstractExtensionService.ts:784
yb @ nativeExtensionService.ts:166
xb @ abstractExtensionService.ts:776
(anonymous) @ abstractExtensionService.ts:754
z @ event.ts:1138
fire @ event.ts:1169
D @ remoteExtensionHost.ts:199
(anonymous) @ remoteExtensionHost.ts:133
z @ event.ts:1138
fire @ event.ts:1169
fire @ ipc.net.ts:650
acceptDisconnect @ ipc.net.ts:979
U @ remoteAgentConnection.ts:774
D @ remoteAgentConnection.ts:729
C @ remoteAgentConnection.ts:723
z @ remoteAgentConnection.ts:677
await in z (async)
y @ remoteAgentConnection.ts:628
(anonymous) @ remoteAgentConnection.ts:600
z @ event.ts:1138
fire @ event.ts:1169
fire @ ipc.net.ts:650
B @ ipc.net.ts:1144
(anonymous) @ ipc.net.ts:1162
setTimeout (async)
B @ ipc.net.ts:1160
send @ ipc.net.ts:1071
U @ rpcProtocol.ts:492
A.<computed>.V.charCodeAt.A.<computed> @ rpcProtocol.ts:254
z @ event.ts:1138
fire @ event.ts:1169
(anonymous) @ event.ts:152
z @ event.ts:1138
A @ event.ts:1149
fire @ event.ts:1173
(anonymous) @ event.ts:152
(anonymous) @ event.ts:169
z @ event.ts:1138
fire @ event.ts:1169
(anonymous) @ event.ts:118
z @ event.ts:1138
fire @ event.ts:1169
(anonymous) @ event.ts:152
z @ event.ts:1138
fire @ event.ts:1169
J @ ipc.ts:675
t @ ipc.ts:743
s @ ipc.ts:732
(anonymous) @ ipc.ts:549
z @ event.ts:1138
A @ event.ts:1149
fire @ event.ts:1173
he @ event.ts:559
emit @ VM614 sandbox_bundle:2
onMessage @ VM614 sandbox_bundle:2
log.ts:441   ERR Extension host (Remote) terminated unexpectedly with code null.
log.ts:441   ERR Extension host (Remote) terminated unexpectedly. The following extensions were running: golang.go, vscode.emmet
notificationsAlerts.ts:42 Remote Extension host terminated unexpectedly 3 times within the last 5 minutes.

I encountered error messages similar to those @amitroshin reported. I googled for the cause of the received error control message when negotiating connection, I think that it might be related to vscode-remote-release.

hyangah commented 11 months ago

Thanks. Unfortunately, I am still at a loss. I updated my issue https://github.com/microsoft/vscode-remote-release/issues/9011. I see various crash reports related to remote extension in the vscode issue tracker and the vscode-remote-release issue tracker. I wonder if anyone happened to try old vscode or recall when this problem started to appear. VS Code Go extension didn't release a new version for quite some time. :-(

amitroshin commented 11 months ago

So due to investigate Lang server crashes I made one more remote machine on another HV and it seems language server works fine there.

Now my development setup looks like this:

Local host with the VSCode:

Windows 11 22H2 host with OpenSSH_for_Windows_8.6p1, LibreSSL 3.4.3., latest VS Code and Go Extension.

First remote host (remote extension host crashes continuously):

VMware ESXi, 7.0.0, 16324942 Intel(R) Xeon(R) Gold 6238R CPU Guest OS Ubuntu 22.04.3.

Second remote host (remote extension host crashes continuously):

VMware ESXi, 7.0.0, 16324942 Intel(R) Xeon(R) Gold 6238R CPU Guest OS Oracle linux 9

Third remote host (remote extension host with gopls works fine):

VMware ESXi, 6.7.0, 8169922 Intel(R) Xeon(R) CPU X5650 Guest OS Ubuntu 22.04.3

Maybe the issue related to hypervisor version or set of CPU extended instructions? I think it maybe because in dmesg output on first and second remote hosts I can see lines like this when the remote extension host crashes:

traps: node[122553] trap invalid opcode ip:1d4ed2c sp:7ffdee05d7c0 error:0 in node[400000+4c51000]
amitroshin commented 11 months ago

A little update to my previous message here. Here is the very interesting thing. I've migrated my First remote machine to the another VMWare node in the same VSphere cluster by live migration. After that I shutdown and power on the guest machine again.

And now I can see that the Remote extension host works fine with Go Language Server.

The new VMWare node is VMware ESXi, 7.0.3, 18644231, Intel(R) Xeon(R) Gold 6240R CPU. I hope my experiments will help to find out the cause of the issue with Remote extension host crashes. If you have any idea what I can do more to help feel free to ask me.

hyangah commented 11 months ago

Thanks @amitroshin for the detailed investigation.

traps: node[122553] trap invalid opcode ip:1d4ed2c sp:7ffdee05d7c0 error:0 in node[400000+4c51000]

Doesn't it imply either the electron or the nodejs used in the extension host had an issue? I think there were some issues like crash in 1.82.0 that required the vscode to update the node version. VS Code 1.83 was just released. Can you please try the newest version of vscode and see if it helps? @yiminmv

amitroshin commented 11 months ago

Hello @hyangah! I`ve repeated a try before upgrade VSCode and after upgrade to v.1.83.0. And got the same behavior of the remote host crashes. But it seems version of Node.js was not changed in the new version of the VSCode. So now I'm pretty sure that the problem strongly depends on VMWare version or CPU model. Hope you paid attention to my two previous comments. I managed to solve my local problem when I just migrate the same linux host to another physical server in the same vSphere cluster.

VSCode before update:

Version: 1.82.3 (user setup)
Commit: fdb98833154679dbaa7af67a5a29fe19e55c2b73
Date: 2023-10-02T10:51:22.294Z
Electron: 25.8.1
ElectronBuildId: 24153832
Chromium: 114.0.5735.289
Node.js: 18.15.0
V8: 11.4.183.29-electron.0
OS: Windows_NT x64 10.0.22621

The same crashes reproduced when Language server turned on.

[1222210.009585] traps: node[664828] trap invalid opcode ip:1d4ed2c sp:7ffe015a4580 error:0 in node[400000+4c51000]
[1222228.811165] traps: node[665281] trap invalid opcode ip:1d4ed2c sp:7fff009658a0 error:0 in node[400000+4c51000]
[1222249.634576] traps: node[665482] trap invalid opcode ip:1d4ed2c sp:7ffcbfb7ea00 error:0 in node[400000+4c51000]

VSCode after update:

Version: 1.83.0 (user setup)
Commit: e7e037083ff4455cf320e344325dacb480062c3c
Date: 2023-10-03T16:12:16.321Z
Electron: 25.8.4
ElectronBuildId: 24154031
Chromium: 114.0.5735.289
Node.js: 18.15.0
V8: 11.4.183.29-electron.0
OS: Windows_NT x64 10.0.22621

The same crashes reproduced when Language server turned on.

[1222270.477508] traps: node[665611] trap invalid opcode ip:1d4ed2c sp:7ffdbc8acda0 error:0 in node[400000+4c51000]
[1222388.417475] traps: node[665955] trap invalid opcode ip:1d4ed2c sp:7ffc93443580 error:0 in node[400000+4c51000]
[1222409.264124] traps: node[666222] trap invalid opcode ip:1d4ed2c sp:7ffe2e2479e0 error:0 in node[400000+4c51000]
hyangah commented 11 months ago

@amitroshin Thanks for checking the vscode version. It's unfortunate. The node/electron version updates were in 1.82.2, so it seems they didn't help for this case. As I said based on your latest comments (I paid attention to your last comments :-), this looks like an issue outside this extension or gopls. The observation here indicates running the gopls remote server was ok so the go program was ok. The observation with godef here also indicates, it's not only the lsp side.

@yiminmv If possible, please update or change the remote machine as @amitroshin shared. If it's not possible or your remote host machine setup is not like @amitroshin's, I strongly recommend filing an issue to github.com/microsoft/vscode issue tracker.

yiminmv commented 11 months ago

Hello,

I've tried migrating my virtual machine on vSphere, but the issue I encountered still exists. Given that there's no new feedback or suggestions at this time, I've decided to close this ticket for now.

Should there be any new recommendations or solutions in the future, I'll consider reopening the issue. Thanks.