cmd/govim: goimports fails in github.com/eliasnaur/gophercon-uk-2019-talk

[eliasnaur]

What version of Vim/Gvim are you using?

Vim/Gvim version

$ vim --version
VIM - Vi IMproved 8.1 (2018 May 18, compiled Aug 22 2019 04:01:19)
macOS version
Included patches: 1-1900
Compiled by Homebrew
Huge version without GUI.  Features included (+) or not (-):
+acl               -farsi             -mouse_sysmouse    -tag_any_white
+arabic            +file_in_path      +mouse_urxvt       -tcl
+autocmd           +find_in_path      +mouse_xterm       +termguicolors
+autochdir         +float             +multi_byte        +terminal
-autoservername    +folding           +multi_lang        +terminfo
-balloon_eval      -footer            -mzscheme          +termresponse
+balloon_eval_term +fork()            +netbeans_intg     +textobjects
-browse            +gettext           +num64             +textprop
++builtin_terms    -hangul_input      +packages          +timers
+byte_offset       +iconv             +path_extra        +title
+channel           +insert_expand     +perl              -toolbar
+cindent           +job               +persistent_undo   +user_commands
-clientserver      +jumplist          +postscript        +vartabs
+clipboard         +keymap            +printer           +vertsplit
+cmdline_compl     +lambda            +profile           +virtualedit
+cmdline_hist      +langmap           -python            +visual
+cmdline_info      +libcall           +python3           +visualextra
+comments          +linebreak         +quickfix          +viminfo
+conceal           +lispindent        +reltime           +vreplace
+cryptv            +listcmds          +rightleft         +wildignore
+cscope            +localmap          +ruby              +wildmenu
+cursorbind        +lua               +scrollbind        +windows
+cursorshape       +menu              +signs             +writebackup
+dialog_con        +mksession         +smartindent       -X11
+diff              +modify_fname      -sound             -xfontset
+digraphs          +mouse             +spell             -xim
-dnd               -mouseshape        +startuptime       -xpm
-ebcdic            +mouse_dec         +statusline        -xsmp
+emacs_tags        -mouse_gpm         -sun_workshop      -xterm_clipboard
+eval              -mouse_jsbterm     +syntax            -xterm_save
+ex_extra          +mouse_netterm     +tag_binary
+extra_search      +mouse_sgr         -tag_old_static
   system vimrc file: "$VIM/vimrc"
     user vimrc file: "$HOME/.vimrc"
 2nd user vimrc file: "~/.vim/vimrc"
      user exrc file: "$HOME/.exrc"
       defaults file: "$VIMRUNTIME/defaults.vim"
  fall-back for $VIM: "/usr/local/share/vim"
Compilation: clang -c -I. -Iproto -DHAVE_CONFIG_H   -DMACOS_X -DMACOS_X_DARWIN  -g -O2 -U_FORTIFY_SOURCE -D_FORTIFY_SOURCE=1
Linking: clang   -L. -fstack-protector-strong -L/usr/local/lib -L/usr/local/opt/libyaml/lib -L/usr/local/opt/openssl/lib -L/usr/local/opt/readline/lib  -L/usr/local/lib -o vim        -lncurses -liconv -lintl -framework AppKit  -L/usr/local/opt/lua/lib -llua5.3 -mmacosx-version-min=10.14 -fstack-protector-strong -L/usr/local/lib  -L/usr/local/Cellar/perl/5.30.0/lib/perl5/5.30.0/darwin-thread-multi-2level/CORE -lperl -lm -lutil -lc  -L/usr/local/opt/python/Frameworks/Python.framework/Versions/3.7/lib/python3.7/config-3.7m-darwin -lpython3.7m -framework CoreFoundation  -lruby.2.6

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

$ go version
go version devel +0212f0410f Thu Aug 15 17:49:11 2019 +0000 darwin/amd64

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

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/var/folders/_7/lnt35k555hl2bs7fjygkhgx00000gp/T/tmp.6dcyONcR/Library/Caches/go-build"
GOENV="/var/folders/_7/lnt35k555hl2bs7fjygkhgx00000gp/T/tmp.6dcyONcR/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/var/folders/_7/lnt35k555hl2bs7fjygkhgx00000gp/T/tmp.6dcyONcR/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/elias/go-tip"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/elias/go-tip/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/var/folders/_7/lnt35k555hl2bs7fjygkhgx00000gp/T/tmp.6dcyONcR/gophercon-uk-2019-talk/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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/_7/lnt35k555hl2bs7fjygkhgx00000gp/T/go-build043891830=/tmp/go-build -gno-record-gcc-switches -fno-common"

