Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

x/tools/gopls: gopls becomes unresponsive from time to time #61969

Closed
dppascual opened this issue Aug 11, 2023 · 16 comments
Closed

x/tools/gopls: gopls becomes unresponsive from time to time #61969

dppascual opened this issue Aug 11, 2023 · 16 comments
Labels
gopls Issues related to the Go language server, gopls. Tools This label describes issues relating to any tools in the x/tools repository.
Milestone
gopls/v0.14.0

Comments

@dppascual
Copy link

gopls version

Build info
----------
golang.org/x/tools/gopls v0.13.1
    golang.org/x/tools/gopls@v0.13.1 h1:Q0cfPbEG1WVfgxcRZ9uKTA6/ckIRNXx6Ym7KgT/VFE4=
    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.20230801165449-23c7f589706c h1:YilyjKn3EDn6X+x+kP+4REeEtG3WeM52dJAr7AWzVrQ=
    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

go env

GO111MODULE="on"
GOARCH="amd64"
GOBIN="/Users/dppascual/go/bin"
GOCACHE="/Users/dppascual/Library/Caches/go-build"
GOENV="/Users/dppascual/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/dppascual/go/pkg/mod"
GONOPROXY="*.bbva.com,*.igrupobbva"
GONOSUMDB="*.bbva.com,*.igrupobbva"
GOOS="darwin"
GOPATH="/Users/dppascual/go"
GOPRIVATE="*.bbva.com,*.igrupobbva"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.19"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/dppascual/projects/work/bbva/titan/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 -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/zg/tz2xtl3138bfl888yv2gc_600000gn/T/go-build818485392=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I haven't found any solid pattern yet that evidences why it is happening, but I have a vague feeling that it could be caused by any condition when code actions are requested. I had to disable the plugin `https://github.com/kosayoda/nvim-lightbulb' (basically, it shows a lightbulb whenever a code action is available at the current cursor position) because it was causing such anomaly happened more frequently.

Also, I have configured an autocommand that execute the code action organize imports each time the file is saved. This action has been always executed when the anomaly comes up, but it doesn't mean the anomaly happens every time the action is executed.

 vim.api.nvim_create_autocmd('BufWritePre', {
                        group = vim.api.nvim_create_augroup( 'GoFormatting', { clear = true }
                        ),
                        pattern = '*.go',
                        callback = function()
                            local params = vim.lsp.util.make_range_params()
                            params.context =
                                { only = { 'source.organizeImports' } }
                            local result = vim.lsp.buf_request_sync(
                                0,
                                'textDocument/codeAction',
                                params,
                                2000
                            )
                            for _, res in pairs(result or {}) do
                                for _, r in pairs(res.result or {}) do
                                    if r.edit then
                                        vim.lsp.util.apply_workspace_edit(
                                            r.edit,
                                            'utf-16'
                                        )
                                    else
                                        vim.lsp.buf.execute_command(r.command)
                                    end
                                end
                            end

                            vim.lsp.buf.format()
                        end,
                    })

What did you expect to see?

The server gopls should send back a response for every method requested by the client.

What did you see instead?

When it happens, completions|diagnostics|code actions stop working for a while (30 seconds or so, and sometimes, even minutes). The editor shows up the following message Server for client 'gopls' not yet ready!

Editor and settings

Editor:

nvim -v                                                                                                                              
NVIM v0.10.0-dev-666+g516b17378
Build type: Release
LuaJIT 2.1.0-beta3
Run "nvim -V1 -v" for more info

