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.

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

x/tools/gopls: diagnostics not sent for new buffer #35638

Closed
myitcv opened this issue Nov 16, 2019 · 34 comments
Closed

x/tools/gopls: diagnostics not sent for new buffer #35638

myitcv opened this issue Nov 16, 2019 · 34 comments
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Tools This label describes issues relating to any tools in the x/tools repository.
Milestone

Comments

@myitcv
Copy link
Member

myitcv commented Nov 16, 2019

What version of Go are you using (go version)?

$ go version
go version devel +c20b71eb37 Sat Nov 16 02:06:39 2019 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20191115202509-3a792d9c32b2
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.1.8-0.20191115202509-3a792d9c32b2

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/myitcv/.cache/go-build"
GOENV="/home/myitcv/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/myitcv/gostuff"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/myitcv/gos"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/myitcv/gos/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/myitcv/gostuff/src/github.com/myitcv/govim/go.mod"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build866188012=/tmp/go-build -gno-record-gcc-switches"

What did you do?

We have a govim test that starts with a module containing the following file (on disk):

package main

import "fmt"

func main() {
	fmt.Println()
}

Then it creates a new buffer for const.go (i.e. does not exist on disk initially) and populates it with the following content:

  
package main

Then it saves const.go, triggering codeAction (for goimports-like fixing) followed by Formatting.

What did you expect to see?

  • diagnostics to be sent for const.go
  • the CodeAction call to not return a nil error and no edits
  • the Formatting call to return a nil error an edits to remove the first blank line

What did you see instead?

  • no diagnostics sent for const.go
  • the CodeAction call returns an error:
gopls.CodeAction() return; err: no ParseGoHandle for file:///tmp/go-test-script668847014/script-format_on_save_new_file_existing_package/const.go

gopls is also logging to stderr:

no results: no analyses for mod.com