What version/commit of govim are you using?

Git commit b6bbbae.

What is the output of :messages in Vim?

Messages maintainer: Bram Moolenaar <Bram@vim.org>

Do the Vim channel, govim or gopls log files show anything interesting?

@myitcv kindly debugged the issue with me and found nothing interesting in the logs.

What did you do?

$ cd $(mktemp -d)
$ export HOME=$PWD
$ git clone https://github.com/myitcv/govim.git ~/.vim/pack/plugins/start/govim
Cloning into '/var/folders/_7/lnt35k555hl2bs7fjygkhgx00000gp/T/tmp.6dcyONcR/.vim/pack/plugins/start/govim'...

...

$ git clone https://github.com/eliasnaur/gophercon-uk-2019-talk.git

...

$ cd gophercon-uk-2019-talk
$ cd demo/
$
$ vi main.go
Installing govim and gopls

I then deleted the import "gioui.org/ui/layout" line and issued :w to save the file.

What did you expect to see?

The import line re-added by govim.

What did you see instead?

No change.

[myitcv]

Thanks for the report.

Bizarrely, I cannot reproduce this any more.

I used the following as a starting point:

export GOVIM_LOGFILE_TMPL=%v
cd $(mktemp -d)
export HOME=$PWD
git clone https://github.com/myitcv/govim.git ~/.vim/pack/plugins/start/govim
cd ~/.vim/pack/plugins/start/govim
git checkout b6bbbaec1c8457db55c5f7e26d3030fe5c118d13
cd $HOME
curl -LSso ~/.vimrc https://raw.githubusercontent.com/myitcv/govim/b6bbbaec1c8457db55c5f7e26d3030fe5c118d13/cmd/govim/config/minimal.vimrc
export GOPATH=$(mktemp -d)
git clone --single-branch --branch live https://github.com/myitcvforks/gophercon-uk-2019-talk
cd gophercon-uk-2019-talk/demo
vi main.go

then waited for "things to settle", which is more precisely defined as waiting for the following to appear in the govim log:

PublishDiagnostics callback: &protocol.PublishDiagnosticsParams{
    URI:         "file:///tmp/tmp.HR7HCq9goZ/gophercon-uk-2019-talk/demo/main.go",
    Version:     0,
    Diagnostics: {
    },
}

Then delete line 6 (via dd), then :w. Leaves me with:

package main

import (
	"gophercon/simple"
	"log"

	"gioui.org/ui"
	"gioui.org/ui/app"
	"gioui.org/ui/layout"
)

func main() {
	go func() {
		theme := simple.NewTheme()
		w := app.NewWindow()
		ops := new(ui.Ops)
		btn := new(simple.IconButton)
		q := w.Queue()
		for e := range w.Events() {
			switch e := e.(type) {
			case app.UpdateEvent:
				cfg := &e.Config
				ops.Reset()
				theme.Reset(cfg)
				cs := layout.RigidConstraints(e.Size)
				for e, ok := btn.Next(q); ok; e, ok = btn.Next(q) {
					log.Println(e)
				}
				btn.Layout(cfg, ops, cs)
				w.Update(ops)
			}
		}
	}()
	app.Main()
}

Are you able to repro with the above?

[eliasnaur]

I can't reproduce the bug with your steps. I re-reproduced the bug on my local checkout of gophercon-uk-2019 a few times, but suddenly I couldn't. Event the steps from my original report doesn't reproduce the bug anymore :(

I suppose we can close this as not reproducible. I'll re-open it if I manage to reproduce the error again. Perhaps my home machine still has the problem.

[myitcv]

I'll re-open it if I manage to reproduce the error again. Perhaps my home machine still has the problem.

Please do.

[eliasnaur]

Aaaand it's back! I'm not sure what makes it intermittent, but now I can reproduce the bug with my own steps and for a small demo with just a single directory with a go.mod and a single main.go. But I can't reproduce the bug with @myitcv's steps above.

