text:
x/tools/gopls: diagnostics not sent for new buffer

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

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

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

We're still seeing this as of 259af5ff87bd.

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

@heschik: it's exactly the one you mention, but you need to be looking on this branch: https://github.com/govim/govim/pull/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

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.

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"}

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.

Per my Slack message, I'm still seeing the TestScripts/scenario_default/format_on_save_new_file_existing_package test fail even with 22774f7dae43231ae3ff025ca3f8f2c37bdff19b. 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.

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.

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

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.

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

fail.log
pass.log

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.

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:

fail.log
pass.log

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?

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)

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

fail.log
pass.log

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

fail.log
pass.log

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

fail.log
pass.log

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

fail.log
pass.log

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

fail.log
pass.log

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.

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 7093a17b0467 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.

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

fail.log
pass.log

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

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 https://github.com/golang/go/issues/35638#issuecomment-565492175, 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.

Not to steal @heschik's thunder, but we've made a bit of progress.
I've just pushed up to https://github.com/govim/govim/pull/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.

Further status update:

@muirdm has helped identify the problem with TestScripts/scenario_default/complete_deep_fuzzy identified in https://github.com/golang/go/issues/36142 and the fix there is simple
I've raised https://github.com/golang/go/issues/36144 for another issue we see very occasionally which, despite its rarity, does appear to be a genuine bug

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

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

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 https://github.com/golang/go/issues/36142 now.
@stamblerre - does adding a configuration option along the lines discussed in https://github.com/golang/go/issues/36142#issuecomment-565732822 make sense to you too?

authors: heschik myitcv


text:
proposal: time: context-aware time Ticker and Timer

Currently, time.Ticker and time.Timer are not context-aware. A typical context-aware usage of a time.Ticker might look like this:
ticker := time.NewTicker(time.Second)
defer ticker.Stop()

for {
  select {
    case val := <-ticker.C:
      // Do things
    case <-ctx.Done():
      return ctx.Err()
  }
}

But it could look like this:
ticker := time.NewTickerCtx(ctx, time.Second)
for val := range <-ticker.C {
  // Do things
}

The context-aware Timer and Ticker would automatically stop and close the channel when the context is cancelled. The channel must be closed, unlike with Stop(), or else the client would still need to check for the context being cancelled. With cancellation via select, there is no risk of a spurious last tick as there is with Stop(). For consistency, I propose that Stop() should retain its existing behaviour, even for timers/tickers created with NewTimerCtx/NewTickerCtx.

The time package can't depend on the context package, as that would introduce a cyclical import.  But perhaps these could be added to the context package?

The context-aware Timer and Ticker would automatically stop and close the channel when the context is cancelled.

This would mean the Stop and Reset methods of *Timer would no longer be usable.

For both the reasons mentioned, it sounds like this should be a separate API from the ones in package time.
You could imagine
package context
func NewTicker(ctx Context, d time.Duration) <-chan time.Time

But it seems like that could be provided just as easily in a third-party package?

This proposal has been added to the active column of the proposals project
and will now be reviewed at the weekly proposal review meetings.
— rsc for the proposal review group

context.Sleep(ctx context.Context, d time.Duration) also proved quite useful in multiple projects to ensure a minimum quiet time but still allow quick exits of services. I would appreciate to have all three available.
I believe they are a good addition to the context package since it nicely extends the relationship between context and time by periodic things, solves problems that won't exist without context.
Having them in the standard library avoids repeating tricky code in multiple projects as well as allowing optimizations that can react to timers never firing.

The time package can't depend on the context package, as that would introduce a cyclical import. But perhaps these could be added to the context package?

Ah, that's a shame. An alternative would be if time redeclared the interface to break the dependency loop?

This would mean the Stop and Reset methods of *Timer would no longer be usable. Edit: And would make this a single-use timer when constructed with a context.

I don't see any issue with Reset continuing to work as-is. Stop (for both Ticker and Timer) is possibly trickier, but I think the easiest thing to do would be to leave them with their current behaviour, unless we want to make new types for them.

But it seems like that could be provided just as easily in a third-party package?

A third-party package would be an option, but it's actually more work than you might expect to write this in terms of the existing time primitives. And I think that Go APIs should generally be context-aware, so in some respects the lack of context-aware timing utilities is a flaw in the stdlib.

I don't see any issue with Reset continuing to work as-is. Stop (for both Ticker and Timer) is possibly trickier, but I think the easiest thing to do would be to leave them with their current behaviour, unless we want to make new types for them.