Also of note is that the initial Configuration call to the client (govim) happens after govim has made a number of calls to gopls. This has certainly changed from before where config was always called first, with effectively any other activity being blocked on it returning (or at least that's how it appeared to work).

See gopls log: fail.log

Separately, this issue appears to be related to #35114 because sometimes we see the following on stderr:

file not found (open /home/myitcv/gostuff/src/github.com/myitcv/playground/const.go: no such file or directory)

cc @stamblerre @matloob

@myitcv myitcv added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. gopls Issues related to the Go language server, gopls. labels Nov 16, 2019
@gopherbot gopherbot added this to the Unreleased milestone Nov 16, 2019
@gopherbot gopherbot added the Tools This label describes issues relating to any tools in the x/tools repository. label Nov 16, 2019
@myitcv
Copy link
Member Author

myitcv commented Nov 18, 2019

This appears to have started as a result of https://go-review.googlesource.com/c/tools/+/206888

@heschi
Copy link
Contributor

heschi commented Dec 7, 2019

I'm done for the day, but this looks a lot like #35949.

@myitcv
Copy link
Member Author

myitcv commented Dec 7, 2019

We're still seeing this as of 259af5f.

@heschi
Copy link
Contributor

heschi commented Dec 9, 2019

@myitcv: which govim test is it? format_on_save_new_file_existing_package doesn't seem to exist any more.

@myitcv
Copy link
Member Author

myitcv commented Dec 9, 2019

@heschik: it's exactly the one you mention, but you need to be looking on this branch: govim/govim#584

GOVIM_TESTSCRIPT_STDERR=true go test -count=1 -v -run "TestScripts/scenario_default/format_on_save_new_file_existing_package" ./cmd/govim
Output

=== RUN   TestScripts
=== RUN   TestScripts/scenario_default
=== RUN   TestScripts/scenario_default/format_on_save_new_file_existing_package
=== PAUSE TestScripts/scenario_default/format_on_save_new_file_existing_package
=== CONT  TestScripts/scenario_default/format_on_save_new_file_existing_package
2019-12-09T20:42:57.347861_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.348016_#1: vim start =======================
2019-12-09T20:42:57.348016_#1: sendJSONMsg: [0,[1,"loaded"]]
2019-12-09T20:42:57.348016_#1: vim end =======================
2019-12-09T20:42:57.349413_#1: vim start =======================
2019-12-09T20:42:57.349413_#1: recvJSONMsg: [1] ["callback",1,[""]]
2019-12-09T20:42:57.349413_#1: vim end =======================
2019-12-09T20:42:57.349499_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.349520_#1: Go version devel +da4d58587e Sat Dec 7 15:57:30 2019 +0000
2019-12-09T20:42:57.349868_#1: Build info: &debug.BuildInfo{
2019-12-09T20:42:57.349868_#1:     Path: "github.com/govim/govim/cmd/govim",
2019-12-09T20:42:57.349868_#1:     Main: debug.Module{
2019-12-09T20:42:57.349868_#1:         Path:    "github.com/govim/govim",
2019-12-09T20:42:57.349868_#1:         Version: "(devel)",
2019-12-09T20:42:57.349868_#1:         Sum:     "",
2019-12-09T20:42:57.349868_#1:         Replace: (*debug.Module)(nil),
2019-12-09T20:42:57.349868_#1:     },
2019-12-09T20:42:57.349868_#1:     Deps: {
2019-12-09T20:42:57.349868_#1:         &debug.Module{
2019-12-09T20:42:57.349868_#1:             Path:    "github.com/fsnotify/fsnotify",
2019-12-09T20:42:57.349868_#1:             Version: "v1.4.7",
2019-12-09T20:42:57.349868_#1:             Sum:     "h1:IXs+QLmnXW2CcXuY+8Mzv/fWEsPGWxqefPtCP5CnV9I=",
2019-12-09T20:42:57.349868_#1:             Replace: (*debug.Module)(nil),
2019-12-09T20:42:57.349868_#1:         },
2019-12-09T20:42:57.349868_#1:         &debug.Module{
2019-12-09T20:42:57.349868_#1:             Path:    "github.com/kr/pretty",
2019-12-09T20:42:57.349868_#1:             Version: "v0.1.0",
2019-12-09T20:42:57.349868_#1:             Sum:     "h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=",
2019-12-09T20:42:57.349868_#1:             Replace: (*debug.Module)(nil),
2019-12-09T20:42:57.349868_#1:         },
2019-12-09T20:42:57.349868_#1:         &debug.Module{
2019-12-09T20:42:57.349868_#1:             Path:    "github.com/kr/text",
2019-12-09T20:42:57.349868_#1:             Version: "v0.1.0",
2019-12-09T20:42:57.349868_#1:             Sum:     "h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=",
2019-12-09T20:42:57.349868_#1:             Replace: (*debug.Module)(nil),
2019-12-09T20:42:57.349868_#1:         },
2019-12-09T20:42:57.349868_#1:         &debug.Module{
2019-12-09T20:42:57.349868_#1:             Path:    "golang.org/x/sys",
2019-12-09T20:42:57.349868_#1:             Version: "v0.0.0-20190429190828-d89cdac9e872",
2019-12-09T20:42:57.349868_#1:             Sum:     "h1:cGjJzUd8RgBw428LXP65YXni0aiGNA4Bl+ls8SmLOm8=",
2019-12-09T20:42:57.349868_#1:             Replace: (*debug.Module)(nil),
2019-12-09T20:42:57.349868_#1:         },
2019-12-09T20:42:57.349868_#1:         &debug.Module{
2019-12-09T20:42:57.349868_#1:             Path:    "golang.org/x/xerrors",
2019-12-09T20:42:57.349868_#1:             Version: "v0.0.0-20190717185122-a985d3407aa7",
2019-12-09T20:42:57.349868_#1:             Sum:     "h1:9zdDQZ7Thm29KFXgAX/+yaf3eVbP7djjWp/dXAppNCc=",
2019-12-09T20:42:57.349868_#1:             Replace: (*debug.Module)(nil),
2019-12-09T20:42:57.349868_#1:         },
2019-12-09T20:42:57.349868_#1:         &debug.Module{
2019-12-09T20:42:57.349868_#1:             Path:    "gopkg.in/tomb.v2",
2019-12-09T20:42:57.349868_#1:             Version: "v2.0.0-20161208151619-d5d1b5820637",
2019-12-09T20:42:57.349868_#1:             Sum:     "h1:yiW+nvdHb9LVqSHQBXfZCieqV4fzYhNBql77zY0ykqs=",
2019-12-09T20:42:57.349868_#1:             Replace: (*debug.Module)(nil),
2019-12-09T20:42:57.349868_#1:         },
2019-12-09T20:42:57.349868_#1:     },
2019-12-09T20:42:57.349868_#1: }
2019-12-09T20:42:57.349925_#1: vim start =======================
2019-12-09T20:42:57.349925_#1: sendJSONMsg: [0,[2,"expr","{\"VersionLong\": exists(\"v:versionlong\")?v:versionlong:-1, \"GuiRunning\": has(\"gui_running\")}"]]
2019-12-09T20:42:57.349925_#1: vim end =======================
2019-12-09T20:42:57.350342_#1: vim start =======================
2019-12-09T20:42:57.350342_#1: recvJSONMsg: [2] ["callback",2,["",{"VersionLong":8012408,"GuiRunning":0}]]
2019-12-09T20:42:57.350342_#1: vim end =======================
2019-12-09T20:42:57.350425_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.350485_#1: Loaded against vim v8.1.2408
2019-12-09T20:42:57.350511_#1: vim start =======================
2019-12-09T20:42:57.350511_#1: sendJSONMsg: [0,[3,"ex","augroup govim"]]
2019-12-09T20:42:57.350511_#1: vim end =======================
2019-12-09T20:42:57.350901_#1: vim start =======================
2019-12-09T20:42:57.350901_#1: recvJSONMsg: [3] ["callback",3,[""]]
2019-12-09T20:42:57.350901_#1: vim end =======================
2019-12-09T20:42:57.350962_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.350990_#1: vim start =======================
2019-12-09T20:42:57.350990_#1: sendJSONMsg: [0,[4,"ex","augroup END"]]
2019-12-09T20:42:57.350990_#1: vim end =======================
2019-12-09T20:42:57.351365_#1: vim start =======================
2019-12-09T20:42:57.351365_#1: recvJSONMsg: [4] ["callback",4,[""]]
2019-12-09T20:42:57.351365_#1: vim end =======================
2019-12-09T20:42:57.351415_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.351434_#1: vim start =======================
2019-12-09T20:42:57.351434_#1: sendJSONMsg: [0,[5,"call","getcwd",-1]]
2019-12-09T20:42:57.351434_#1: vim end =======================
2019-12-09T20:42:57.351731_#1: vim start =======================
2019-12-09T20:42:57.351731_#1: recvJSONMsg: [5] ["callback",5,["","/tmp/go-test-script458939670/script-format_on_save_new_file_existing_package"]]
2019-12-09T20:42:57.351731_#1: vim end =======================
2019-12-09T20:42:57.351817_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.351863_#1: vim start =======================
2019-12-09T20:42:57.351863_#1: sendJSONMsg: [0,[6,"function","GOVIM_internal_BalloonExpr",[]]]
2019-12-09T20:42:57.351863_#1: vim end =======================
2019-12-09T20:42:57.352153_#1: vim start =======================
2019-12-09T20:42:57.352153_#1: recvJSONMsg: [6] ["callback",6,[""]]
2019-12-09T20:42:57.352153_#1: vim end =======================
2019-12-09T20:42:57.352217_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.352244_#1: vim start =======================
2019-12-09T20:42:57.352244_#1: sendJSONMsg: [0,[7,"autocmd","autocommand:0"," govim BufUnload *.go",["eval(expand('\u003cabuf\u003e'))"]]]
2019-12-09T20:42:57.352244_#1: vim end =======================
2019-12-09T20:42:57.352525_#1: vim start =======================
2019-12-09T20:42:57.352525_#1: recvJSONMsg: [7] ["callback",7,[""]]
2019-12-09T20:42:57.352525_#1: vim end =======================
2019-12-09T20:42:57.352596_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.352634_#1: vim start =======================
2019-12-09T20:42:57.352634_#1: sendJSONMsg: [0,[8,"autocmd","autocommand:1"," govim BufNewFile,BufRead *.go",["{\"Num\": eval(expand('\u003cabuf\u003e')), \"Name\": fnamemodify(bufname(eval(expand('\u003cabuf\u003e'))),':p'), \"Contents\": join(getbufline(eval(expand('\u003cabuf\u003e')), 0, \"$\"), \"\\n\").\"\\n\", \"Loaded\": bufloaded(eval(expand('\u003cabuf\u003e')))}"]]]
2019-12-09T20:42:57.352634_#1: vim end =======================
2019-12-09T20:42:57.352929_#1: vim start =======================
2019-12-09T20:42:57.352929_#1: recvJSONMsg: [8] ["callback",8,[""]]
2019-12-09T20:42:57.352929_#1: vim end =======================
2019-12-09T20:42:57.352992_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.353014_#1: vim start =======================
2019-12-09T20:42:57.353014_#1: sendJSONMsg: [0,[9,"autocmd","autocommand:2"," govim BufWritePre *.go",["eval(expand('\u003cabuf\u003e'))"]]]
2019-12-09T20:42:57.353014_#1: vim end =======================
2019-12-09T20:42:57.353354_#1: vim start =======================
2019-12-09T20:42:57.353354_#1: recvJSONMsg: [9] ["callback",9,[""]]
2019-12-09T20:42:57.353354_#1: vim end =======================
2019-12-09T20:42:57.353417_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.353439_#1: vim start =======================
2019-12-09T20:42:57.353439_#1: sendJSONMsg: [0,[10,"function","GOVIM_internal_Complete",["findarg","base"]]]
2019-12-09T20:42:57.353439_#1: vim end =======================
2019-12-09T20:42:57.353768_#1: vim start =======================
2019-12-09T20:42:57.353768_#1: recvJSONMsg: [10] ["callback",10,[""]]
2019-12-09T20:42:57.353768_#1: vim end =======================
2019-12-09T20:42:57.353834_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.353866_#1: vim start =======================
2019-12-09T20:42:57.353866_#1: sendJSONMsg: [0,[11,"command","GOVIMGoToDef",{"nargs":"-nargs=?"}]]
2019-12-09T20:42:57.353866_#1: vim end =======================
2019-12-09T20:42:57.354194_#1: vim start =======================
2019-12-09T20:42:57.354194_#1: recvJSONMsg: [11] ["callback",11,[""]]
2019-12-09T20:42:57.354194_#1: vim end =======================
2019-12-09T20:42:57.354248_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.354270_#1: vim start =======================
2019-12-09T20:42:57.354270_#1: sendJSONMsg: [0,[12,"command","GOVIMSuggestedFixes",{"nargs":"-nargs=?"}]]
2019-12-09T20:42:57.354270_#1: vim end =======================
2019-12-09T20:42:57.354628_#1: vim start =======================
2019-12-09T20:42:57.354628_#1: recvJSONMsg: [12] ["callback",12,[""]]
2019-12-09T20:42:57.354628_#1: vim end =======================
2019-12-09T20:42:57.354688_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.354720_#1: vim start =======================
2019-12-09T20:42:57.354720_#1: sendJSONMsg: [0,[13,"command","GOVIMGoToPrevDef",{"count":"-count=1","nargs":"-nargs=?"}]]
2019-12-09T20:42:57.354720_#1: vim end =======================
2019-12-09T20:42:57.355073_#1: vim start =======================
2019-12-09T20:42:57.355073_#1: recvJSONMsg: [13] ["callback",13,[""]]
2019-12-09T20:42:57.355073_#1: vim end =======================
2019-12-09T20:42:57.355135_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.355158_#1: vim start =======================
2019-12-09T20:42:57.355158_#1: sendJSONMsg: [0,[14,"function","GOVIMHover",[]]]
2019-12-09T20:42:57.355158_#1: vim end =======================
2019-12-09T20:42:57.355459_#1: vim start =======================
2019-12-09T20:42:57.355459_#1: recvJSONMsg: [14] ["callback",14,[""]]
2019-12-09T20:42:57.355459_#1: vim end =======================
2019-12-09T20:42:57.355538_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.355597_#1: vim start =======================
2019-12-09T20:42:57.355597_#1: sendJSONMsg: [0,[15,"autocmd","autocommand:3"," govim BufDelete *.go",["eval(expand('\u003cabuf\u003e'))"]]]
2019-12-09T20:42:57.355597_#1: vim end =======================
2019-12-09T20:42:57.355986_#1: vim start =======================
2019-12-09T20:42:57.355986_#1: recvJSONMsg: [15] ["callback",15,[""]]
2019-12-09T20:42:57.355986_#1: vim end =======================
2019-12-09T20:42:57.356055_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.356088_#1: vim start =======================
2019-12-09T20:42:57.356088_#1: sendJSONMsg: [0,[16,"command","GOVIMGoFmt",{}]]
2019-12-09T20:42:57.356088_#1: vim end =======================
2019-12-09T20:42:57.356382_#1: vim start =======================
2019-12-09T20:42:57.356382_#1: recvJSONMsg: [16] ["callback",16,[""]]
2019-12-09T20:42:57.356382_#1: vim end =======================
2019-12-09T20:42:57.356437_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.356457_#1: vim start =======================
2019-12-09T20:42:57.356457_#1: sendJSONMsg: [0,[17,"command","GOVIMGoImports",{}]]
2019-12-09T20:42:57.356457_#1: vim end =======================
2019-12-09T20:42:57.356774_#1: vim start =======================
2019-12-09T20:42:57.356774_#1: recvJSONMsg: [17] ["callback",17,[""]]
2019-12-09T20:42:57.356774_#1: vim end =======================
2019-12-09T20:42:57.356831_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.356852_#1: vim start =======================
2019-12-09T20:42:57.356852_#1: sendJSONMsg: [0,[18,"command","GOVIMQuickfixDiagnostics",{}]]
2019-12-09T20:42:57.356852_#1: vim end =======================
2019-12-09T20:42:57.357082_#1: vim start =======================
2019-12-09T20:42:57.357082_#1: recvJSONMsg: [18] ["callback",18,[""]]
2019-12-09T20:42:57.357082_#1: vim end =======================
2019-12-09T20:42:57.357138_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.357160_#1: vim start =======================
2019-12-09T20:42:57.357160_#1: sendJSONMsg: [0,[19,"function","GOVIM_internal_BufChanged",["bufnr","start","end","added","changes"]]]
2019-12-09T20:42:57.357160_#1: vim end =======================
2019-12-09T20:42:57.357401_#1: vim start =======================
2019-12-09T20:42:57.357401_#1: recvJSONMsg: [19] ["callback",19,[""]]
2019-12-09T20:42:57.357401_#1: vim end =======================
2019-12-09T20:42:57.357454_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.357472_#1: vim start =======================
2019-12-09T20:42:57.357472_#1: sendJSONMsg: [0,[20,"function","GOVIM_internal_SetConfig",["config"]]]
2019-12-09T20:42:57.357472_#1: vim end =======================
2019-12-09T20:42:57.357790_#1: vim start =======================
2019-12-09T20:42:57.357790_#1: recvJSONMsg: [20] ["callback",20,[""]]
2019-12-09T20:42:57.357790_#1: vim end =======================
2019-12-09T20:42:57.357846_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.357868_#1: vim start =======================
2019-12-09T20:42:57.357868_#1: sendJSONMsg: [0,[21,"ex","call govim#config#Set(\"_internal_Func\", function(\"GOVIM_internal_SetConfig\"))"]]
2019-12-09T20:42:57.357868_#1: vim end =======================
2019-12-09T20:42:57.358346_#1: vim start =======================
2019-12-09T20:42:57.358346_#1: recvJSONMsg: [21] ["function","function:GOVIM_internal_SetConfig",[{}]]
2019-12-09T20:42:57.358346_#1: vim end =======================
2019-12-09T20:42:57.358386_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.358517_#1: vim start =======================
2019-12-09T20:42:57.358517_#1: sendJSONMsg: [21,["",null]]
2019-12-09T20:42:57.358517_#1: vim end =======================
2019-12-09T20:42:57.358761_#1: vim start =======================
2019-12-09T20:42:57.358761_#1: recvJSONMsg: [22] ["callback",21,[""]]
2019-12-09T20:42:57.358761_#1: vim end =======================
2019-12-09T20:42:57.358798_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.358813_#1: vim start =======================
2019-12-09T20:42:57.358813_#1: sendJSONMsg: [0,[22,"function","GOVIM_internal_SetUserBusy",["isBusy"]]]
2019-12-09T20:42:57.358813_#1: vim end =======================
2019-12-09T20:42:57.359088_#1: vim start =======================
2019-12-09T20:42:57.359088_#1: recvJSONMsg: [23] ["callback",22,[""]]
2019-12-09T20:42:57.359088_#1: vim end =======================
2019-12-09T20:42:57.359122_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.359136_#1: vim start =======================
2019-12-09T20:42:57.359136_#1: sendJSONMsg: [0,[23,"function","GOVIM_internal_PopupSelection",["id","selected"]]]
2019-12-09T20:42:57.359136_#1: vim end =======================
2019-12-09T20:42:57.359418_#1: vim start =======================
2019-12-09T20:42:57.359418_#1: recvJSONMsg: [24] ["callback",23,[""]]
2019-12-09T20:42:57.359418_#1: vim end =======================
2019-12-09T20:42:57.359452_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.359466_#1: vim start =======================
2019-12-09T20:42:57.359466_#1: sendJSONMsg: [0,[24,"command","GOVIMReferences",{}]]
2019-12-09T20:42:57.359466_#1: vim end =======================
2019-12-09T20:42:57.359744_#1: vim start =======================
2019-12-09T20:42:57.359744_#1: recvJSONMsg: [25] ["callback",24,[""]]
2019-12-09T20:42:57.359744_#1: vim end =======================
2019-12-09T20:42:57.359786_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.359802_#1: vim start =======================
2019-12-09T20:42:57.359802_#1: sendJSONMsg: [0,[25,"command","GOVIMRename",{"nargs":"-nargs=?"}]]
2019-12-09T20:42:57.359802_#1: vim end =======================
2019-12-09T20:42:57.360084_#1: vim start =======================
2019-12-09T20:42:57.360084_#1: recvJSONMsg: [26] ["callback",25,[""]]
2019-12-09T20:42:57.360084_#1: vim end =======================
2019-12-09T20:42:57.360128_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.360146_#1: vim start =======================
2019-12-09T20:42:57.360146_#1: sendJSONMsg: [0,[26,"command","GOVIMStringFn",{"complete":"-complete=customlist,GOVIM_internal_StringFnComplete","nargs":"-nargs=+","range":"-range"}]]
2019-12-09T20:42:57.360146_#1: vim end =======================
2019-12-09T20:42:57.360448_#1: vim start =======================
2019-12-09T20:42:57.360448_#1: recvJSONMsg: [27] ["callback",26,[""]]
2019-12-09T20:42:57.360448_#1: vim end =======================
2019-12-09T20:42:57.360480_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.360492_#1: vim start =======================
2019-12-09T20:42:57.360492_#1: sendJSONMsg: [0,[27,"function","GOVIM_internal_StringFnComplete",["ArgLead","CmdLine","CursorPos"]]]
2019-12-09T20:42:57.360492_#1: vim end =======================
2019-12-09T20:42:57.360788_#1: vim start =======================
2019-12-09T20:42:57.360788_#1: recvJSONMsg: [28] ["callback",27,[""]]
2019-12-09T20:42:57.360788_#1: vim end =======================
2019-12-09T20:42:57.360820_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.360887_#1: vim start =======================
2019-12-09T20:42:57.360887_#1: sendJSONMsg: [0,[28,"call","sign_define","govimErrSign",{"text":"\u003e\u003e","texthl":"govimErr"}]]
2019-12-09T20:42:57.360887_#1: vim end =======================
2019-12-09T20:42:57.361197_#1: vim start =======================
2019-12-09T20:42:57.361197_#1: recvJSONMsg: [29] ["callback",28,["",0]]
2019-12-09T20:42:57.361197_#1: vim end =======================
2019-12-09T20:42:57.361229_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.361245_#1: vim start =======================
2019-12-09T20:42:57.361245_#1: sendJSONMsg: [0,[29,"call","sign_define","govimWarnSign",{"text":"\u003e\u003e","texthl":"govimWarn"}]]
2019-12-09T20:42:57.361245_#1: vim end =======================
2019-12-09T20:42:57.361505_#1: vim start =======================
2019-12-09T20:42:57.361505_#1: recvJSONMsg: [30] ["callback",29,["",0]]
2019-12-09T20:42:57.361505_#1: vim end =======================
2019-12-09T20:42:57.361538_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.361554_#1: vim start =======================
2019-12-09T20:42:57.361554_#1: sendJSONMsg: [0,[30,"call","sign_define","govimInfoSign",{"text":"\u003e\u003e","texthl":"govimInfo"}]]
2019-12-09T20:42:57.361554_#1: vim end =======================
2019-12-09T20:42:57.361947_#1: vim start =======================
2019-12-09T20:42:57.361947_#1: recvJSONMsg: [31] ["callback",30,["",0]]
2019-12-09T20:42:57.361947_#1: vim end =======================
2019-12-09T20:42:57.362013_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.362037_#1: vim start =======================
2019-12-09T20:42:57.362037_#1: sendJSONMsg: [0,[31,"call","sign_define","govimHintSign",{"text":"\u003e\u003e","texthl":"govimHint"}]]
2019-12-09T20:42:57.362037_#1: vim end =======================
2019-12-09T20:42:57.362269_#1: vim start =======================
2019-12-09T20:42:57.362269_#1: recvJSONMsg: [32] ["callback",31,["",0]]
2019-12-09T20:42:57.362269_#1: vim end =======================
2019-12-09T20:42:57.362350_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.362372_#1: vim start =======================
2019-12-09T20:42:57.362372_#1: sendJSONMsg: [0,[32,"function","GOVIMMotion",["direction","target"]]]
2019-12-09T20:42:57.362372_#1: vim end =======================
2019-12-09T20:42:57.362637_#1: vim start =======================
2019-12-09T20:42:57.362637_#1: recvJSONMsg: [33] ["callback",32,[""]]
2019-12-09T20:42:57.362637_#1: vim end =======================
2019-12-09T20:42:57.362690_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.362719_#1: vim start =======================
2019-12-09T20:42:57.362719_#1: sendJSONMsg: [0,[33,"function","GOVIMHello",[]]]
2019-12-09T20:42:57.362719_#1: vim end =======================
2019-12-09T20:42:57.363042_#1: vim start =======================
2019-12-09T20:42:57.363042_#1: recvJSONMsg: [34] ["callback",33,[""]]
2019-12-09T20:42:57.363042_#1: vim end =======================
2019-12-09T20:42:57.363115_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.363146_#1: vim start =======================
2019-12-09T20:42:57.363146_#1: sendJSONMsg: [0,[34,"command","GOVIMHello",{"nargs":"-nargs=?"}]]
2019-12-09T20:42:57.363146_#1: vim end =======================
2019-12-09T20:42:57.363379_#1: vim start =======================
2019-12-09T20:42:57.363379_#1: recvJSONMsg: [35] ["callback",34,[""]]
2019-12-09T20:42:57.363379_#1: vim end =======================
2019-12-09T20:42:57.363434_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.363451_#1: vim start =======================
2019-12-09T20:42:57.363451_#1: sendJSONMsg: [0,[35,"function","GOVIM_internal_DumpPopups",[]]]
2019-12-09T20:42:57.363451_#1: vim end =======================
2019-12-09T20:42:57.363699_#1: vim start =======================
2019-12-09T20:42:57.363699_#1: recvJSONMsg: [36] ["callback",35,[""]]
2019-12-09T20:42:57.363699_#1: vim end =======================
2019-12-09T20:42:57.363751_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.363765_#1: vim start =======================
2019-12-09T20:42:57.363765_#1: sendJSONMsg: [0,[36,"function","GOVIM_internal_ShowMessagePopup",[]]]
2019-12-09T20:42:57.363765_#1: vim end =======================
2019-12-09T20:42:57.364021_#1: vim start =======================
2019-12-09T20:42:57.364021_#1: recvJSONMsg: [37] ["callback",36,[""]]
2019-12-09T20:42:57.364021_#1: vim end =======================
2019-12-09T20:42:57.364087_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.364121_#1: vim start =======================
2019-12-09T20:42:57.364121_#1: sendJSONMsg: [0,[37,"function","GOVIMSimpleBatch",[]]]
2019-12-09T20:42:57.364121_#1: vim end =======================
2019-12-09T20:42:57.364366_#1: vim start =======================
2019-12-09T20:42:57.364366_#1: recvJSONMsg: [38] ["callback",37,[""]]
2019-12-09T20:42:57.364366_#1: vim end =======================
2019-12-09T20:42:57.364417_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.364432_#1: vim start =======================
2019-12-09T20:42:57.364432_#1: sendJSONMsg: [0,[38,"function","GOVIMCancelBatch",[]]]
2019-12-09T20:42:57.364432_#1: vim end =======================
2019-12-09T20:42:57.364675_#1: vim start =======================
2019-12-09T20:42:57.364675_#1: recvJSONMsg: [39] ["callback",38,[""]]
2019-12-09T20:42:57.364675_#1: vim end =======================
2019-12-09T20:42:57.364718_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.364733_#1: vim start =======================
2019-12-09T20:42:57.364733_#1: sendJSONMsg: [0,[39,"function","GOVIMBadBatch",[]]]
2019-12-09T20:42:57.364733_#1: vim end =======================
2019-12-09T20:42:57.364958_#1: vim start =======================
2019-12-09T20:42:57.364958_#1: recvJSONMsg: [40] ["callback",39,[""]]
2019-12-09T20:42:57.364958_#1: vim end =======================
2019-12-09T20:42:57.365012_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.365027_#1: vim start =======================
2019-12-09T20:42:57.365027_#1: sendJSONMsg: [0,[40,"function","GOVIMAssertFailedBatch",[]]]
2019-12-09T20:42:57.365027_#1: vim end =======================
2019-12-09T20:42:57.365268_#1: vim start =======================
2019-12-09T20:42:57.365268_#1: recvJSONMsg: [41] ["callback",40,[""]]
2019-12-09T20:42:57.365268_#1: vim end =======================
2019-12-09T20:42:57.365323_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.365338_#1: vim start =======================
2019-12-09T20:42:57.365338_#1: sendJSONMsg: [0,[41,"function","GOVIMNonBatchCallInBatch",[]]]
2019-12-09T20:42:57.365338_#1: vim end =======================
2019-12-09T20:42:57.365630_#1: vim start =======================
2019-12-09T20:42:57.365630_#1: recvJSONMsg: [42] ["callback",41,[""]]
2019-12-09T20:42:57.365630_#1: vim end =======================
2019-12-09T20:42:57.365663_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.365676_#1: vim start =======================
2019-12-09T20:42:57.365676_#1: sendJSONMsg: [0,[42,"expr","has(\"gui_running\")"]]
2019-12-09T20:42:57.365676_#1: vim end =======================
2019-12-09T20:42:57.365921_#1: vim start =======================
2019-12-09T20:42:57.365921_#1: recvJSONMsg: [43] ["callback",42,["",0]]
2019-12-09T20:42:57.365921_#1: vim end =======================
2019-12-09T20:42:57.365971_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.366006_#1: gopls log file: /tmp/gopls_log
2019-12-09T20:42:57.366016_#1: vim start =======================
2019-12-09T20:42:57.366016_#1: sendJSONMsg: [0,[43,"ex","let s:gopls_logfile=\"/tmp/gopls_log\""]]
2019-12-09T20:42:57.366016_#1: vim end =======================
2019-12-09T20:42:57.366243_#1: vim start =======================
2019-12-09T20:42:57.366243_#1: recvJSONMsg: [44] ["callback",43,[""]]
2019-12-09T20:42:57.366243_#1: vim end =======================
2019-12-09T20:42:57.366299_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.366312_#1: Running gopls: /tmp/gobin-gopls-installdir816453587/gopls -rpc.trace -logfile /tmp/gopls_log
2019-12-09T20:42:57.367486_#1: gopls server start =======================
2019-12-09T20:42:57.367486_#1: gopls.Initialize() call; params:
2019-12-09T20:42:57.367486_#1: &protocol.ParamInitialize{
2019-12-09T20:42:57.367486_#1:     InitializeParams: struct { protocol.InnerInitializeParams; protocol.WorkspaceFoldersInitializeParams }{
2019-12-09T20:42:57.367486_#1:         InnerInitializeParams: protocol.InnerInitializeParams{
2019-12-09T20:42:57.367486_#1:             ProcessID:    0,
2019-12-09T20:42:57.367486_#1:             ClientInfo:   struct { Name string "json:\"name\""; Version string "json:\"version,omitempty\"" }{},
2019-12-09T20:42:57.367486_#1:             RootPath:     "",
2019-12-09T20:42:57.367486_#1:             RootURI:      "file:///tmp/go-test-script458939670/script-format_on_save_new_file_existing_package",
2019-12-09T20:42:57.367486_#1:             Capabilities: struct { Workspace struct { protocol.WorkspaceClientCapabilities; WorkspaceFolders bool "json:\"workspaceFolders,omitempty\""; Configuration bool "json:\"configuration,omitempty\"" }; TextDocument protocol.TextDocumentClientCapabilities "json:\"textDocument,omitempty\""; Window interface {} "json:\"window,omitempty\""; Experimental interface {} "json:\"experimental,omitempty\""; DynamicRegistration bool "json:\"dynamicRegistration,omitempty\"" }{
2019-12-09T20:42:57.367486_#1:                 Workspace: struct { protocol.WorkspaceClientCapabilities; WorkspaceFolders bool "json:\"workspaceFolders,omitempty\""; Configuration bool "json:\"configuration,omitempty\"" }{
2019-12-09T20:42:57.367486_#1:                     WorkspaceClientCapabilities: protocol.WorkspaceClientCapabilities{
2019-12-09T20:42:57.367486_#1:                         ApplyEdit:              false,
2019-12-09T20:42:57.367486_#1:                         WorkspaceEdit:          protocol.WorkspaceEditClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                         DidChangeConfiguration: protocol.DidChangeConfigurationClientCapabilities{DynamicRegistration:true},
2019-12-09T20:42:57.367486_#1:                         DidChangeWatchedFiles:  protocol.DidChangeWatchedFilesClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                         Symbol:                 protocol.WorkspaceSymbolClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                         ExecuteCommand:         protocol.ExecuteCommandClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     },
2019-12-09T20:42:57.367486_#1:                     WorkspaceFolders: false,
2019-12-09T20:42:57.367486_#1:                     Configuration:    true,
2019-12-09T20:42:57.367486_#1:                 },
2019-12-09T20:42:57.367486_#1:                 TextDocument: protocol.TextDocumentClientCapabilities{
2019-12-09T20:42:57.367486_#1:                     Synchronization: protocol.TextDocumentSyncClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     Completion:      protocol.CompletionClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     Hover:           protocol.HoverClientCapabilities{
2019-12-09T20:42:57.367486_#1:                         DynamicRegistration: false,
2019-12-09T20:42:57.367486_#1:                         ContentFormat:       {"plaintext"},
2019-12-09T20:42:57.367486_#1:                     },
2019-12-09T20:42:57.367486_#1:                     SignatureHelp:      protocol.SignatureHelpClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     Declaration:        protocol.DeclarationClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     Definition:         protocol.DefinitionClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     TypeDefinition:     protocol.TypeDefinitionClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     Implementation:     protocol.ImplementationClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     References:         protocol.ReferenceClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     DocumentHighlight:  protocol.DocumentHighlightClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     DocumentSymbol:     protocol.DocumentSymbolClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     CodeAction:         protocol.CodeActionClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     CodeLens:           protocol.CodeLensClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     DocumentLink:       protocol.DocumentLinkClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     ColorProvider:      protocol.DocumentColorClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     Formatting:         protocol.DocumentFormattingClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     RangeFormatting:    protocol.DocumentRangeFormattingClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     OnTypeFormatting:   protocol.DocumentOnTypeFormattingClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     Rename:             protocol.RenameClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     FoldingRange:       protocol.FoldingRangeClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     SelectionRange:     protocol.SelectionRangeClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                     PublishDiagnostics: protocol.PublishDiagnosticsClientCapabilities{},
2019-12-09T20:42:57.367486_#1:                 },
2019-12-09T20:42:57.367486_#1:                 Window:              nil,
2019-12-09T20:42:57.367486_#1:                 Experimental:        nil,
2019-12-09T20:42:57.367486_#1:                 DynamicRegistration: false,
2019-12-09T20:42:57.367486_#1:             },
2019-12-09T20:42:57.367486_#1:             InitializationOptions: map[string]interface {}{
2019-12-09T20:42:57.367486_#1:                 "incrementalSync": bool(true),
2019-12-09T20:42:57.367486_#1:                 "noDocsOnHover":   bool(true),
2019-12-09T20:42:57.367486_#1:             },
2019-12-09T20:42:57.367486_#1:             Trace:                  "",
2019-12-09T20:42:57.367486_#1:             WorkDoneProgressParams: protocol.WorkDoneProgressParams{},
2019-12-09T20:42:57.367486_#1:         },
2019-12-09T20:42:57.367486_#1:         WorkspaceFoldersInitializeParams: protocol.WorkspaceFoldersInitializeParams{},
2019-12-09T20:42:57.367486_#1:     },
2019-12-09T20:42:57.367486_#1:     WorkDoneProgressParams: protocol.WorkDoneProgressParams{},
2019-12-09T20:42:57.367486_#1: }
2019-12-09T20:42:57.367486_#1: gopls server end =======================
2019-12-09T20:42:57.415780_#1: gopls server start =======================
2019-12-09T20:42:57.415780_#1: gopls.Initialize() return; err: ; res:
2019-12-09T20:42:57.415780_#1: &protocol.InitializeResult{
2019-12-09T20:42:57.415780_#1:     Capabilities: struct { TextDocumentSync interface {} "json:\"textDocumentSync,omitempty\""; CompletionProvider protocol.CompletionOptions "json:\"completionProvider,omitempty\""; HoverProvider bool "json:\"hoverProvider,omitempty\""; SignatureHelpProvider protocol.SignatureHelpOptions "json:\"signatureHelpProvider,omitempty\""; DeclarationProvider interface {} "json:\"declarationProvider,omitempty\""; DefinitionProvider bool "json:\"definitionProvider,omitempty\""; TypeDefinitionProvider interface {} "json:\"typeDefinitionProvider,omitempty\""; ImplementationProvider interface {} "json:\"implementationProvider,omitempty\""; ReferencesProvider bool "json:\"referencesProvider,omitempty\""; DocumentHighlightProvider bool "json:\"documentHighlightProvider,omitempty\""; DocumentSymbolProvider bool "json:\"documentSymbolProvider,omitempty\""; CodeActionProvider interface {} "json:\"codeActionProvider,omitempty\""; CodeLensProvider protocol.CodeLensOptions "json:\"codeLensProvider,omitempty\""; DocumentLinkProvider protocol.DocumentLinkOptions "json:\"documentLinkProvider,omitempty\""; ColorProvider interface {} "json:\"colorProvider,omitempty\""; WorkspaceSymbolProvider bool "json:\"workspaceSymbolProvider,omitempty\""; DocumentFormattingProvider bool "json:\"documentFormattingProvider,omitempty\""; DocumentRangeFormattingProvider bool "json:\"documentRangeFormattingProvider,omitempty\""; DocumentOnTypeFormattingProvider protocol.DocumentOnTypeFormattingOptions "json:\"documentOnTypeFormattingProvider,omitempty\""; RenameProvider interface {} "json:\"renameProvider,omitempty\""; FoldingRangeProvider interface {} "json:\"foldingRangeProvider,omitempty\""; SelectionRangeProvider interface {} "json:\"selectionRangeProvider,omitempty\""; ExecuteCommandProvider protocol.ExecuteCommandOptions "json:\"executeCommandProvider,omitempty\""; Experimental interface {} "json:\"experimental,omitempty\""; Workspace protocol.WorkspaceGn "json:\"workspace,omitempty\"" }{
2019-12-09T20:42:57.415780_#1:         TextDocumentSync: map[string]interface {}{
2019-12-09T20:42:57.415780_#1:             "openClose": bool(true),
2019-12-09T20:42:57.415780_#1:             "change":    float64(2),
2019-12-09T20:42:57.415780_#1:             "save":      map[string]interface {}{
2019-12-09T20:42:57.415780_#1:             },
2019-12-09T20:42:57.415780_#1:         },
2019-12-09T20:42:57.415780_#1:         CompletionProvider: protocol.CompletionOptions{
2019-12-09T20:42:57.415780_#1:             TriggerCharacters:       {"."},
2019-12-09T20:42:57.415780_#1:             AllCommitCharacters:     nil,
2019-12-09T20:42:57.415780_#1:             ResolveProvider:         false,
2019-12-09T20:42:57.415780_#1:             WorkDoneProgressOptions: protocol.WorkDoneProgressOptions{},
2019-12-09T20:42:57.415780_#1:         },
2019-12-09T20:42:57.415780_#1:         HoverProvider:         true,
2019-12-09T20:42:57.415780_#1:         SignatureHelpProvider: protocol.SignatureHelpOptions{
2019-12-09T20:42:57.415780_#1:             TriggerCharacters:       {"(", ","},
2019-12-09T20:42:57.415780_#1:             RetriggerCharacters:     nil,
2019-12-09T20:42:57.415780_#1:             WorkDoneProgressOptions: protocol.WorkDoneProgressOptions{},
2019-12-09T20:42:57.415780_#1:         },
2019-12-09T20:42:57.415780_#1:         DeclarationProvider:              nil,
2019-12-09T20:42:57.415780_#1:         DefinitionProvider:               true,
2019-12-09T20:42:57.415780_#1:         TypeDefinitionProvider:           bool(true),
2019-12-09T20:42:57.415780_#1:         ImplementationProvider:           bool(true),
2019-12-09T20:42:57.415780_#1:         ReferencesProvider:               true,
2019-12-09T20:42:57.415780_#1:         DocumentHighlightProvider:        true,
2019-12-09T20:42:57.415780_#1:         DocumentSymbolProvider:           true,
2019-12-09T20:42:57.415780_#1:         CodeActionProvider:               bool(true),
2019-12-09T20:42:57.415780_#1:         CodeLensProvider:                 protocol.CodeLensOptions{},
2019-12-09T20:42:57.415780_#1:         DocumentLinkProvider:             protocol.DocumentLinkOptions{},
2019-12-09T20:42:57.415780_#1:         ColorProvider:                    nil,
2019-12-09T20:42:57.415780_#1:         WorkspaceSymbolProvider:          false,
2019-12-09T20:42:57.415780_#1:         DocumentFormattingProvider:       true,
2019-12-09T20:42:57.415780_#1:         DocumentRangeFormattingProvider:  false,
2019-12-09T20:42:57.415780_#1:         DocumentOnTypeFormattingProvider: protocol.DocumentOnTypeFormattingOptions{},
2019-12-09T20:42:57.415780_#1:         RenameProvider:                   bool(true),
2019-12-09T20:42:57.415780_#1:         FoldingRangeProvider:             bool(true),
2019-12-09T20:42:57.415780_#1:         SelectionRangeProvider:           nil,
2019-12-09T20:42:57.415780_#1:         ExecuteCommandProvider:           protocol.ExecuteCommandOptions{
2019-12-09T20:42:57.415780_#1:             Commands:                {"tidy"},
2019-12-09T20:42:57.415780_#1:             WorkDoneProgressOptions: protocol.WorkDoneProgressOptions{},
2019-12-09T20:42:57.415780_#1:         },
2019-12-09T20:42:57.415780_#1:         Experimental: nil,
2019-12-09T20:42:57.415780_#1:         Workspace:    protocol.WorkspaceGn{
2019-12-09T20:42:57.415780_#1:             WorkspaceFolders: protocol.WorkspaceFoldersGn{Supported:true, ChangeNotifications:"workspace/didChangeWorkspaceFolders"},
2019-12-09T20:42:57.415780_#1:         },
2019-12-09T20:42:57.415780_#1:     },
2019-12-09T20:42:57.415780_#1:     ServerInfo: struct { Name string "json:\"name\""; Version string "json:\"version,omitempty\"" }{},
2019-12-09T20:42:57.415780_#1: }
2019-12-09T20:42:57.415780_#1: gopls server end =======================
2019-12-09T20:42:57.415838_#1: gopls server start =======================
2019-12-09T20:42:57.415838_#1: gopls.Initialized() call; params:
2019-12-09T20:42:57.415838_#1: &protocol.InitializedParams{}
2019-12-09T20:42:57.415838_#1: gopls server end =======================
2019-12-09T20:42:57.415899_#1: gopls server start =======================
2019-12-09T20:42:57.415899_#1: gopls.Initialized() return; err: 
2019-12-09T20:42:57.415899_#1: gopls server end =======================
2019-12-09T20:42:57.416419_#1: gopls client start =======================
2019-12-09T20:42:57.416419_#1: RegisterCapability: &protocol.RegistrationParams{
2019-12-09T20:42:57.416419_#1:     Registrations: {
2019-12-09T20:42:57.416419_#1:         {
2019-12-09T20:42:57.416419_#1:             ID:              "workspace/didChangeConfiguration",
2019-12-09T20:42:57.416419_#1:             Method:          "workspace/didChangeConfiguration",
2019-12-09T20:42:57.416419_#1:             RegisterOptions: nil,
2019-12-09T20:42:57.416419_#1:         },
2019-12-09T20:42:57.416419_#1:         {
2019-12-09T20:42:57.416419_#1:             ID:              "workspace/didChangeWorkspaceFolders",
2019-12-09T20:42:57.416419_#1:             Method:          "workspace/didChangeWorkspaceFolders",
2019-12-09T20:42:57.416419_#1:             RegisterOptions: nil,
2019-12-09T20:42:57.416419_#1:         },
2019-12-09T20:42:57.416419_#1:     },
2019-12-09T20:42:57.416419_#1: }
2019-12-09T20:42:57.416419_#1: gopls client end =======================
2019-12-09T20:42:57.466230_#1: gopls client start =======================
2019-12-09T20:42:57.466230_#1: Configuration: &protocol.ParamConfiguration{
2019-12-09T20:42:57.466230_#1:     ConfigurationParams: protocol.ConfigurationParams{
2019-12-09T20:42:57.466230_#1:         Items: {
2019-12-09T20:42:57.466230_#1:             {ScopeURI:"file:///tmp/go-test-script458939670/script-format_on_save_new_file_existing_package", Section:"gopls"},
2019-12-09T20:42:57.466230_#1:             {ScopeURI:"file:///tmp/go-test-script458939670/script-format_on_save_new_file_existing_package", Section:"gopls-script-format_on_save_new_file_existing_package"},
2019-12-09T20:42:57.466230_#1:         },
2019-12-09T20:42:57.466230_#1:     },
2019-12-09T20:42:57.466230_#1:     PartialResultParams: protocol.PartialResultParams{},
2019-12-09T20:42:57.466230_#1: }
2019-12-09T20:42:57.466230_#1: gopls client end =======================
2019-12-09T20:42:57.466336_#1: gopls client start =======================
2019-12-09T20:42:57.466336_#1: Configuration response: []interface {}{
2019-12-09T20:42:57.466336_#1:     map[string]interface {}{
2019-12-09T20:42:57.466336_#1:         "hoverKind":   "FullDocumentation",
2019-12-09T20:42:57.466336_#1:         "staticcheck": &bool(false),
2019-12-09T20:42:57.466336_#1:     },
2019-12-09T20:42:57.466336_#1:     nil,
2019-12-09T20:42:57.466336_#1: }
2019-12-09T20:42:57.466336_#1: gopls client end =======================
2019-12-09T20:42:57.466607_#1: gopls client start =======================
2019-12-09T20:42:57.466607_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/09 20:42:57 Build info\n----------\ngolang.org/x/tools/gopls master\n    golang.org/x/tools/gopls@v0.1.8-0.20191206204035-259af5ff87bd h1:6k7G3XVlkl2O93ZpeX0M8jIATGDWZAI00gcZNRReYew=\n    github.com/BurntSushi/toml@v0.3.1 h1:WXkYYl6Yr3qBf1K79EBnL4mak0OimBfB0XUf9Vl28OQ=\n    github.com/sergi/go-diff@v1.0.0 h1:Kpca3qRNrduNnOQeazBd0ysaKrUJiIuISHxogkT9RPQ=\n    golang.org/x/sync@v0.0.0-20190423024810-112230192c58 h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU=\n    golang.org/x/tools@v0.0.0-20191206204035-259af5ff87bd h1:Zc7EU2PqpsNeIfOoVA7hvQX4cS3YDJEs5KlfatT3hLo=\n    golang.org/x/xerrors@v0.0.0-20190717185122-a985d3407aa7 h1:9zdDQZ7Thm29KFXgAX/+yaf3eVbP7djjWp/dXAppNCc=\n    honnef.co/go/tools@v0.0.1-2019.2.3 h1:3JgtbtFHMiCmsznwGVTUWbgGov+pVqnlf1dEJTNAXeM=\n\nGo info\n-------\ngo version devel +da4d58587e Sat Dec 7 15:57:30 2019 +0000 linux/amd64\n\nGO111MODULE=\"\"\nGOARCH=\"amd64\"\nGOBIN=\"\"\nGOCACHE=\"/tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/.home/.cache/go-build\"\nGOENV=\"/tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/.home/.config/go/env\"\nGOEXE=\"\"\nGOFLAGS=\"\"\nGOHOSTARCH=\"amd64\"\nGOHOSTOS=\"linux\"\nGOINSECURE=\"\"\nGONOPROXY=\"\"\nGONOSUMDB=\"*\"\nGOOS=\"linux\"\nGOPATH=\"/tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/.home/go\"\nGOPRIVATE=\"\"\nGOPROXY=\"http://127.0.0.1:37691/mod\"\nGOROOT=\"/home/myitcv/dev/go\"\nGOSUMDB=\"sum.golang.org\"\nGOTMPDIR=\"\"\nGOTOOLDIR=\"/home/myitcv/dev/go/pkg/tool/linux_amd64\"\nGCCGO=\"gccgo\"\nAR=\"ar\"\nCC=\"gcc\"\nCXX=\"g++\"\nCGO_ENABLED=\"1\"\nGOMOD=\"/home/myitcv/gostuff/src/github.com/myitcv/govim/go.mod\"\nCGO_CFLAGS=\"-g -O2\"\nCGO_CPPFLAGS=\"\"\nCGO_CXXFLAGS=\"-g -O2\"\nCGO_FFLAGS=\"-g -O2\"\nCGO_LDFLAGS=\"-g -O2\"\nPKG_CONFIG=\"pkg-config\"\nGOGCCFLAGS=\"-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/_tmp/go-build607023757=/tmp/go-build -gno-record-gcc-switches\"\n"}
2019-12-09T20:42:57.466607_#1: gopls client end =======================
2019-12-09T20:42:57.473456_#1: vim start =======================
2019-12-09T20:42:57.473456_#1: sendJSONMsg: [0,[44,"initcomplete"]]
2019-12-09T20:42:57.473456_#1: vim end =======================
2019-12-09T20:42:57.476301_#1: vim start =======================
2019-12-09T20:42:57.476301_#1: recvJSONMsg: [45] ["callback",44,[""]]
2019-12-09T20:42:57.476301_#1: vim end =======================
2019-12-09T20:42:57.476403_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.479885_#1: vim start =======================
2019-12-09T20:42:57.479885_#1: sendJSONMsg: [0,[45,"call","s:schedule",1]]
2019-12-09T20:42:57.479885_#1: vim end =======================
2019-12-09T20:42:57.485973_#1: vim start =======================
2019-12-09T20:42:57.485973_#1: recvJSONMsg: [46] ["schedule",1]
2019-12-09T20:42:57.485973_#1: vim end =======================
2019-12-09T20:42:57.486027_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.486060_#1: vim start =======================
2019-12-09T20:42:57.486060_#1: sendJSONMsg: [0,[46,"ex","e main.go"]]
2019-12-09T20:42:57.486060_#1: vim end =======================
2019-12-09T20:42:57.486547_#1: vim start =======================
2019-12-09T20:42:57.486547_#1: recvJSONMsg: [47] ["function","autocommand:0",[1]]
2019-12-09T20:42:57.486547_#1: vim end =======================
2019-12-09T20:42:57.486607_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.486649_#1: vim start =======================
2019-12-09T20:42:57.486649_#1: sendJSONMsg: [47,["",null]]
2019-12-09T20:42:57.486649_#1: vim end =======================
2019-12-09T20:42:57.489071_#1: vim start =======================
2019-12-09T20:42:57.489071_#1: recvJSONMsg: [48] ["function","autocommand:1",[{"Num":1,"Name":"/tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/main.go","Loaded":1,"Contents":"package main\n\nfunc main() {\n}\n"}]]
2019-12-09T20:42:57.489071_#1: vim end =======================
2019-12-09T20:42:57.489120_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.489192_#1: vim start =======================
2019-12-09T20:42:57.489192_#1: sendJSONMsg: [0,[47,"call","listener_add","GOVIM_internal_EnrichDelta",1]]
2019-12-09T20:42:57.489192_#1: vim end =======================
2019-12-09T20:42:57.489508_#1: vim start =======================
2019-12-09T20:42:57.489508_#1: recvJSONMsg: [49] ["callback",47,["",1]]
2019-12-09T20:42:57.489508_#1: vim end =======================
2019-12-09T20:42:57.489580_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.489628_#1: vim start =======================
2019-12-09T20:42:57.489628_#1: sendJSONMsg: [0,[48,"call","s:batchCall",[["call","s:mustBeZero","sign_unplace","govim"]]]]
2019-12-09T20:42:57.489628_#1: vim end =======================
2019-12-09T20:42:57.489939_#1: vim start =======================
2019-12-09T20:42:57.489939_#1: recvJSONMsg: [50] ["callback",48,["",[0]]]
2019-12-09T20:42:57.489939_#1: vim end =======================
2019-12-09T20:42:57.489987_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.490048_#1: gopls server start =======================
2019-12-09T20:42:57.490048_#1: gopls.DidOpen() call; params:
2019-12-09T20:42:57.490048_#1: &protocol.DidOpenTextDocumentParams{
2019-12-09T20:42:57.490048_#1:     TextDocument: protocol.TextDocumentItem{URI:"file:///tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/main.go", LanguageID:"go", Version:1, Text:"package main\n\nfunc main() {\n}\n"},
2019-12-09T20:42:57.490048_#1: }
2019-12-09T20:42:57.490048_#1: gopls server end =======================
2019-12-09T20:42:57.490142_#1: gopls server start =======================
2019-12-09T20:42:57.490142_#1: gopls.DidOpen() return; err: 
2019-12-09T20:42:57.490142_#1: gopls server end =======================
2019-12-09T20:42:57.490173_#1: vim start =======================
2019-12-09T20:42:57.490173_#1: sendJSONMsg: [48,["",null]]
2019-12-09T20:42:57.490173_#1: vim end =======================
2019-12-09T20:42:57.491519_#1: vim start =======================
2019-12-09T20:42:57.491519_#1: recvJSONMsg: [51] ["callback",46,[""]]
2019-12-09T20:42:57.491519_#1: vim end =======================
2019-12-09T20:42:57.491557_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.491577_#1: vim start =======================
2019-12-09T20:42:57.491577_#1: sendJSONMsg: [46,["",""]]
2019-12-09T20:42:57.491577_#1: vim end =======================
2019-12-09T20:42:57.491775_#1: vim start =======================
2019-12-09T20:42:57.491775_#1: recvJSONMsg: [52] ["callback",45,["",0]]
2019-12-09T20:42:57.491775_#1: vim end =======================
2019-12-09T20:42:57.491826_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.496632_#1: vim start =======================
2019-12-09T20:42:57.496632_#1: sendJSONMsg: [0,[49,"call","s:schedule",2]]
2019-12-09T20:42:57.496632_#1: vim end =======================
2019-12-09T20:42:57.497706_#1: vim start =======================
2019-12-09T20:42:57.497706_#1: recvJSONMsg: [53] ["schedule",2]
2019-12-09T20:42:57.497706_#1: vim end =======================
2019-12-09T20:42:57.497749_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.497794_#1: vim start =======================
2019-12-09T20:42:57.497794_#1: sendJSONMsg: [0,[50,"ex","e const.go"]]
2019-12-09T20:42:57.497794_#1: vim end =======================
2019-12-09T20:42:57.498754_#1: vim start =======================
2019-12-09T20:42:57.498754_#1: recvJSONMsg: [54] ["function","autocommand:0",[1]]
2019-12-09T20:42:57.498754_#1: vim end =======================
2019-12-09T20:42:57.498787_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.498849_#1: vim start =======================
2019-12-09T20:42:57.498849_#1: sendJSONMsg: [54,["",null]]
2019-12-09T20:42:57.498849_#1: vim end =======================
2019-12-09T20:42:57.501788_#1: vim start =======================
2019-12-09T20:42:57.501788_#1: recvJSONMsg: [55] ["function","autocommand:1",[{"Num":3,"Name":"/tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/const.go","Loaded":1,"Contents":"\n"}]]
2019-12-09T20:42:57.501788_#1: vim end =======================
2019-12-09T20:42:57.501831_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.501903_#1: vim start =======================
2019-12-09T20:42:57.501903_#1: sendJSONMsg: [0,[51,"call","listener_add","GOVIM_internal_EnrichDelta",3]]
2019-12-09T20:42:57.501903_#1: vim end =======================
2019-12-09T20:42:57.502156_#1: vim start =======================
2019-12-09T20:42:57.502156_#1: recvJSONMsg: [56] ["callback",51,["",2]]
2019-12-09T20:42:57.502156_#1: vim end =======================
2019-12-09T20:42:57.502183_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.502212_#1: vim start =======================
2019-12-09T20:42:57.502212_#1: sendJSONMsg: [0,[52,"call","s:batchCall",[["call","s:mustBeZero","sign_unplace","govim"]]]]
2019-12-09T20:42:57.502212_#1: vim end =======================
2019-12-09T20:42:57.502519_#1: vim start =======================
2019-12-09T20:42:57.502519_#1: recvJSONMsg: [57] ["callback",52,["",[0]]]
2019-12-09T20:42:57.502519_#1: vim end =======================
2019-12-09T20:42:57.502557_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.502623_#1: gopls server start =======================
2019-12-09T20:42:57.502623_#1: gopls.DidOpen() call; params:
2019-12-09T20:42:57.502623_#1: &protocol.DidOpenTextDocumentParams{
2019-12-09T20:42:57.502623_#1:     TextDocument: protocol.TextDocumentItem{URI:"file:///tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/const.go", LanguageID:"go", Version:1, Text:"\n"},
2019-12-09T20:42:57.502623_#1: }
2019-12-09T20:42:57.502623_#1: gopls server end =======================
2019-12-09T20:42:57.502674_#1: gopls server start =======================
2019-12-09T20:42:57.502674_#1: gopls.DidOpen() return; err: 
2019-12-09T20:42:57.502674_#1: gopls server end =======================
2019-12-09T20:42:57.502687_#1: vim start =======================
2019-12-09T20:42:57.502687_#1: sendJSONMsg: [55,["",null]]
2019-12-09T20:42:57.502687_#1: vim end =======================
2019-12-09T20:42:57.502746_#1: info only: failed to parse buffer /tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/const.go: /tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/const.go:1:2: expected ';', found 'EOF' (and 2 more errors)
2019-12-09T20:42:57.505422_#1: vim start =======================
2019-12-09T20:42:57.505422_#1: recvJSONMsg: [58] ["callback",50,[""]]
2019-12-09T20:42:57.505422_#1: vim end =======================
2019-12-09T20:42:57.505449_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.505472_#1: vim start =======================
2019-12-09T20:42:57.505472_#1: sendJSONMsg: [53,["",""]]
2019-12-09T20:42:57.505472_#1: vim end =======================
2019-12-09T20:42:57.505749_#1: vim start =======================
2019-12-09T20:42:57.505749_#1: recvJSONMsg: [59] ["callback",49,["",0]]
2019-12-09T20:42:57.505749_#1: vim end =======================
2019-12-09T20:42:57.505809_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.513321_#1: vim start =======================
2019-12-09T20:42:57.513321_#1: sendJSONMsg: [0,[53,"call","s:schedule",3]]
2019-12-09T20:42:57.513321_#1: vim end =======================
2019-12-09T20:42:57.513762_#1: vim start =======================
2019-12-09T20:42:57.513762_#1: recvJSONMsg: [60] ["schedule",3]
2019-12-09T20:42:57.513762_#1: vim end =======================
2019-12-09T20:42:57.513819_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.513852_#1: vim start =======================
2019-12-09T20:42:57.513852_#1: sendJSONMsg: [0,[54,"ex","r const.txt"]]
2019-12-09T20:42:57.513852_#1: vim end =======================
2019-12-09T20:42:57.514253_#1: vim start =======================
2019-12-09T20:42:57.514253_#1: recvJSONMsg: [61] ["callback",54,[""]]
2019-12-09T20:42:57.514253_#1: vim end =======================
2019-12-09T20:42:57.514302_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.514321_#1: vim start =======================
2019-12-09T20:42:57.514321_#1: sendJSONMsg: [60,["",""]]
2019-12-09T20:42:57.514321_#1: vim end =======================
2019-12-09T20:42:57.514421_#1: vim start =======================
2019-12-09T20:42:57.514421_#1: recvJSONMsg: [62] ["function","function:GOVIM_internal_BufChanged",[3,2,2,1,[{"lnum":2,"col":1,"added":1,"end":2,"lines":["package main"]}]]]
2019-12-09T20:42:57.514421_#1: vim end =======================
2019-12-09T20:42:57.514461_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.514649_#1: gopls server start =======================
2019-12-09T20:42:57.514649_#1: gopls.DidChange() call; params:
2019-12-09T20:42:57.514649_#1: &protocol.DidChangeTextDocumentParams{
2019-12-09T20:42:57.514649_#1:     TextDocument: protocol.VersionedTextDocumentIdentifier{
2019-12-09T20:42:57.514649_#1:         Version:                2,
2019-12-09T20:42:57.514649_#1:         TextDocumentIdentifier: protocol.TextDocumentIdentifier{URI:"file:///tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/const.go"},
2019-12-09T20:42:57.514649_#1:     },
2019-12-09T20:42:57.514649_#1:     ContentChanges: {
2019-12-09T20:42:57.514649_#1:         {
2019-12-09T20:42:57.514649_#1:             Range: &protocol.Range{
2019-12-09T20:42:57.514649_#1:                 Start: protocol.Position{Line:1, Character:0},
2019-12-09T20:42:57.514649_#1:                 End:   protocol.Position{Line:1, Character:0},
2019-12-09T20:42:57.514649_#1:             },
2019-12-09T20:42:57.514649_#1:             RangeLength: 0,
2019-12-09T20:42:57.514649_#1:             Text:        "package main\n",
2019-12-09T20:42:57.514649_#1:         },
2019-12-09T20:42:57.514649_#1:     },
2019-12-09T20:42:57.514649_#1: }
2019-12-09T20:42:57.514649_#1: gopls server end =======================
2019-12-09T20:42:57.514796_#1: gopls server start =======================
2019-12-09T20:42:57.514796_#1: gopls.DidChange() return; err: 
2019-12-09T20:42:57.514796_#1: gopls server end =======================
2019-12-09T20:42:57.514808_#1: vim start =======================
2019-12-09T20:42:57.514808_#1: sendJSONMsg: [62,["",null]]
2019-12-09T20:42:57.514808_#1: vim end =======================
2019-12-09T20:42:57.515035_#1: vim start =======================
2019-12-09T20:42:57.515035_#1: recvJSONMsg: [63] ["callback",53,["",0]]
2019-12-09T20:42:57.515035_#1: vim end =======================
2019-12-09T20:42:57.515069_#1: run: waiting to read a JSON message
2019-12-09T20:42:57.518871_#1: gopls client start =======================
2019-12-09T20:42:57.518871_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/09 20:42:57 go/packages.Load\n\tpackages = 1"}
2019-12-09T20:42:57.518871_#1: gopls client end =======================
2019-12-09T20:42:57.518937_#1: gopls client start =======================
2019-12-09T20:42:57.518937_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/09 20:42:57 go/packages.Load\n\tpackage = mod.com\n\tfiles = [/tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/main.go]"}
2019-12-09T20:42:57.518937_#1: gopls client end =======================
2019-12-09T20:42:57.520750_#1: gopls stderr: 2019/12/09 20:42:57 failed to run analyses: no package for mod.com
2019-12-09T20:42:57.520763_#1: gopls stderr: 	file = file:///tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/main.go
2019-12-09T20:42:57.520940_#1: gopls stderr: 2019/12/09 20:42:57 diagnoseFile: could not generate diagnostics: couldn't exec 'go [list -f {{context.GOARCH}} {{context.Compiler}} -- unsafe]': context canceled *errors.errorString
2019-12-09T20:42:57.521223_#1: gopls client start =======================
2019-12-09T20:42:57.521223_#1: LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2019/12/09 20:42:57 diagnoseFile: could not generate diagnostics: couldn't exec 'go [list -f {{context.GOARCH}} {{context.Compiler}} -- unsafe]': context canceled *errors.errorString"}
2019-12-09T20:42:57.521223_#1: gopls client end =======================
2019-12-09T20:42:57.521282_#1: gopls client start =======================
2019-12-09T20:42:57.521282_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/09 20:42:57 go/packages.Load\n\tpackages = 0"}
2019-12-09T20:42:57.521282_#1: gopls client end =======================
2019-12-09T20:42:57.521685_#1: gopls client start =======================
2019-12-09T20:42:57.521685_#1: LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2019/12/09 20:42:57 failed to run analyses: no package for mod.com\n\tfile = file:///tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/main.go"}
2019-12-09T20:42:57.521685_#1: gopls client end =======================
2019-12-09T20:42:57.566794_#1: gopls client start =======================
2019-12-09T20:42:57.566794_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/09 20:42:57 go/packages.Load\n\tpackages = 1"}
2019-12-09T20:42:57.566794_#1: gopls client end =======================
2019-12-09T20:42:57.566893_#1: gopls client start =======================
2019-12-09T20:42:57.566893_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/09 20:42:57 go/packages.Load\n\tpackage = mod.com\n\tfiles = [/tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/main.go /tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/const.go]"}
2019-12-09T20:42:57.566893_#1: gopls client end =======================
2019-12-09T20:42:57.567239_#1: gopls client start =======================
2019-12-09T20:42:57.567239_#1: PublishDiagnostics callback: &protocol.PublishDiagnosticsParams{
2019-12-09T20:42:57.567239_#1:     URI:         "file:///tmp/go-test-script458939670/script-format_on_save_new_file_existing_package/main.go",
2019-12-09T20:42:57.567239_#1:     Version:     1,
2019-12-09T20:42:57.567239_#1:     Diagnostics: {
2019-12-09T20:42:57.567239_#1:     },
2019-12-09T20:42:57.567239_#1: }
2019-12-09T20:42:57.567239_#1: gopls client end =======================
2019-12-09T20:42:58.009441_#1: vim start =======================
2019-12-09T20:42:58.009441_#1: recvJSONMsg: [64] ["function","function:GOVIM_internal_SetUserBusy",[1]]
2019-12-09T20:42:58.009441_#1: vim end =======================
2019-12-09T20:42:58.009557_#1: run: waiting to read a JSON message
2019-12-09T20:42:58.009657_#1: vim start =======================
2019-12-09T20:42:58.009657_#1: sendJSONMsg: [64,["",null]]
2019-12-09T20:42:58.009657_#1: vim end =======================
2019-12-09T20:43:01.390583_#1: vim start =======================
2019-12-09T20:43:01.390583_#1: sendJSONMsg: [0,[55,"call","s:schedule",4]]
2019-12-09T20:43:01.390583_#1: vim end =======================
2019-12-09T20:43:01.391404_#1: vim start =======================
2019-12-09T20:43:01.391404_#1: recvJSONMsg: [65] ["schedule",4]
2019-12-09T20:43:01.391404_#1: vim end =======================
2019-12-09T20:43:01.391476_#1: run: waiting to read a JSON message
2019-12-09T20:43:01.391540_#1: vim start =======================
2019-12-09T20:43:01.391540_#1: sendJSONMsg: [0,[56,"ex","qall!"]]
2019-12-09T20:43:01.391540_#1: vim end =======================
2019-12-09T20:43:01.392164_#1: vim start =======================
2019-12-09T20:43:01.392164_#1: recvJSONMsg: [66] ["function","autocommand:0",[3]]
2019-12-09T20:43:01.392164_#1: vim end =======================
2019-12-09T20:43:01.392235_#1: run: waiting to read a JSON message
2019-12-09T20:43:01.392292_#1: vim start =======================
2019-12-09T20:43:01.392292_#1: sendJSONMsg: [66,["",null]]
2019-12-09T20:43:01.392292_#1: vim end =======================
2019-12-09T20:43:01.392919_#1: vim start =======================
2019-12-09T20:43:01.392919_#1: closing connection
2019-12-09T20:43:01.392919_#1: vim end =======================
2019-12-09T20:43:01.393004_#1: gopls server start =======================
2019-12-09T20:43:01.393004_#1: gopls.Shutdown() call
2019-12-09T20:43:01.393004_#1: gopls server end =======================
2019-12-09T20:43:01.393099_#1: vim start =======================
2019-12-09T20:43:01.393099_#1: sendJSONMsg: [65,["",""]]
2019-12-09T20:43:01.393099_#1: vim end =======================
2019-12-09T20:43:01.394083_#1: gopls server start =======================
2019-12-09T20:43:01.394083_#1: gopls.Shutdown() return; err: 
2019-12-09T20:43:01.394083_#1: gopls server end =======================
2019-12-09T20:43:01.394604_#1: gopls stderr: gopls: failed reading header line "EOF"
    TestScripts/scenario_default/format_on_save_new_file_existing_package: testscript.go:316: 
        WORK=$WORK
        PATH=/home/myitcv/gostuff/knownbin:/home/myitcv/gos/misc/wasm:/home/myitcv/bin/myitcv_io_go:/home/myitcv/bin:/home/myitcv/gos/misc/wasm:/home/myitcv/bin/myitcv_io_go:/home/myitcv/bin:/home/myitcv/bin/bingo:/home/myitcv/nodes/bin:/home/myitcv/nodes/bin:/home/myitcv/rubys/bin:/home/myitcv/python3s/bin:/home/myitcv/pythons/bin:/home/myitcv/bin:/home/myitcv/usr/google-cloud-sdk/bin:/home/myitcv/usr/chromedriver:/home/myitcv/usr/wabt/bin:/home/myitcv/usr/git/bin:/home/myitcv/usr/clang/bin:/home/myitcv/dev/vim/src:/home/myitcv/usr/vim/bin:/home/myitcv/usr/bin:/sbin:/usr/sbin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/home/myitcv/gos/bin:/home/myitcv/Android/Sdk/tools:/home/myitcv/Android/Sdk/platform-tools:/home/myitcv/.vim/plugged/fzf/bin
        HOME=$WORK/.home
        TMPDIR=$WORK/_tmp
        devnull=/dev/null
        :=:
        exe=
        GOPROXY=http://127.0.0.1:37691/mod
        GONOSUMDB=*
        PLUGIN_PATH=/home/myitcv/gostuff/src/github.com/myitcv/govim
        CURRENT_GOPATH=/home/myitcv/gostuff
        GOVIMTEST_SOCKET=127.0.0.1:41043
        GOVIMTESTDRIVER_SOCKET=0.0.0.0:45957
    # Test format on save for a file that does not yet exist on disk in the
    # context of a package that does already exist (3.919s)
    > vim ex 'e main.go'
    > vim ex 'e const.go'
    > vim ex 'r const.txt'
    > errlogmatch 'PublishDiagnostics callback: &protocol.PublishDiagnosticsParams{\n\S+:\s+URI:\s+"file://'$WORK/const.go
    FAIL: testdata/scenario_default/format_on_save_new_file_existing_package.txt:7: errlogmatch failed to find match