[leitzler]

Got somehow nerd-sniped into this as well on my way home from work.
I managed to reproduce it using Paul's steps (except for the wait for "things to settle") on the subway a few times, but as soon as I got home the error disappeared.

Haven't had time to dive deeper, but I realised that the connection was pretty bad on my way home, and during this "things to settle" wait, there were a few network requests to gioui.org.

Could it be related to gopls being interrupted by a save during some init phase that takes longer time on slow connections? And then doesn't recover fully.

I had to try running it at home again but manually blocking the network requests for a few seconds, then I'm able to reproduce it again.

[myitcv]

I managed to reproduce it using Paul's steps (except for the wait for "things to settle") on the subway a few times, but as soon as I got home the error disappeared.

One thing to potentially note here. With current master (b6bbbae) we do not have a number of fixes to race conditions, threading model etc in gopls. With https://github.com/myitcv/govim/tree/tools_gopls_95c3470cfb70 (branch for #467) we do. So it would be interesting if you can repro using the latter, modulo golang/go#33647 (which is the blocking reason why #467 is not merged)

except for the wait for "things to settle"

This could be a very significant part of the problem. Again, with https://github.com/myitcv/govim/tree/tools_gopls_95c3470cfb70 the problem may just have "gone away". Otherwise, it's possible (likely?) that the initial run of gopls "does something different/significant", which if interrupted or some such, causes things to get into a bad state, much like you both have suggested.

The one other thing to note from previous tests is that the git server behind gioui.org is much slower than github.com. So if you are using Go 1.12.x (i.e. not hitting https://proxy.golang.org by default) then you might be hitting a slow path. I recall from our debugging session that @eliasnaur is using tip, so perhaps not an issue there, assuming valid package/module import paths are being used (because if not they proxy will fall through to the git server in any case)

[eliasnaur]

For some reason, setting GOPATH=$HOME makes goimports work. Unsetting GOPATH again makes the problem re-appear. That applies to @myitcv's example as well.

[myitcv]

That's interesting. I'm still stuck as to how you reproduce this with my steps given I can't reproduce it. But it sounds like @leitzler has made progress on reproducing?

[leitzler]

Unfortunately I'm back to not being able to reproduce it (in a consistent way). Played around with different network issues but after letting network requests through it does actually recover. Next save formats everything..

@eliasnaur just out of curiosity, could you add a pair of logs where you do the same steps where one works and the other doesn't?

[eliasnaur]

I think I can do better. Here is a Dockerfile with everything set up:

https://gist.github.com/eliasnaur/a61fb0ad106b3a762c2e81ec8d82a464

I can then reproduce the problem with:

$ docker build . # From the directory with the Dockerfile
$ docker run --rm -it <image name> /bin/bash

and then following the instructions from my report. I did
wait for things to settle, and ran a go test . from the demo
directory to make sure everything was warmed up.

Then, running export GOPATH=$HOME makes the automatic
goimport work for me! Unsetting with export -n GOPATH again
broke the import. Remember to git checkout . between attempts.

[leitzler]

Ha! Nice repo indeed 👍. I just gave it a quick try but it didn't work at all, as in doesn't seem to try to load govim.

edit: Ops, ran vi instead of vim, have it aliased on my machine.

[leitzler]

Able to repro at least. But did you not have GOPATH set explicitly when running into the issue the first time?

I've seen some places where scripts/code assume that GOPATH is set (probably written pre Go 1.8 where the default value was introduced). Could this be the case here as well?

I'm not super familiar with gopls internals, but maybe here for example? https://github.com/golang/tools/blob/922a4ee32d1add0a49cd363b04bb56407baa2ec6/internal/lsp/cache/view.go#L193

[eliasnaur]

I've run with GOPATH cleared ever since I set GO111MODULE=on on my machines.

[myitcv]

@leitzler created a fix for this in https://go-review.googlesource.com/c/tools/+/191600/

We're just blocked on golang/go#33647, then we can update

[eliasnaur]

Because https://go-review.googlesource.com/c/tools/+/192719 is listed in 6961210, I assume this is fixed with v0.0.23. Thank you for working on this!