gopls:

    {
        'neovim/nvim-lspconfig',
        opts = {
            servers = {
                gopls = {
                    -- cmd = { 'gopls', '-rpc.trace' },
                    settings = {
                        gopls = {
                            usePlaceholders = true,
                            gofumpt = true,
                            analyses = {
                                fieldalignment = true,
                                nilness = true,
                                unusedparams = true,
                                unusedwrite = true,
                                useany = true,
                                deprecated = true,
                            },
                            codelenses = {
                                gc_details = false,
                                generate = true,
                                regenerate_cgo = true,
                                run_govulncheck = true,
                                test = true,
                                tidy = true,
                                upgrade_dependency = true,
                                vendor = true,
                            },
                            experimentalPostfixCompletions = true,
                            completeUnimported = true,
                            staticcheck = true,
                            directoryFilters = { '-.git', '-node_modules' },
                            semanticTokens = true,
                            hints = {
                                assignVariableTypes = true,
                                compositeLiteralFields = true,
                                compositeLiteralTypes = true,
                                constantValues = true,
                                functionTypeParameters = true,
                                parameterNames = true,
                                rangeVariableTypes = true,
                            },
                        },
                    },
                },
            },
            setup = {
                gopls = function(_, opts)
                    -- workaround for gopls not supporting semanticTokensProvider
                    -- https://github.com/golang/go/issues/54531#issuecomment-1464982242
                    -- stylua: ignore
                    vim.api.nvim_create_autocmd("LspAttach", {
                        callback = function(ev)
                            local client = vim.lsp.get_client_by_id(ev.data.client_id)
                            if client.name == 'gopls' then
                                if
                                    not client.server_capabilities.semanticTokensProvider
                                then
                                    local semantic =
                                    client.config.capabilities.textDocument.semanticTokens
                                    client.server_capabilities.semanticTokensProvider =
                                    {
                                        full = true,
                                        legend = {
                                            tokenTypes = semantic.tokenTypes,
                                            tokenModifiers = semantic.tokenModifiers,
                                        },
                                        range = true,
                                    }
                                end
                            end
                        end
                    })-- end workaround

                    -- Run gofmt/gofumpt, import packages automatically on save
                    -- stylua: ignore
                    vim.api.nvim_create_autocmd('BufWritePre', {
                        group = vim.api.nvim_create_augroup( 'GoFormatting', { clear = true }
                        ),
                        pattern = '*.go',
                        callback = function()
                            local params = vim.lsp.util.make_range_params()
                            params.context =
                                { only = { 'source.organizeImports' } }
                            local result = vim.lsp.buf_request_sync(
                                0,
                                'textDocument/codeAction',
                                params,
                                2000
                            )
                            for _, res in pairs(result or {}) do
                                for _, r in pairs(res.result or {}) do
                                    if r.edit then
                                        vim.lsp.util.apply_workspace_edit(
                                            r.edit,
                                            'utf-16'
                                        )
                                    else
                                        vim.lsp.buf.execute_command(r.command)
                                    end
                                end
                            end

                            vim.lsp.buf.format()
                        end,
                    })
                end,
            },
        },
    },

Logs