Correct me if I'm wrong, but I don't think Timer is allowed to reassign to its channel C.
ctx, cancel := context.WithTimeout(context.Background(), time.Second)
defer cancel()
timer := time.NewTimerCtx(ctx, time.Minute)
ch := timer.C
<-ch // context cancelled after 1s, so channel is closed.
if !timer.Stop() {
	<-ch // we won't hit this, since Stop() returned true
}
timer.Reset(time.Minute) // has to reassign C, so it'll send on a completely different channel
<-ch // returns zero value immediately, not actual timestamp after 1 minute

This snippet may not be idiomatic, since t.C is documented in all the Timer examples. But consider the case of a function that purely consumes channel and not a timer. It would not be able to read new input on the channel.

Reset() should not allow the Timer to be reused, because the context is still expired. Reset() would only work as long as the context has not yet expired.

Reset could be defined to reassign the channel if (and only if) the timer was created using time.NewTimerCtx, but at that point I don't see much advantage in having Reset at all vs. just allocating a new timer. So probably it's better to have NewTimerCtx return a type that doesn't have a Reset method.
(See also #37196.)

Re time and context, Go packages form a strict import hierarchy. Time is an incredibly low-level package. Context is much higher level. So time cannot refer to context, unfortunate though that may seem.
Re the broader discussion, all these detailed arguments strongly suggest that this API should be worked out in a third-party package first before we consider adding new API to context itself.

Based on the discussion above, this proposal seems like a likely decline.
— rsc for the proposal review group

No change in consensus, so declined.
— rsc for the proposal review group

source: gharchive/issue

authors: alercah bcmills ianlancetaylor nightlyone rsc smasher164

repo: golang/go

license_type: permissive

license_source: github-api


text:
x/tools/gopls: massive cpu and memory usage

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

go version go1.15.7 darwin/amd64

Does this issue reproduce with the latest release?
Yes - With go1.16.4 as well
What operating system and processor architecture are you using (go env)?
go env Output
$ go env
GO111MODULE="off"
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/zach.schulze/Library/Caches/go-build"
GOENV="/Users/zach.schulze/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/zach.schulze/go-code/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/zach.schulze/go-code"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/private/var/tmp/_bazel_zach.schulze/507f29846d43dcd14bc7e23ed37206d8/external/go_sdk"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/private/var/tmp/_bazel_zach.schulze/507f29846d43dcd14bc7e23ed37206d8/external/go_sdk/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/jc/10b96gcj0gl80vll0lym3njr0000gn/T/go-build512011677=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?
Start gopls in a mono-repo and begin working
What did you expect to see?
gopls should function properly within a mono-repo. Memory and CPU usage should plateau and no longer climb and slow down the entire machine
What did you see instead?
go and gopls climb in memory and CPU usage till the point I must completely close and restart all go/gopls instances. This is within a single mono repo that is using vs 1.15.7 but is reproducible on the latest gopls and go version.

Duplicate of #45363?

@TheSecEng: Can you please follow the troubleshooting guide here and share your gopls logs? Also, please take a look at the memory section of the troubleshooting guide and include those zips if you have them.

@stamblerre  I did the logfile command, however it just logs the LSP commands. And that contains private code that I can't just post here. What are we looking for exactly?
Also, my TMPDIR has this in it
-rw-r--r--   1 zach.schulze  staff  13297 Jun 29 08:52 gopls.7730-1GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  12910 Jun 29 08:52 gopls.7730-1GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13408 Jun 29 08:52 gopls.7730-2GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  13412 Jun 29 08:52 gopls.7730-2GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13533 Jun 29 08:52 gopls.7730-3GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  13524 Jun 29 08:52 gopls.7730-3GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13415 Jun 29 08:52 gopls.7730-4GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  13371 Jun 29 08:52 gopls.7730-4GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13689 Jun 29 08:52 gopls.7730-5GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  13418 Jun 29 08:52 gopls.7730-5GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13725 Jun 29 08:52 gopls.7730-6GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  13728 Jun 29 08:52 gopls.7730-6GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  14136 Jun 29 09:12 gopls.8191-10GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  14140 Jun 29 09:12 gopls.8191-10GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  14129 Jun 29 09:12 gopls.8191-11GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  14141 Jun 29 09:12 gopls.8191-11GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  14292 Jun 29 09:12 gopls.8191-12GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  14153 Jun 29 09:12 gopls.8191-12GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  16860 Jun 29 09:13 gopls.8191-13GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  16695 Jun 29 09:13 gopls.8191-13GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  17106 Jun 29 09:13 gopls.8191-14GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  17066 Jun 29 09:13 gopls.8191-14GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  17213 Jun 29 09:13 gopls.8191-15GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  17185 Jun 29 09:13 gopls.8191-15GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  17329 Jun 29 09:13 gopls.8191-16GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  17450 Jun 29 09:13 gopls.8191-16GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13026 Jun 29 09:09 gopls.8191-1GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  12629 Jun 29 09:09 gopls.8191-1GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13341 Jun 29 09:10 gopls.8191-2GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  13310 Jun 29 09:10 gopls.8191-2GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13349 Jun 29 09:10 gopls.8191-3GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  13355 Jun 29 09:10 gopls.8191-3GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13748 Jun 29 09:10 gopls.8191-4GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  13791 Jun 29 09:10 gopls.8191-4GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13813 Jun 29 09:10 gopls.8191-5GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  13753 Jun 29 09:10 gopls.8191-5GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  13972 Jun 29 09:10 gopls.8191-6GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  13812 Jun 29 09:10 gopls.8191-6GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  14054 Jun 29 09:12 gopls.8191-7GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  14031 Jun 29 09:12 gopls.8191-7GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  14091 Jun 29 09:12 gopls.8191-8GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  14100 Jun 29 09:12 gopls.8191-8GiB-withnames.zip
-rw-r--r--   1 zach.schulze  staff  14136 Jun 29 09:12 gopls.8191-9GiB-nonames.zip
-rw-r--r--   1 zach.schulze  staff  14096 Jun 29 09:12 gopls.8191-9GiB-withnames.zip

@stamblerre I did the logfile command, however it just logs the LSP commands. And that contains private code that I can't just post here. What are we looking for exactly?

If you can redact out the private pieces of information, it would still be helpful to see. gopls usually logs errors and other useful information. One way to share less information might be to share the output of gopls -v version and the output of gopls -rpc.trace -v check path/to/file.go for a file in your workspace.
The nonames files are redacted, so if you're willing to share one of those zips we can take a look at those too.

@bcmills yes, this seems like a duplicate to me

authors: TheSecEng bcmills bhcleek stamblerre


text:
x/tools/cmd/godoc: Doc links not working

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

$ go version
go version go1.18.1 linux/amd64

Does this issue reproduce with the latest release?
Yes, installed with go install golang.org/x/tools/cmd/godoc@latest
What operating system and processor architecture are you using (go env)?
go env Output
$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/lotus/.cache/go-build"
GOENV="/home/lotus/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/lotus/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/lotus/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/lotus/go/go1.18.1"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/lotus/go/go1.18.1/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.18.1"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build1915755458=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Documented a function using Doc links, as defined on the Go Doc Comments page.// ErrIteratorDone is returned by [Iterator.Next] when the iterator will not yield more items.
//
// The value of ErrIteratorDone is the same as the value of [io.EOF] for compatibility with libraries
// that use [io.EOF] to identify when a sequence of items has been exhausted successfully.
var ErrIteratorDone = io.EOF

Run godoc -links=true

What did you expect to see?
The docs with links to Iterator.Next and to io.EOF
What did you see instead?

Neither link is being interpreted by godoc. The same issue happens with pkgsite, should I open a separate bug for that?

The -links for godoc is not for comment links. It's the linking in variable / function signature.
Enhanced documentation is part of go1.19+, the binaries will need to be built with that.
Even then, godoc won't work as it uses a different url structure.
godoc is frozen / deprecated as of #49212

Please forgive me if chiming in with a godoc pkgsite replacement  script. Based on the idea of Milan Daverde(?) I'm using this script that automatically installs the components if not done so for the user and then runs pkgsite in "local" filesystem mode; this works around the problem that pkgsite isn't designed to hot reload changed files from the local file system:
#!/bin/bash
set -e

if ! command -v pkgsite &>/dev/null; then
    export PATH="$(go env GOPATH)/bin:$PATH"
    if ! command -v pkgsite &>/dev/null; then
        go install golang.org/x/pkgsite/cmd/pkgsite@master
    fi
fi

# In case the user hasn't set an explicit installation location, avoid polluting
# our own project...
NPMBIN=$(cd $HOME && npm bin)
export PATH="$NPMBIN:$PATH"
if ! command -v browser-sync &>/dev/null; then
    (cd $HOME && npm install browser-sync)
fi

if ! command -v nodemon &>/dev/null; then
    (cd $HOME && npm install nodemon)
fi

# https://stackoverflow.com/a/2173421
trap "trap - SIGTERM && kill -- -$$" SIGINT SIGTERM EXIT

# https://mdaverde.com/posts/golang-local-docs
browser-sync start --port 6060 --proxy localhost:6061 --reload-delay 2000 --reload-debounce 5000 --no-ui --no-open &
PKGSITE=$(which pkgsite)
nodemon --signal SIGTERM --watch './**/*' -e go --exec "browser-sync --port 6060 reload && $PKGSITE -http=localhost:6061 ."

Maybe the Go team might want to document how to get pkgsite working in a local godoc-replacement scenario?

As I mentioned on the last line, this is also not behaving correctly with pkgsite.
There it only works with the full path, so [io.EOF] works, but Iterator.Next doesn't. I have to use the add the package name to link to something on the same file.
Should I open that as a separate issue?

sure, include more reproduction instructions though, since it's working locally for me.

Ok
Since godoc is deprecated I'll close this one

If you imported the package you would be able to reference it with the imported package name.
Otherwise just watcher is an unknown/ambiguous reference.

authors: Fryuni seankhliao thediveo


text:
testing: TestMain not working sequentially

Package Structure:
/pkg
       x_test.go
/pkg/sub-package
       y_test.go

x_test.go
import "testing"
import "github.com/ory/dockertest"

func TestMain(m *testing.M) {
    pool, _ := dockertest.NewPool("")
    resource, _ := pool.Run("mysql", "5.7", []string{"MYSQL_ROOT_PASSWORD=secret"}) // Create and run container
    defer pool.Purge(resource) // Kill container

    m.Run()
}

func TestXXX(t *testing.T) {
// Do some tests using mysql container running
}

y_test.go
import "testing"
import "github.com/ory/dockertest"

func TestMain(m *testing.M) {
    pool, _ := dockertest.NewPool("")
    resource, _ := pool.Run("mysql", "5.7", []string{"MYSQL_ROOT_PASSWORD=secret"}) // Create and run container
    defer pool.Purge(resource) // Kill container

    m.Run()
}

func TestYYY(t *testing.T) {
// Do some tests using mysql container running
}

If I run the tests in each directory separately, it works perfectly:

It creates mysql container.
It Runs the tests.
It kills the docker container
Tests end and test results returned

If however I run go test -v ./... from the parent directory:
The tests error out at pool.Run saying that mysql container already exists.
I believe the correct behaviour should be that TestMain should be run independently and sequentially. Only After outer TestMain returns should the inner packages be tested.
That way the containers are already killed before the inner packages are tested, giving the opportunity for the inner package to create their own container (and cleanup themself)

This is working as documented. Per https://pkg.go.dev/cmd/go#hdr-Testing_flags:

The 'go test' command may run tests for different packages
in parallel as well, according to the setting of the -p flag
(see 'go help build').

You can use the -p flag to control the number of processes that go test runs in parallel (see https://pkg.go.dev/cmd/go#hdr-Compile_packages_and_dependencies), so -p 1 would run the tests sequentially.
That said, it is almost always preferable to structure the tests such that each invocation of the test binary works with its own (hermetic) resources.

authors: bcmills pjebs


text:
x/tools/gopls: weird files treated as packages

If one edits a random text file, say /tmp/foof, go/packages/golist.go treats it as a Go file. The comment at line 349 is
"// If we get nothing back from go list,
// try to make this file into its own ad-hoc package.
// TODO(rstambler): Should this check against the original response?"
One would think it should look to see if there is a .go file involved somehow. Otherwise the gopls output is polluted by a lot of messages like
[Error - 10:22:27 AM] 2022/09/01 10:22:27 analyzer "tests" failed: analysis tests for package /tmp/foof panicked: runtime error: invalid memory address or nil pointer dereference

Do you remember anything about how this happened? Typical LSP clients like VS Code and Emacs+eglot won't consider an arbitrary text file as a Go file unless it has a .go suffix, so gopls isn't involved. Did you force the interpretation to Go using the menu at the lower right of VS Code? I tried this, and gopls became usable within the Go file.

authors: adonovan pjweinb