--- FAIL: TestScripts (5.36s)
--- FAIL: TestScripts/scenario_default (0.00s)
--- FAIL: TestScripts/scenario_default/format_on_save_new_file_existing_package (4.15s)
FAIL
FAIL github.com/govim/govim/cmd/govim 5.366s
FAIL

@heschi
Copy link
Contributor

heschi commented Dec 9, 2019

Thanks, repros nicely. I think this is metadata corruption:

2019/12/09 17:08:14 diagnoseFile: publishing diagnostics for file:///tmp/go-test-script976794166/script-format_on_save_new_file_existing_package/const.go: map[source.FileIdentity][]source.Diagnostic{source.FileIdentity{URI:"file:///tmp/go-test-script976794166/script-format_on_save_new_file_existing_package/main.go", Version:1, Identifier:"2a9644c7924cdfe6aaae09d857d1e6c0b4a1363d", Kind:0}:[]source.Diagnostic{}}

We try to generate diagnostics for const.go, which involves running diagnostics on the whole package, but somehow we don't know that const.go is in the package.

@gopherbot
Copy link

Change https://golang.org/cl/210559 mentions this issue: internal/lsp/cache: invalidate metadata even without Create

@myitcv
Copy link
Member Author

myitcv commented Dec 9, 2019

In a similar vein, the following govim test is also failing:

GOVIM_TESTSCRIPT_STDERR=true go test -count=1 -v -run "TestScripts/scenario_default/quickfix_retain_position" ./cmd/govim

with what appears to be the root cause of:

[Trace - 22:51:09.782 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2019/12/09 22:51:09 diagnoseFile: could not generate diagnostics: couldn't exec 'go [list -f {{context.GOARCH}} {{context.Compiler}} -- unsafe]': context canceled *errors.errorString"}

@heschi
Copy link
Contributor

heschi commented Dec 9, 2019

When I run that test I get the following output:

--- FAIL: TestScripts (2.61s)
    --- FAIL: TestScripts/scenario_default (0.00s)
        --- FAIL: TestScripts/scenario_default/quickfix_retain_position (1.17s)
            testscript.go:316: 
                # Test that the quickfix window logic around retaining its selected item
                # First ensure we get the expected errors (0.386s)
                # Disabled pending resolution to https://github.com/golang/go/issues/34103
                # errlogmatch -count=0 'LogMessage callback: &protocol\.LogMessageParams\{Type:(1|2), Message:".*'
                # Verify we have the first entry selected (0.014s)
                # Now move to the next error and check the position (0.020s)
                # Now add another error and check the index (0.142s)
                > cp other.go.orig other.go
                > errlogmatch 'sendJSONMsg: \[0,\[\d+,"call","s:batchCall",\[\["call","s:mustNothing","setqflist"'
                > vim ex 'copen'
                > vim ex 'w errors'
                > cmp errors errors.golden.updated
                [diff -errors +errors.golden.updated]
                 main.go|6 col 2| undeclared name: asdf
                 main.go|8 col 2| undeclared name: fdas
                +other.go|3 col 1| expected declaration, found asdf
                
                FAIL: testdata/scenario_default/quickfix_retain_position.txt:28: errors and errors.golden.updated differ

I don't see any reason errors from other.go shouldn't be in the diagnostics list, so that looks fine to me. The cancellation errors from diagnosis are generally harmless. Please file a new issue if you think something's up.

@myitcv
Copy link
Member Author

myitcv commented Dec 9, 2019

Per my Slack message, I'm still seeing the TestScripts/scenario_default/format_on_save_new_file_existing_package test fail even with 22774f7. It fails less often, but when it fails it fails for the same reason explained above. i.e. we don't get diagnostics for const.go.

@myitcv myitcv reopened this Dec 9, 2019
@myitcv
Copy link
Member Author

myitcv commented Dec 9, 2019

I don't see any reason errors from other.go shouldn't be in the diagnostics list, so that looks fine to me.

That's just the problem; they're not in the errors list, and that's why the test is failing. Hence why I think it's related to/the same as this issue.

Please file a new issue if you think something's up.

I'll wait until we have a resolution on this issue first.

@heschi
Copy link
Contributor

heschi commented Dec 9, 2019

Ah, got it. Maybe, I'll take a look tomorrow.

@heschi
Copy link
Contributor

heschi commented Dec 9, 2019

I think that quickfix_retain_position is just getting an early diagnostics notification it's not set up to handle. From what I can tell the server is in the process of publishing another one when it's shut down. Certainly the test doesn't hang for 30 seconds like format_on_save_new_file_existing_package used to.

On my workstation format_on_save_new_file_existing_package passes 100 times. I uploaded https://golang.org/cl/210560; if you could pull a log for me with that I'd appreciate it.

@myitcv
Copy link
Member Author

myitcv commented Dec 10, 2019

Just re-ran format_on_save_new_file_existing_package on my machine using CL 210560. First time it failed, second time it passed. Both logs attached

@myitcv
Copy link
Member Author

myitcv commented Dec 10, 2019

I think that quickfix_retain_position is just getting an early diagnostics notification it's not set up to handle.

Ah, good spot, I see what's happened here. We refactored diagnostic handling recently and the errlogmatch line that is meant to block pending the diagnostics arriving for other.go was not updated. Now fixed, and that test now reliably passes.

@myitcv
Copy link
Member Author

myitcv commented Dec 10, 2019

FWIW we just implemented DidSave to be sure the lack of this wasn't having any bearing on our tests.

Still see format_on_save_new_file_existing_package failing. Using CL 210560 I've also pulled logs for that:

@heschi
Copy link
Contributor

heschi commented Dec 10, 2019

Fun. We load, discover const.go in mod.com, and then...immediately forget?

[Trace - 12:35:48.337 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2019/12/10 12:35:48 go/packages.Load\n\tpackage = mod.com\n\tfiles = [/tmp/go-test-script702193888/script-format_on_save_new_file_existing_package/main.go /tmp/go-test-script702193888/script-format_on_save_new_file_existing_package/const.go]"}


2019/12/10 12:35:48 diagnoseFile: publishing diagnostics for file:///tmp/go-test-script702193888/script-format_on_save_new_file_existing_package/const.go: map[source.FileIdentity][]source.Diagnostic{source.FileIdentity{URI:"file:///tmp/go-test-script702193888/script-format_on_save_new_file_existing_package/main.go", Version:1, Identifier:"2a9644c7924cdfe6aaae09d857d1e6c0b4a1363d", Kind:0}:[]source.Diagnostic{}}

This is going to take more iteration. I'm still kind of a GitHub noob. Is triggering a Travis build as simple as sending a PR, or do I need some permissions?

@myitcv
Copy link
Member Author

myitcv commented Dec 10, 2019

Is triggering a Travis build as simple as sending a PR

Yes. So fork govim, fork tools, replace x/tools and gopls with a commit in your fork version, create a branch of govim, push branch with changes to your fork, create a PR with a subject prefix of [DO NOT MERGE]. (Do not mark [WIP] otherwise you will skip a number of the builds in the matrix)

@myitcv
Copy link
Member Author

myitcv commented Dec 11, 2019

Just re-ran against patchset 2 of CL 210560. Still see format_on_save_new_file_existing_package failing:

@myitcv
Copy link
Member Author

myitcv commented Dec 11, 2019

Just re-ran against patchset 3 of CL 210560. Still see format_on_save_new_file_existing_package failing:

@myitcv
Copy link
Member Author

myitcv commented Dec 11, 2019

Just re-ran against patchset 4 of CL 210560. Still see format_on_save_new_file_existing_package failing:

@myitcv
Copy link
Member Author

myitcv commented Dec 11, 2019

Just re-ran against patchset 5 of CL 210560. Still see format_on_save_new_file_existing_package failing:

@myitcv
Copy link
Member Author

myitcv commented Dec 11, 2019

Just re-ran against patchset 6 of CL 210560. Still see format_on_save_new_file_existing_package failing:

@heschi
Copy link
Contributor

heschi commented Dec 11, 2019

Thanks for all the testing. I'm not sure we know the precise problem, but we have a pretty good theory.

When you open a new file, we need to reload the packages that it belongs to. To do that, we look at all the packages in the workspace, and heuristically invalidate any that have files in the same directory as the new file. That requires looking through the existing metadata. That happens in the if originalFH == nil block of invalidateContent.

However, the reads for the invalidation happen in a different critical section than v.snapshot.clone below. If the current snapshot finishes loading metadata after the check, we may end up including exactly the metadata we wanted to invalidate. Then very bad things happen later when we do a packages.Load only to throw away the new results in setMetadata.

I thought that the trigger in this test was the initial workspace load, which runs diagnostics concurrently with other operations, so I tried to make that synchronous in the latest patchsets. But either I didn't succeed, I was wrong about the trigger, or the theory is bad.

@myitcv
Copy link
Member Author

myitcv commented Dec 13, 2019

Thanks for the update, @heschik.

Also significant to my mind is that if you look at a failing log of format_on_save_new_file_existing_package against 7093a17 then you will notice three PublishDiagnostics notifications for main.go that are all identical (each has zero diagnostics). Given recent changes in CL 208261 this is also not right.

@myitcv
Copy link
Member Author

myitcv commented Dec 14, 2019

Just re-ran against patchset 1 of CL 211377. Still see format_on_save_new_file_existing_package failing:

@myitcv
Copy link
Member Author

myitcv commented Dec 14, 2019

Sorry, uploaded wrong log files in previous comment for anyone following along (closely). Re-uploaded and updated previous comment.

@myitcv
Copy link
Member Author

myitcv commented Dec 14, 2019

One critical-looking issue appears to be this line:

2019/12/14 06:47:27 diagnoseFile: publishing diagnostics for file:///tmp/go-test-script510947094/script-format_on_save_new_file_existing_package/const.go: map[source.FileIdentity][]source.Diagnostic{source.FileIdentity{URI:"file:///tmp/go-test-script510947094/script-format_on_save_new_file_existing_package/main.go", Version:1, Identifier:"2a9644c7924cdfe6aaae09d857d1e6c0b4a1363d", Kind:0}:[]source.Diagnostic{}}

Note the logs says it's publishing diagnostics for const.go but actually has diagnostics for main.go in hand. Which is why, per #35638 (comment), we then see the diagnostics for main.go published again, despite the fact they haven't changed. But also why we don't see diagnostics for const.go ever being published.

@myitcv
Copy link
Member Author

myitcv commented Dec 14, 2019

Not to steal @heschik's thunder, but we've made a bit of progress.

I've just pushed up to govim/govim#584 (our PR for upgrading x/tools and x/tools/gopls to the latest master). This depends on https://github.com/myitcvforks/tools/tree/heschi_hacks which is https://go-review.googlesource.com/c/tools/+/211377 plus a small fix for the package invalidation logic within snapshot clone.

I've also fixed up other tests that were incorrectly, following CL 208261, waiting on diagnostics to be sent when they haven't changed.

Locally I haven't been able to reproduce a breaking format_on_save_new_file_existing_package with this fix which is good news. Hence we're "getting more green" as far as the build is concerned, something that is confirmed by CI:

https://travis-ci.org/govim/govim/builds/624989118

The one test that is now failing relatively regularly is TestScripts/scenario_default/complete_deep_fuzzy, but I will open a separate issue for that once we land a fix for this issue.

@myitcv
Copy link
Member Author

myitcv commented Dec 14, 2019

Further status update:

However at this stage, with a fix for the first point applied, and given the rarity of the second point, we currently have a green govim build for our upgrade to latest x/tools and x/tools/gopls PR

@gopherbot
Copy link

Change https://golang.org/cl/211537 mentions this issue: internal/lsp/cache: consolidate snapshot cloning

@gopherbot
Copy link

Change https://golang.org/cl/211578 mentions this issue: internal/lsp/cache: don't forget files just because they change

gopherbot pushed a commit to golang/tools that referenced this issue Dec 16, 2019
Cloning is complicated enough without worrying about concurrency, so
hold the snapshot's lock during the entire process.

Consolidate everything into one function. I don't think that the split
was making it easier to understand, and I was able to see and clean up
some extra complexity once it was all in one place. Let's discuss
options if you think the result is too long.

I don't intend any semantic changes in this CL.

Updates golang/go#35638.

Change-Id: I05c4b28875976293f5fcd56248d9c9e468f85cc6
Reviewed-on: https://go-review.googlesource.com/c/tools/+/211537
Run-TryBot: Heschi Kreinick <heschi@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Rebecca Stambler <rstambler@golang.org>
@heschi
Copy link
Contributor

heschi commented Dec 16, 2019

@myitcv, can you confirm that https://golang.org/cl/211578 works?

myitcv pushed a commit to myitcvforks/tools that referenced this issue Dec 16, 2019
Cloning is complicated enough without worrying about concurrency, so
hold the snapshot's lock during the entire process.

Consolidate everything into one function. I don't think that the split
was making it easier to understand, and I was able to see and clean up
some extra complexity once it was all in one place. Let's discuss
options if you think the result is too long.

I don't intend any semantic changes in this CL.

Updates golang/go#35638.

Change-Id: I05c4b28875976293f5fcd56248d9c9e468f85cc6
myitcv pushed a commit to myitcvforks/tools that referenced this issue Dec 16, 2019
The situation in golang/go#35638 was as follows:

didOpen main.go creates a snapshot that knows main.go is in package
"mod.com".
didChange main.go creates a snapshot. When a file changes, we discard
its contents by leaving the file handle out of the "files" map.
didOpen const.go creates a snapshot, and attempts to invalidate the
metadata for packages in the same directory.

The way we detect packages in the same directory is by iterating through
the files in the snapshot. But we threw away the only file in "mod.com"
in step 2 when its contents changed. If a diagnostics run happened to
get in between the two steps, it would re-load main.go and the bug would
go away. If not, step 3 would find no files and fail to invalidate
"mod.com".

The best way to fix this is to insert the new file handle eagerly during
cloning. That way there's no confusion.

Fixes golang/go#35638.

Change-Id: I340bd28a96ad7b4cc912032065f3c2732c380bb2
@myitcv
Copy link
Member Author

myitcv commented Dec 16, 2019

Looks good so far: https://travis-ci.org/govim/govim/builds/625918838?utm_medium=notification&utm_source=github_status. Note the build would almost certainly have failed pre the race tests if the fix was not good.

Just need a fix for #36142 now.

@stamblerre - does adding a configuration option along the lines discussed in #36142 (comment) make sense to you too?

myitcv pushed a commit to myitcvforks/tools that referenced this issue Dec 17, 2019
The situation in golang/go#35638 was as follows:

didOpen main.go creates a snapshot that knows main.go is in package
"mod.com".
didChange main.go creates a snapshot. When a file changes, we discard
its contents by leaving the file handle out of the "files" map.
didOpen const.go creates a snapshot, and attempts to invalidate the
metadata for packages in the same directory.

The way we detect packages in the same directory is by iterating through
the files in the snapshot. But we threw away the only file in "mod.com"
in step 2 when its contents changed. If a diagnostics run happened to
get in between the two steps, it would re-load main.go and the bug would
go away. If not, step 3 would find no files and fail to invalidate
"mod.com".

The best way to fix this is to insert the new file handle eagerly during
cloning. That way there's no confusion.

Fixes golang/go#35638.

Change-Id: I340bd28a96ad7b4cc912032065f3c2732c380bb2
myitcv pushed a commit to myitcvforks/tools that referenced this issue Dec 17, 2019
The situation in golang/go#35638 was as follows:

didOpen main.go creates a snapshot that knows main.go is in package
"mod.com".
didChange main.go creates a snapshot. When a file changes, we discard
its contents by leaving the file handle out of the "files" map.
didOpen const.go creates a snapshot, and attempts to invalidate the
metadata for packages in the same directory.

The way we detect packages in the same directory is by iterating through
the files in the snapshot. But we threw away the only file in "mod.com"
in step 2 when its contents changed. If a diagnostics run happened to
get in between the two steps, it would re-load main.go and the bug would
go away. If not, step 3 would find no files and fail to invalidate
"mod.com".

The best way to fix this is to insert the new file handle eagerly during
cloning. That way there's no confusion.

Fixes golang/go#35638.

Change-Id: I340bd28a96ad7b4cc912032065f3c2732c380bb2
@stamblerre stamblerre modified the milestones: gopls/v1.0.0, gopls/v0.4.0 Jul 22, 2020
@golang golang locked and limited conversation to collaborators Jul 22, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge gopls Issues related to the Go language server, gopls. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Tools This label describes issues relating to any tools in the x/tools repository.
Projects
None yet
Development

No branches or pull requests

4 participants