[ERROR][2023-08-11 12:39:49] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:49.967 PM] Sending notification 'workspace/didChangeWatchedFiles'.\nParams: {\"changes\":[{\"type\":1,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}]}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:50] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:50.109 PM] Sending request 'textDocument/codeLens - (1040)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:50] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:50.109 PM] Sending request 'textDocument/documentHighlight - (1041)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":23}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:50] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:50.852 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1037}\r\n\r\n\r\n[Trace - 12:39:50.852 PM] Sending request 'textDocument/documentHighlight - (1042)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":37,\"character\":26}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:50] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:50.959 PM] Sending request 'textDocument/documentHighlight - (1043)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":37,\"character\":26}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:51] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:51.045 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1042}\r\n\r\n\r\n[Trace - 12:39:51.045 PM] Sending request 'textDocument/documentHighlight - (1044)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":23}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:51] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:51.151 PM] Sending request 'textDocument/documentHighlight - (1045)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":23}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:51] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:51.584 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1044}\r\n\r\n\r\n[Trace - 12:39:51.585 PM] Sending request 'textDocument/documentHighlight - (1046)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":23}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:51] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:51.959 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1046}\r\n\r\n\r\n[Trace - 12:39:51.959 PM] Sending request 'textDocument/documentHighlight - (1047)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":23}}\r\n\r\n\r\n[Trace - 12:39:51.961 PM] Sending request 'textDocument/codeAction - (1048)'.\nParams: {\"context\":{\"only\":[\"source.organizeImports\"]},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"range\":{\"start\":{\"line\":38,\"character\":23},\"end\":{\"line\":38,\"character\":23}}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:54] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:54.093 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1048}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:54] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:54.093 PM] Sending request 'textDocument/formatting - (1049)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"options\":{\"insertSpaces\":false,\"tabSize\":4}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:55] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:55.153 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1049}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:39:55] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:39:55.164 PM] Sending notification 'textDocument/didSave'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:11] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:11.313 PM] Sending notification 'workspace/didChangeWatchedFiles'.\nParams: {\"changes\":[{\"type\":1,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}]}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:11] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:11.460 PM] Sending request 'textDocument/documentHighlight - (1050)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":23}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:16] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:16.138 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1047}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:16] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:16.138 PM] Sending request 'textDocument/documentHighlight - (1051)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":23}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:17] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:17.871 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1051}\r\n\r\n\r\n[Trace - 12:40:17.871 PM] Sending request 'textDocument/documentHighlight - (1052)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":10}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:18] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:18.761 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":175,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":10},\"end\":{\"line\":38,\"character\":24}},\"rangeLength\":14,\"text\":\"\"}]}\r\n\r\n\r\n[Trace - 12:40:18.761 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1052}\r\n\r\n\r\n[Trace - 12:40:18.761 PM] Sending request 'textDocument/documentHighlight - (1053)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":10}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:18] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:18.769 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1053}\r\n\r\n\r\n[Trace - 12:40:18.769 PM] Sending request 'textDocument/documentHighlight - (1054)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":10}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:18] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:18.887 PM] Sending request 'textDocument/documentHighlight - (1055)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":10}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:18] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:18.965 PM] Sending request 'textDocument/semanticTokens/full - (1056)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:19] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:19.367 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":176,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":10},\"end\":{\"line\":38,\"character\":10}},\"rangeLength\":0,\"text\":\"j\"}]}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:19] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:19.367 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1054}\r\n\r\n\r\n[Trace - 12:40:19.368 PM] Sending request 'textDocument/documentHighlight - (1057)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":11}}\r\n\r\n\r\n[Trace - 12:40:19.370 PM] Sending request 'textDocument/completion - (1058)'.\nParams: {\"context\":{\"triggerKind\":1},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":11}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:19] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:19.485 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1057}\r\n\r\n\r\n[Trace - 12:40:19.485 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":177,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":11},\"end\":{\"line\":38,\"character\":11}},\"rangeLength\":0,\"text\":\"s\"}]}\r\n\r\n\r\n[Trace - 12:40:19.485 PM] Sending request 'textDocument/documentHighlight - (1059)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":12}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:19] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:19.603 PM] Sending request 'textDocument/documentHighlight - (1060)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":12}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:19] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:19.636 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":178,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":12},\"end\":{\"line\":38,\"character\":12}},\"rangeLength\":0,\"text\":\"o\"}]}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:19] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:19.636 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1059}\r\n\r\n\r\n[Trace - 12:40:19.637 PM] Sending request 'textDocument/documentHighlight - (1061)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":13}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:19] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:19.742 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1061}\r\n\r\n\r\n[Trace - 12:40:19.742 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":179,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":13},\"end\":{\"line\":38,\"character\":13}},\"rangeLength\":0,\"text\":\"n\"}]}\r\n\r\n\r\n[Trace - 12:40:19.742 PM] Sending request 'textDocument/documentHighlight - (1062)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":14}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:19] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:19.858 PM] Sending request 'textDocument/documentHighlight - (1063)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":14}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:19] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:19.942 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1056}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:19] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:19.942 PM] Sending request 'textDocument/semanticTokens/full - (1064)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:20] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:20.056 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":180,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":14},\"end\":{\"line\":38,\"character\":14}},\"rangeLength\":0,\"text\":\".\"}]}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:20] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:20.057 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1062}\r\n\r\n\r\n[Trace - 12:40:20.057 PM] Sending request 'textDocument/documentHighlight - (1065)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":15}}\r\n\r\n\r\n[Trace - 12:40:20.059 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1058}\r\n\r\n\r\n[Trace - 12:40:20.059 PM] Sending request 'textDocument/completion - (1066)'.\nParams: {\"context\":{\"triggerKind\":2,\"triggerCharacter\":\".\"},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":15}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:20] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:20.178 PM] Sending request 'textDocument/documentHighlight - (1067)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":15}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:20] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:20.261 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1064}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:20] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:20.261 PM] Sending request 'textDocument/semanticTokens/full - (1068)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:22] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:22.595 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":181,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":15},\"end\":{\"line\":38,\"character\":15}},\"rangeLength\":0,\"text\":\"E\"}]}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:22] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:22.595 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1065}\r\n\r\n\r\n[Trace - 12:40:22.596 PM] Sending request 'textDocument/documentHighlight - (1069)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":16}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:22] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:22.783 PM] Sending request 'textDocument/documentHighlight - (1070)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":16}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:22] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:22.799 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1068}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:22] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:22.799 PM] Sending request 'textDocument/semanticTokens/full - (1071)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.116 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":182,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":16},\"end\":{\"line\":38,\"character\":16}},\"rangeLength\":0,\"text\":\"n\"}]}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.117 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1069}\r\n\r\n\r\n[Trace - 12:40:23.117 PM] Sending request 'textDocument/documentHighlight - (1072)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":17}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.284 PM] Sending request 'textDocument/documentHighlight - (1073)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":17}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.318 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1071}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.318 PM] Sending request 'textDocument/semanticTokens/full - (1074)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.645 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":183,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":17},\"end\":{\"line\":38,\"character\":17}},\"rangeLength\":0,\"text\":\"c\"}]}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.645 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1072}\r\n\r\n\r\n[Trace - 12:40:23.645 PM] Sending request 'textDocument/documentHighlight - (1075)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":18}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.731 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1075}\r\n\r\n\r\n[Trace - 12:40:23.731 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":184,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":18},\"end\":{\"line\":38,\"character\":18}},\"rangeLength\":0,\"text\":\"o\"}]}\r\n\r\n\r\n[Trace - 12:40:23.731 PM] Sending request 'textDocument/documentHighlight - (1076)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":19}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.850 PM] Sending request 'textDocument/documentHighlight - (1077)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":19}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.886 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":185,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":19},\"end\":{\"line\":38,\"character\":19}},\"rangeLength\":0,\"text\":\"d\"}]}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:23] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:23.886 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1076}\r\n\r\n\r\n[Trace - 12:40:23.886 PM] Sending request 'textDocument/documentHighlight - (1078)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":20}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:24] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:24.020 PM] Sending request 'textDocument/documentHighlight - (1079)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":20}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:24] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:24.081 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":186,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":20},\"end\":{\"line\":38,\"character\":20}},\"rangeLength\":0,\"text\":\"e\"}]}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:24] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:24.082 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1078}\r\n\r\n\r\n[Trace - 12:40:24.082 PM] Sending request 'textDocument/documentHighlight - (1080)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":21}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:24] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:24.140 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1080}\r\n\r\n\r\n[Trace - 12:40:24.140 PM] Sending notification 'textDocument/didChange'.\nParams: {\"textDocument\":{\"version\":187,\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"contentChanges\":[{\"range\":{\"start\":{\"line\":38,\"character\":21},\"end\":{\"line\":38,\"character\":21}},\"rangeLength\":0,\"text\":\"r\"}]}\r\n\r\n\r\n[Trace - 12:40:24.140 PM] Sending request 'textDocument/documentHighlight - (1081)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":22}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:24] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:24.259 PM] Sending request 'textDocument/documentHighlight - (1082)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":22}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:24] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:24.341 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1074}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:24] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:24.341 PM] Sending request 'textDocument/semanticTokens/full - (1083)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:26] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:26.281 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1081}\r\n\r\n\r\n[Trace - 12:40:26.281 PM] Sending request 'textDocument/documentHighlight - (1084)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":21}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:26] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:26.282 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1084}\r\n\r\n\r\n[Trace - 12:40:26.282 PM] Sending request 'textDocument/documentHighlight - (1085)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":21}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:26] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:26.394 PM] Sending request 'textDocument/documentHighlight - (1086)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":21}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:26] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:26.702 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1085}\r\n\r\n\r\n[Trace - 12:40:26.702 PM] Sending request 'textDocument/documentHighlight - (1087)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":37,\"character\":24}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:26] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:26.808 PM] Sending request 'textDocument/documentHighlight - (1088)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":37,\"character\":24}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:26] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:26.926 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1087}\r\n\r\n\r\n[Trace - 12:40:26.926 PM] Sending request 'textDocument/documentHighlight - (1089)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":21}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:27] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:27.033 PM] Sending request 'textDocument/documentHighlight - (1090)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"position\":{\"line\":38,\"character\":21}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:29] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:29.377 PM] Sending request 'textDocument/codeAction - (1091)'.\nParams: {\"context\":{\"diagnostics\":[]},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"range\":{\"start\":{\"line\":38,\"character\":21},\"end\":{\"line\":38,\"character\":21}}}\r\n\r\n\r\n"
[ERROR][2023-08-11 12:40:30] .../vim/lsp/rpc.lua:676	"rpc"	"/Users/dppascual/.local/share/nvim/mason/bin/gopls"	"stderr"	"[Trace - 12:40:30.448 PM] Sending notification '$/cancelRequest'.\nParams: {\"id\":1091}\r\n\r\n\r\n"
@dppascual dppascual added gopls Issues related to the Go language server, gopls. Tools This label describes issues relating to any tools in the x/tools repository. labels Aug 11, 2023
@gopherbot gopherbot added this to the Unreleased milestone Aug 11, 2023
@findleyr
Copy link
Contributor

@dppascual are you definitely observing this with gopls@v0.13.1? That release specifically fixed several root causes that could lead to slow code actions.

The only remaining cause of such behavior is the goimports cache (#59216), but that should be relatively rare. Are you observing this a lot?

Server for client 'gopls' not yet ready!

Do you know if this message is only shown by neovim during initialization? That could indicate a gopls crash followed by a reinitialization.

@dppascual
Copy link
Author

@dppascual are you definitely observing this with gopls@v0.13.1? That release specifically fixed several root causes that could lead to slow code actions.

Yes, if you observe the path of the gopls printed out in the log, it points to gopls@v0.13.1

$ /Users/dppascual/.local/share/nvim/mason/bin/gopls -v version  
Build info
----------
golang.org/x/tools/gopls v0.13.1
    golang.org/x/tools/gopls@v0.13.1 h1:Q0cfPbEG1WVfgxcRZ9uKTA6/ckIRNXx6Ym7KgT/VFE4=
    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.20230801165449-23c7f589706c h1:YilyjKn3EDn6X+x+kP+4REeEtG3WeM52dJAr7AWzVrQ=
    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

The only remaining cause of such behavior is the goimports cache (#59216), but that should be relatively rare. Are you observing this a lot?

The last working day it happened to me about three times.

Server for client 'gopls' not yet ready!

Do you know if this message is only shown by neovim during initialization? That could indicate a gopls crash followed by a reinitialization.

No, it is shown when I request a code action for organising imports or filling up a new struct, among others.

@findleyr Let me continue digging down into such problem and collecting more info since the gopls is initialized until the errors comes up again. The size of the log could be huge but it will contain the whole trace and help us to identify what's going on.

@dppascual
Copy link
Author

@findleyr 30 minutes after gopls is initialized, neovim reports the same error upon executing a code action. Also, I cannot get info from any object neither completion popup is shown. I've attached the log.

lsp.log

@findleyr
Copy link
Contributor

Yes, if you observe the path of the gopls printed out in the log, it points to gopls@v0.13.1

@dppascual sorry for not being clear. I did observe that, but wondered if perhaps you were reporting on issues observed in the past, before the update. Thanks for clarifying.

I've attached the log.

Thank you! We will take a look.

@findleyr
Copy link
Contributor

findleyr commented Aug 28, 2023 •
edited

Sorry, have been backlogged with work. Finally got a chance to dig into this today. Here's a critical section of the logs:

[Trace - 09:39:55.872 AM] Sending notification '$/cancelRequest'.\nParams: {\"id\":481}\r\n\r\n\r\n
[Trace - 09:39:55.872 AM] Sending notification 'textDocument/didChange'.\nParams: {\"contentChanges\":[{\"rangeLength\":17,\"text\":\"\",\"range\":{\"start\":{\"line\":5,\"character\":0},\"end\":{\"line\":6,\"character\":0}}}],\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\",\"version\":4}}\r\n\r\n\r\n[Trace - 09:39:55.873 AM] Sending request 'textDocument/documentHighlight - (482)'.\nParams: {\"position\":{\"line\":5,\"character\":8},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n[Trace - 09:39:55.873 AM] Sending notification '$/cancelRequest'.\nParams: {\"id\":482}\r\n\r\n\r\n[Trace - 09:39:55.873 AM] Sending request 'textDocument/documentHighlight - (483)'.\nParams: {\"position\":{\"line\":5,\"character\":8},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n[Trace - 09:39:55.873 AM] Sending notification '$/cancelRequest'.\nParams: {\"id\":483}\r\n\r\n\r\n[Trace - 09:39:55.873 AM] Sending request 'textDocument/documentHighlight - (484)'.\nParams: {\"position\":{\"line\":5,\"character\":8},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[Error - Received] 09:39:55.890 AM #482 JSON RPC cancelled\r\n\r\n\r\n"
[Error - Received] 09:39:55.890 AM #483 JSON RPC cancelled\r\n\r\n\r\n"
[Trace - 09:39:56.075 AM] Sending request 'textDocument/semanticTokens/full - (485)'.\nParams: {\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[Trace - 09:39:56.090 AM] Sending notification '$/cancelRequest'.\nParams: {\"id\":480}\r\n\r\n\r\n"
[Trace - 09:39:56.090 AM] Sending request 'textDocument/codeAction - (486)'.\nParams: {\"context\":{\"diagnostics\":[]},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"range\":{\"start\":{\"line\":5,\"character\":8},\"end\":{\"line\":5,\"character\":8}}}\r\n\r\n\r\n"
[Trace - 09:39:56.244 AM] Sending notification '$/cancelRequest'.\nParams: {\"id\":484}\r\n\r\n\r\n"
[Trace - 09:39:56.246 AM] Sending request 'textDocument/documentHighlight - (487)'.\nParams: {\"position\":{\"line\":4,\"character\":8},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[Error - Received] 09:39:56.271 AM #484 JSON RPC cancelled\r\n\r\n\r\n"
[Trace - 09:39:56.453 AM] Sending notification '$/cancelRequest'.\nParams: {\"id\":486}\r\n\r\n\r\n"
[Trace - 09:39:56.456 AM] Sending request 'textDocument/codeAction - (488)'.\nParams: {\"context\":{\"diagnostics\":[]},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"range\":{\"start\":{\"line\":4,\"character\":8},\"end\":{\"line\":4,\"character\":8}}}\r\n\r\n\r\n"
[Trace - 09:39:56.482 AM] Sending notification '$/cancelRequest'.\nParams: {\"id\":487}\r\n\r\n\r\n[Trace - 09:39:56.483 AM] Sending request 'textDocument/documentHighlight - (489)'.\nParams: {\"position\":{\"line\":5,\"character\":8},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"}}\r\n\r\n\r\n"
[Trace - 09:39:56.687 AM] Sending notification '$/cancelRequest'.\nParams: {\"id\":488}\r\n\r\n\r\n"
[Trace - 09:39:56.688 AM] Sending request 'textDocument/codeAction - (490)'.\nParams: {\"context\":{\"diagnostics\":[]},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"range\":{\"start\":{\"line\":5,\"character\":8},\"end\":{\"line\":5,\"character\":8}}}\r\n\r\n\r\n"
[Trace - 09:39:57.815 AM] Sending request 'textDocument/codeAction - (491)'.\nParams: {\"context\":{\"diagnostics\":[]},\"textDocument\":{\"uri\":\"file:\\/\\/\\/Users\\/dppascual\\/projects\\/work\\/bbva\\/titan\\/libs\\/tracing\\/opentelemetry\\/exporters\\/seemas\\/exporter_test.go\"},\"range\":{\"start\":{\"line\":5,\"character\":8},\"end\":{\"line\":5,\"character\":8}}}\r\n\r\n\r\n"
[Trace - 09:39:58.873 AM] Sending notification '$/cancelRequest'.\nParams: {\"id\":491}\r\n\r\n\r\n"
[Trace - 09:40:16.388 AM] Received notification 'window/logMessage'.\nParams: {\"type\":3,\"message\":\"2023/08/14 09:40:16 go/packages.Load #4\\n\\tsnapshot=57\\n\\tdirectory=file:///Users/dppascual/projects/work/bbva/titan\\n\\tquery=[file=/Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/exporter_test.go]\\n\\tpackages=1\\n\"}\r\n\r\n\r\n"
[Trace - 09:40:16.388 AM] Received notification 'window/logMessage'.\nParams: {\"type\":3,\"message\":\"2023/08/14 09:40:16 go/packages.Load #4\\n\\tsnapshot=57\\n\\tdirectory=file:///Users/dppascual/projects/work/bbva/titan\\n\\tpackage=\\\"bbva.com/connectors/titan/libs/tracing/opentelemetry/exporters/seemas_test [bbva.com/connectors/titan/libs/tracing/opentelemetry/exporters/seemas.test]\\\"\\n\\tfiles=[/Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/exporter_test.go /Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/model_test.go /Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/processor_test.go /Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/uuid_test.go]\\n\"}\r\n\r\n\r\n"
[Trace - 09:40:16.388 AM] Received notification 'window/logMessage'.\nParams: {\"type\":3,\"message\":\"2023/08/14 09:40:16 go/packages.Load #2\\n\\tsnapshot=57\\n\\tdirectory=file:///Users/dppascual/projects/work/bbva/titan\\n\\tquery=[file=/Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/exporter_test.go]\\n\\tpackages=1\\n\"}\r\n\r\n\r\n[Trace - 09:40:16.388 AM] Received notification 'window/logMessage'.\nParams: {\"type\":3,\"message\":\"2023/08/14 09:40:16 go/packages.Load #2\\n\\tsnapshot=57\\n\\tdirectory=file:///Users/dppascual/projects/work/bbva/titan\\n\\tpackage=\\\"bbva.com/connectors/titan/libs/tracing/opentelemetry/exporters/seemas_test [bbva.com/connectors/titan/libs/tracing/opentelemetry/exporters/seemas.test]\\\"\\n\\tfiles=[/Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/exporter_test.go /Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/model_test.go /Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/processor_test.go /Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/uuid_test.go]\\n\"}\r\n\r\n\r\n"
[Trace - 09:40:16.392 AM] Received notification 'window/logMessage'.\nParams: {\"type\":3,\"message\":\"2023/08/14 09:40:16 go/packages.Load #2: updating metadata for 1 packages\\n\"}\r\n\r\n\r\n"
[Trace - 09:40:16.409 AM] Received notification 'window/logMessage'.\nParams: {\"type\":3,\"message\":\"2023/08/14 09:40:16 go/packages.Load #4: updating metadata for 0 packages\\n\"}\r\n\r\n\r\n"
[Trace - 09:40:16.429 AM] Received notification 'textDocument/publishDiagnostics'.\nParams: {\"uri\":\"file:///Users/dppascual/projects/work/bbva/titan/libs/tracing/opentelemetry/exporters/seemas/exporter_test.go\",\"version\":4,\"diagnostics\":[{\"range\":{\"start\":{\"line\":41,\"character\":13},\"end\":{\"line\":41,\"character\":17}},\"severity\":1,\"code\":\"UndeclaredName\",\"codeDescription\":{\"href\":\"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal#UndeclaredName\"},\"source\":\"compiler\",\"message\":\"undeclared name: json\"},{\"range\":{\"start\":{\"line\":64,\"character\":15},\"end\":{\"line\":64,\"character\":19}},\"severity\":1,\"code\":\"UndeclaredName\",\"codeDescription\":{\"href\":\"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal#UndeclaredName\"},\"source\":\"compiler\",\"message\":\"undeclared name: json\"},{\"range\":{\"start\":{\"line\":215,\"character\":15},\"end\":{\"line\":215,\"character\":19}},\"severity\":1,\"code\":\"UndeclaredName\",\"codeDescription\":{\"href\":\"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal#UndeclaredName\"},\"source\":\"compiler\",\"message\":\"undeclared name: json\"},{\"range\":{\"start\":{\"line\":227,\"character\":3},\"end\":{\"line\":227,\"character\":11}},\"severity\":1,\"code\":\"UndeclaredName\",\"codeDescription\":{\"href\":\"https://pkg.go.dev/golang.org/x/tools/internal/typesinternal#UndeclaredName\"},\"source\":\"compiler\",\"message\":\"undeclared name: asdfasdf\"}]}\r\n\r\n\r\n"
[Error - Received] 09:40:16.429 AM #486 JSON RPC cancelled\r\n\r\n\r\n[Trace - 09:40:16.429 AM] Received response 'textDocument/semanticTokens/full - (485)' in 20354ms.\nResult: {\"resultId\":\"2023-08-14 09:40:16.429503 +0200 CEST m=+1428.385471934\",\"data\":[...]"

In summary:

  • exporter_test.go is changed, presumably in a way that invalidates metadata
  • a bunch of requests are canceled, presumably from an early version
  • two goroutines try to reload it using go/packages (Load #2 and #4, presumably #3 was cancelled). These are probably (1) diagnosing the change and (2) computing semantic tokens
  • after 20s, both loads return.
  • semantic tokens are quickly computed for the loaded package

Based on this, I suspect:

  1. Some sort of starvation/deadlock during loading... but before load results are returned all the locks are very short lived (there is a longer lived lock to apply the results of loading).
  2. Some sort of starvation in the Go command when two loads of the same file occur simultaneously.
  3. Some sort of long-lived lock on the previous snapshot preventing it from being cloned.

The 20s interval is suspicious: if we can figure out where that delay/timeout is coming from, it may lead us to the root cause. Of course, it may be coincidental.

@dppascual something you can do to help us narrow this down is the following: start gopls with -debug=localhost:6060 and then visit http://localhost:6060/trace/ following a freeze. There, you should be able to see fine-grained summaries of recent gopls operations. You can also start the debug server dynamically by running Go: Start language server's maintainer interface from the VS Code command palette. If you look through the longest operations, are there some that stick out as taking 20s+? I'd particularly be interested in the longest cache.snapshot.load.

CC @adonovan

@findleyr findleyr modified the milestones: Unreleased, gopls/v0.14.0 Aug 28, 2023
@findleyr
Copy link
Contributor

Putting this in the v0.14.0 milestone as it would be good to track this down ASAP. With that said, I don't currently have ideas how to proceed. I don't experience this in my day-to-day development.

From the logs, there definitely appears to be a bug somewhere, but we need more information to track it down.

@dppascual
Copy link
Author

@findleyr I've been coding the last two weeks against the latest version of gopls (0.13.2) and I haven't experienced any latency problem. Also I enabled the plugin that was causing the error to appear most frequently but the issue is not reproduced, the server responds in a reasonable time.

Looking at the changes of the latest version of gopls, it is a minor version that applies a concrete bugfix so it should not be related to the mentioned problem. It happened to me with the previous version (0.13.1) but I've not tested such version again after updating to the latest one. I propose to keep this issue open until the next version is released and if the error comes up, I will bring it here with more info.

@dppascual
Copy link
Author

hey @findleyr, during the last working day I started to observe that gopls became unresponsive. As you mentioned in your last comment, I have been working with gopls in debug mode since there and the following screenshots show that there are multiple operations stick out as taking more than 20s.

Screenshot 2023-09-21 at 15 13 05

Screenshot 2023-09-21 at 15 14 00

On the other side, I want to mention two other issues non related to this one:

  • The first one is the autocomplete operation, it sometimes takes several seconds to show a pop up with the exported values of the recently imported package . It makes coding not very smooth (I have already seen in the backlog a couple of issues that make a mention of it)
  • The second one is the diagnostic operation, it usually takes seconds to refresh the UI interface when the error was already fixed. I don't know if the problem comes from the neovim or lsp side. I'm thinking of updating diagnostics only on save because it leads to confusion when coding.

Just mentioning them here because the attached report can shed some light. Let me know if you need more info to track it down.

@findleyr
Copy link
Contributor

Thanks @dppascual

The autocomplete problem is (I believe) understood, and I have fixes on the way (#62665).

I'll highlight one thing that may be related: 1m49s for source.AllImportsFixes. That indicates an enormous time spent in goimports -- longer than I've seen before. Other metrics look similarly unhappy: 30s to run the Go command?!

Could you run gopls stats from your workspace root, and report the result (feel free to prune anything you are uncomfortable sharing)? This will help us get a sense of the size of your workspace.

@dppascual
Copy link
Author

@findleyr I don't see any sensitive info that I cannot share so here it is:

Initializing workspace...     done (46.933777127s)
Gathering bug reports...      done (938.159562ms)
Querying memstats...          done (22.758337ms)
Querying workspace stats...   done (5.560918ms)
Collecting directory info...  done (98.026967ms)
{
  "BugReports": [],
  "CacheDir": "/Users/dppascual/Library/Caches/gopls/d4163706",
  "DirStats": {
    "Files": 2978,
    "TestdataFiles": 4,
    "GoFiles": 257,
    "ModFiles": 1,
    "Dirs": 647
  },
  "GOARCH": "amd64",
  "GOOS": "darwin",
  "GOPLSCACHE": "",
  "GoVersion": "go1.21.0",
  "GoplsVersion": "v0.13.2",
  "InitialWorkspaceLoadDuration": "46.933777127s",
  "MemStats": {
    "HeapAlloc": 50656920,
    "HeapInUse": 82747392,
    "TotalAlloc": 640521344
  },
  "WorkspaceStats": {
    "Files": {
      "Total": 2507,
      "Largest": 395043,
      "Errs": 0
    },
    "Views": [
      {
        "GoCommandVersion": "go1.21.1",
        "AllPackages": {
          "Packages": 526,
          "LargestPackage": 139,
          "CompiledGoFiles": 2586,
          "Modules": 81
        },
        "WorkspacePackages": {
          "Packages": 98,
          "LargestPackage": 13,
          "CompiledGoFiles": 314,
          "Modules": 1
        },
        "Diagnostics": 0
      }
    ]
  }
}

@findleyr
Copy link
Contributor

Thanks. That's not a particularly large workspace. I'm really surprised by how slow the initial workspace load is. I'm equally surprised by the slowness observed in your traces above for imports scanning and running the Go command.

Could you run the following from your workspace root?

time go list -json -test -compiled -deps ./...

Right now, I am suspicious of a slow file system, as all the operations that are abnormally slow interact with the file system in some way. Does that ring any bells?

@dppascual
Copy link
Author

Right now I have to go, it is the time the executed command has spent:

go list -json -test -compiled -deps ./...  1.54s user 2.29s system 17% cpu 22.125 total

I will run some benchmark on my filesystem and upload the report.

@dppascual
Copy link
Author

Hi @findleyr, sorry for my late reply, I've been very busy at work. You were right, it was caused by slow read operations. When it was fixed, the times were drastically reduced, and the coding became smooth. Also, I've tried completion operations by using gopls@master and the exported values of the package introduced were popped up relatively quickly.

Here is the new result of gopls stats:

Initializing workspace...     done (1.442257128s)
Gathering bug reports...      done (121.638605ms)
Querying memstats...          done (8.745355ms)
Querying workspace stats...   done (2.985928ms)
Collecting directory info...  done (68.771871ms)
{
  "BugReports": [],
  "CacheDir": "/Users/dppascual/Library/Caches/gopls/9bdeb8c8",
  "DirStats": {
    "Files": 3029,
    "TestdataFiles": 4,
    "GoFiles": 257,
    "ModFiles": 1,
    "Dirs": 647
  },
  "GOARCH": "amd64",
  "GOOS": "darwin",
  "GOPLSCACHE": "",
  "GoVersion": "go1.21.1",
  "GoplsVersion": "(devel)",
  "InitialWorkspaceLoadDuration": "1.442257128s",
  "MemStats": {
    "HeapAlloc": 35857496,
    "HeapInUse": 48857088,
    "TotalAlloc": 91094472
  },
  "WorkspaceStats": {
    "Files": {
      "Total": 2507,
      "Largest": 395043,
      "Errs": 0
    },
    "Views": [
      {
        "GoCommandVersion": "go1.21.1",
        "AllPackages": {
          "Packages": 526,
          "LargestPackage": 139,
          "CompiledGoFiles": 2586,
          "Modules": 81
        },
        "WorkspacePackages": {
          "Packages": 98,
          "LargestPackage": 13,
          "CompiledGoFiles": 314,
          "Modules": 1
        },
        "Diagnostics": 0
      }
    ]
  }
}

I guess it makes more sense to you, don't you?

@findleyr
Copy link
Contributor

Thanks @dppascual, that looks much better!

Out of curiosity, what was the cause of the slow reads?

@findleyr
Copy link
Contributor

findleyr commented Oct 2, 2023

(I'll close this as resolved. Please let me know if I'm misunderstanding.)

@findleyr findleyr closed this as completed Oct 2, 2023
@dppascual
Copy link
Author

Hi @findleyr, The initial reason was because the SSD was under 20% free space, it made my computer slow down and became unresponsiveness because of how SSDs use caching to be fast. It usually causes performance impact on write operations, but read ones were affected as well. After freeing some space, gopls started to response super fast, but right now it is happening again. I'm super sure my disk is causing this slowness because I'm also suffering how slow the neovim startup is , it takes ~= 7s, when it should be close to ms. Having said it, the issue can be keep closed. Thanks for your help.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
gopls Issues related to the Go language server, gopls. Tools This label describes issues relating to any tools in the x/tools repository.
Projects
None yet
Milestone
gopls/v0.14.0
Development

No branches or pull requests
3 participants
@gopherbot @dppascual @findleyr