Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

x/tools/gopls: format on save breaks imports when reordered #35388

Closed
zikaeroh opened this issue Nov 6, 2019 · 35 comments
Closed

x/tools/gopls: format on save breaks imports when reordered #35388

zikaeroh opened this issue Nov 6, 2019 · 35 comments
Assignees
Milestone

Comments

@zikaeroh
Copy link
Contributor

@zikaeroh zikaeroh commented Nov 6, 2019

What did you do?

In https://github.com/hortbot/hortbot/blob/master/internal/cli/flags/ircflags/ircargs.go, swap around some import lines and save.

My Go-related configs:

    "go.lintOnSave": "workspace",
    "go.lintTool": "golangci-lint",
    "go.formatTool": "goimports",
    "go.useLanguageServer": true,
    "go.alternateTools": {
        "go-langserver": "gopls"
    },
    "go.buildOnSave": "off",
    "go.vetOnSave": "off",
    "[go]": {
        "editor.snippetSuggestions": "none",
        "editor.formatOnSave": true,
        "editor.codeActionsOnSave": {
            "source.organizeImports": true
        },
        "editor.codeActionsOnSaveTimeout": 3000
    },
    "gopls": {
        "completeUnimported": true,
        "watchFileChanges": true,
        "deepCompletion": true,
        "go-diff": true,
        "local": "github.com/hortbot/hortbot"
    },

Though I'd normally configure local in the project's settings, since it doesn't make much sense globally.

What did you expect to see?

The imports are reordered back to the way they were (or re-sorted by the local feature).

What did you see instead?

The imports get formatted very wrong. Imports get deleted, duplicated, and sometimes turn out syntatically correct with misplaced quotes. I tried to do a screencap.

https://streamable.com/ffxjz

I also verified this without go-diff enabled to see if it was the diff algorithm, but there was no difference.

Also, the local option is applied at an unknown time. I want things to behave exactly as they do with VS Code + goimports, i.e. "hit save, imports are reordered and fixed", but can't seem to get that to work.

Build info

golang.org/x/tools/gopls master
    golang.org/x/tools/gopls@v0.1.8-0.20191105231337-689d0f08e67a h1:4tnHOn2ZDC1EOp6PyPlUfrxeuw1IzXmJ6Hh359rRlSI=
    github.com/BurntSushi/toml@v0.3.1 h1:WXkYYl6Yr3qBf1K79EBnL4mak0OimBfB0XUf9Vl28OQ=
    github.com/sergi/go-diff@v1.0.0 h1:Kpca3qRNrduNnOQeazBd0ysaKrUJiIuISHxogkT9RPQ=
    golang.org/x/sync@v0.0.0-20190423024810-112230192c58 h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU=
    golang.org/x/tools@v0.0.0-20191105231337-689d0f08e67a h1:RzzIfXstYPS78k0QViPGpDcTlV+QuYrbxVmsxDHdxTs=
    golang.org/x/xerrors@v0.0.0-20190717185122-a985d3407aa7 h1:9zdDQZ7Thm29KFXgAX/+yaf3eVbP7djjWp/dXAppNCc=
    honnef.co/go/tools@v0.0.1-2019.2.3 h1:3JgtbtFHMiCmsznwGVTUWbgGov+pVqnlf1dEJTNAXeM=

Go info

go version go1.13.4 linux/amd64

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/jake/.cache/go-build"
GOENV="/home/jake/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/jake/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/jake/zikaeroh/hortbot/hortbot/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-build676081404=/tmp/go-build -gno-record-gcc-switches"
@gopherbot gopherbot added this to the Unreleased milestone Nov 6, 2019
@gopherbot gopherbot added the Tools label Nov 6, 2019
@gopherbot
Copy link

@gopherbot gopherbot commented Nov 6, 2019

Thank you for filing a gopls issue! Please take a look at the Troubleshooting guide, and make sure that you have provided all of the relevant information here.

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Nov 6, 2019

Can you reproduce this by running the gopls imports command? Can you share your gopls logs from when this happens (https://github.com/golang/tools/blob/master/gopls/doc/troubleshooting.md#capturing-logs)?

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 6, 2019

gopls imports makes no change to my file after I reorder my imports (-d flag shows no output).

Logs here: https://gist.github.com/zikaeroh/7eb4a0a7d7d21d929185315bd8cdcb45

Here is a screenshot of the bad quoting (since I couldn't get it in the screen recording):

image

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Nov 6, 2019

Thanks! I'll take a look at the logs. Can you also share the output of running gopls imports with gopls -rpc.trace -v imports?

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Nov 6, 2019

Interestingly enough, the only time textDocument/codeAction returns a value in your log is this:

[Trace - 20:38:56.202 PM] Received response 'textDocument/codeAction - (10)' in 1445ms.
Result: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"changes":{"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags/ircflags/ircargs.go":[{"range":{"start":{"line":10,"character":3},"end":{"line":11,"character":3}},"newText":""},{"range":{"start":{"line":12,"character":53},"end":{"line":12,"character":53}},"newText":"\"\n\t\"github.com/hortbot/hortbot/internal/pkg/ctxlog"}]}}}]

All it's doing here is deleting a line and adding the "github.com/hortbot/hortbot/internal/pkg/ctxlog" important, which doesn't sound like it should cause the results you're seeing. Is it possible that both gopls and some other save hook are applying edits to your file?

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 6, 2019

Output:

2019/11/05 20:51:19 Info:2019/11/05 20:51:19 Build info
----------
golang.org/x/tools/gopls master
    golang.org/x/tools/gopls@v0.1.8-0.20191105231337-689d0f08e67a h1:4tnHOn2ZDC1EOp6PyPlUfrxeuw1IzXmJ6Hh359rRlSI=
    github.com/BurntSushi/toml@v0.3.1 h1:WXkYYl6Yr3qBf1K79EBnL4mak0OimBfB0XUf9Vl28OQ=
    github.com/sergi/go-diff@v1.0.0 h1:Kpca3qRNrduNnOQeazBd0ysaKrUJiIuISHxogkT9RPQ=
    golang.org/x/sync@v0.0.0-20190423024810-112230192c58 h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU=
    golang.org/x/tools@v0.0.0-20191105231337-689d0f08e67a h1:RzzIfXstYPS78k0QViPGpDcTlV+QuYrbxVmsxDHdxTs=
    golang.org/x/xerrors@v0.0.0-20190717185122-a985d3407aa7 h1:9zdDQZ7Thm29KFXgAX/+yaf3eVbP7djjWp/dXAppNCc=
    honnef.co/go/tools@v0.0.1-2019.2.3 h1:3JgtbtFHMiCmsznwGVTUWbgGov+pVqnlf1dEJTNAXeM=

Go info
-------
go version go1.13.4 linux/amd64

GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/jake/.cache/go-build"
GOENV="/home/jake/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/jake/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/lib/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/jake/zikaeroh/hortbot/hortbot/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-build496587565=/tmp/go-build -gno-record-gcc-switches"
2019/11/05 20:51:20 Info:2019/11/05 20:51:20 go/packages.Load
	packages = 1
2019/11/05 20:51:20 Info:2019/11/05 20:51:20 go/packages.Load
	package = github.com/hortbot/hortbot/internal/cli/flags/ircflags
	files = [/home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags/ircflags/ircargs.go]
// Package ircflags processes IRC-related flags.
package ircflags

import (
	"context"
	"database/sql"
	"time"

	"github.com/hortbot/hortbot/internal/birc"
	"github.com/hortbot/hortbot/internal/db/modelsx"
	"github.com/hortbot/hortbot/internal/db/redis"
	"go.uber.org/zap"
	"github.com/hortbot/hortbot/internal/pkg/apis/twitch"
	"github.com/hortbot/hortbot/internal/pkg/ctxlog"
	"github.com/hortbot/hortbot/internal/pkg/twitchx"
)

type IRC struct {
	Nick         string        `long:"irc-nick" env:"HB_IRC_NICK" description:"IRC nick" required:"true"`
	Pass         string        `long:"irc-pass" env:"HB_IRC_PASS" description:"IRC pass" required:"true"`
	PingInterval time.Duration `long:"irc-ping-interval" env:"HB_IRC_PING_INTERVAL" description:"How often to ping the IRC server"`
	PingDeadline time.Duration `long:"irc-ping-deadline" env:"HB_IRC_PING_DEADLINE" description:"How long to wait for a PONG before disconnecting"`
	Token        bool          `long:"irc-token" env:"HB_IRC_TOKEN" description:"Use a token from the database if available"`

	RateLimitSlow   int           `long:"irc-rate-limit-slow" env:"HB_IRC_RATE_LIMIT_RATE" description:"Message allowed per rate limit period (slow)"`
	RateLimitFast   int           `long:"irc-rate-limit-fast" env:"HB_IRC_RATE_LIMIT_RATE" description:"Message allowed per rate limit period (fast)"`
	RateLimitPeriod time.Duration `long:"irc-rate-limit-period" env:"HB_IRC_RATE_LIMIT_PERIOD" description:"Rate limit period"`
}

var DefaultIRC = IRC{
	PingInterval:    5 * time.Minute,
	PingDeadline:    5 * time.Second,
	RateLimitSlow:   15,
	RateLimitFast:   80,
	RateLimitPeriod: 30 * time.Second,
}

func (args *IRC) Pool(ctx context.Context, db *sql.DB, tw twitch.API) *birc.Pool {
	logger := ctxlog.FromContext(ctx)

	channels, err := modelsx.ListActiveChannels(ctx, db, args.Nick)
	if err != nil {
		logger.Fatal("error listing initial channels", zap.Error(err))
	}

	nick := args.Nick
	pass := args.Pass

	if args.Token {
		token, err := twitchx.FindBotToken(ctx, db, tw, nick)
		if err != nil {
			logger.Fatal("error querying for bot token", zap.Error(err))
		}
		if token != nil {
			logger.Debug("using token from database")
			pass = "oauth:" + token.AccessToken
		}
	}

	pc := birc.PoolConfig{
		Config: birc.Config{
			UserConfig: birc.UserConfig{
				Nick: nick,
				Pass: pass,
			},
			InitialChannels: channels,
			Caps:            []string{birc.TwitchCapCommands, birc.TwitchCapTags},
			PingInterval:    args.PingInterval,
			PingDeadline:    args.PingDeadline,
		},
	}

	return birc.NewPool(pc)
}

func (args *IRC) SendMessageAllowed(ctx context.Context, rdb *redis.DB, origin, target string) (bool, error) {
	return rdb.SendMessageAllowed(ctx, origin, target, args.RateLimitSlow, args.RateLimitFast, args.RateLimitPeriod)
}

I am not aware of any other save hook unless the VS Code extension is still trying to run an external tool even though I have not disabled gopls's formatting. For fun, I replaced my goimports binary with a script that just echo'd a string to try and get it to break or replace the buffer, but the behavior I gave in my original post persists.

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Nov 6, 2019

Thanks for trying that out. I guess we can rule that out then. To confirm with the gopls imports command - this is the original file? Can you see what happens when you remove some imports? If you run it a couple times, does it give you consistent results?

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 6, 2019

The above tests were done simply with the reorderings. If I only remove an import, I do see it trying to add it back. With gopls imports -d:

$ gopls imports -d ircargs.go                      
--- /home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags/ircflags/ircargs.go.orig
+++ /home/jake/zikaeroh/hortbot/hortbot/internal/cli/flags/ircflags/ircargs.go
@@ -10,7 +10,8 @@
 	"github.com/hortbot/hortbot/internal/db/modelsx"
 	"github.com/hortbot/hortbot/internal/db/redis"
 	"github.com/hortbot/hortbot/internal/pkg/apis/twitch"
-	"github.com/hortbot/hortbot/internal/pkg/twitchx"
+	"github.com/hortbot/hortbot/internal/pkg/ctxlog"
+	"github.com/hortbot/hortbot/internal/pkg/twitchx"
 	"go.uber.org/zap"
 )
@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Nov 6, 2019

Can you try using the imports from gopls without the local setting? I would be curious to see if you experience the same behavior without it. Also, if you are able to share a log from when the imports behave strangely that would be helpful, even if it's very long - it's just hard to investigate since your previous log didn't seem to have any incorrect behavior in it.

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 6, 2019

Hopefully this is what you're looking for: https://gist.github.com/zikaeroh/3300ac58971886fd3f217f9338da2c56

local is unset. The behavior is still there. I made a number of changes, ordering, removed imports, swapped lines, undid, etc. Experienced bad import replacements, quotes getting misplaced, as well as the imports even appearing outside of the import block.

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 6, 2019

Just to try and eliminate the Go extension as the source of the problem, I configured it to run the formatting tool with a bad flag (-THISISBAD). The bad changes still happen, which tell me at least that the Go extension isn't running an external tool (since it'd otherwise give me an error, or at least do nothing). I have nothing else installed that could do any formatting.

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Nov 6, 2019

Yes, that log was helpful - thank you! One thing I noticed about it is that there were a number of textDocument/codeAction responses that seem to be duplicated. If you look at the responses here, you will see the 3 code action responses that are all the same. I wonder if these diffs are all being applied simultaneously and then colliding. I would expect that this could be fixed via #35243.

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 6, 2019

Is there any plan to not try and use both format and code actions separately in order to manage imports, instead just doing everything as goimports does as a single action?

With how formatting and import management have been combined via goimports/goreturns in editors for a good while, I would really like that behavior to continue, rather than trying to do both individually (and then have to deal with figuring out which edits match which version, and bugs like this).

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Nov 6, 2019

No, the current plan is actually to separate goimports from gofmt as much as possible (see #30843). This way, the source.organizeImports code action will actually do just that, and gofmt will only format a file. Similarly, we would be happy to add the functionality of goreturns, but only as a quickfix, not a format action.

In general, it is much more correct for us to match edits to a specific version of a file - that's really the issue here. If your editor is slow or something gets out of sync with the client and the server - you will immediately get strange behavior if edits are not associated with a specific version of the file.

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 6, 2019

Absolutely, the versions matter and that should be fixed. My only thought was that it seemed like splitting things is complicating a scenario that a lot of people have been using for a while, even if doing a bunch of stuff on format is different than most every other LSP enabled language (mainly because doing something like "find me the right new imports to make this file sane" is such a cheap operation in Go, like so many other things).

@ianthehat
Copy link

@ianthehat ianthehat commented Nov 7, 2019

Historically they were combined only because a save hook was the only way to trigger them, and the fact that they are combined is the source of considerable problems.
For instance, goreturns needed to include the functionality of goimports which needed to include the functionality of gofmt, just because people wanted all three, but then people also wanted gofmt -s which was not part of goimports so they end up running multiple save hooks anyway, all of which are redoing the same behaviors for the parts that the authors decided all their users needed, and now there is gofumpt...

By carefully teasing the functionality apart we can allow users to pick and choose, and authors of a new piece of functionality will no longer need to include a random collection of other save hooks they think are important.

Also much of this functionality does not (and should not) need you to save the file to trigger.

@stamblerre stamblerre self-assigned this Nov 7, 2019
@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 7, 2019

That's fair and reasonable, and I understand and agree with it from that point of view. I was going to stick this on #30843, but I can put my thoughts here too.

I'm just thinking towards the day where gopls is "released" and something like VS Code switches from it being an experiment to the main experience. The default behavior for VS Code users at the moment is "run goreturns, or goimports if in module mode". Formatting on save does everything those tools did. If you enable gopls, the format on save behavior now does a different thing, and you find out from the gopls docs that you have to enable language-scoped settings like codeActionsOnSave to get the old behavior back. That might be jarring. New users who start with gopls may not even know that this feature exists (as in the past where people "discovered" goimports until it was just the default in many editors).

At the end of the day, if I can hit save and things are formatted and reorganized as they would be if I ran goimports (with the bugs fixed 😉), then I'll be happy. More fixes and options showing up I can work with would be nice, too. I just don't want to end up regressing something I've been happy with for many years. 😄

@ianthehat
Copy link

@ianthehat ianthehat commented Nov 7, 2019

Yes, the intention is that the default configuration will be what we believe to be the best normal user experience, which will include those kinds of things. The configuration options will still be there for power users, but the defaults will be sane.

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 7, 2019

At the risk of extending this longer (when my bug isn't related, per se), how do you plan on setting the sane defaults when it's the client's job to apply things like fixes?

(At least, it's my impression that options like editor.codeActionsOnSave are things you ask the editor to do, and thus not something the server controls.)

@ianthehat
Copy link

@ianthehat ianthehat commented Nov 7, 2019

Each client needs to decide what the sensible defaults are, we have opinions, and to some extent we hope that clients will respect them so that the unconfigured experience will be reasonably common across all clients, but some things will be different because the model the clients work in is different, and that is okay.
We will probably have the most influence over the VSCode behavior because we directly contribute to that plugin, and that will probably be our exemplar for what we think the user experience should be.

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 13, 2019

Since #35243 was fixed, I went and retried formatting/import sorting again as above, but the same behavior persists.

https://gist.github.com/zikaeroh/618e23c7292123e62a65dbcb71d2c107

I can see in the log that the code actions now include version numbers, but maybe there's something else that's needed (or #35243 alone wasn't the entire story).

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Nov 14, 2019

Taking a look at the logs, it seems like the version numbers are wrong (also, #35584). I'll investigate that further.

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Nov 14, 2019

This is a bit of a brain dump from my analysis of the logs here. If you're able to attach a screencast of what you're seeing while a log is being written that would be super helpful for analysis as well.


All of the codeActions that suggest modifications to the file:

[Trace - 15:31:17.423 PM] Received response 'textDocument/codeAction - (6)' in 430ms.
Result: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"documentChanges":[{"textDocument":{"version":2,"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"edits":[{"range":{"start":{"line":16,"character":5},"end":{"line":17,"character":5}},"newText":""},{"range":{"start":{"line":17,"character":24},"end":{"line":17,"character":24}},"newText":"\"\n\t\"go.uber.org/zap"}]}]}}]

[Trace - 15:31:17.426 PM] Received response 'textDocument/codeAction - (7)' in 211ms.
Result: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"documentChanges":[{"textDocument":{"version":2,"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"edits":[{"range":{"start":{"line":16,"character":5},"end":{"line":17,"character":5}},"newText":""},{"range":{"start":{"line":17,"character":24},"end":{"line":17,"character":24}},"newText":"\"\n\t\"go.uber.org/zap"}]}]}}]

[Trace - 15:31:21.965 PM] Received response 'textDocument/codeAction - (10)' in 3570ms.
Result: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"documentChanges":[{"textDocument":{"version":10,"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"edits":[{"range":{"start":{"line":9,"character":3},"end":{"line":10,"character":3}},"newText":""},{"range":{"start":{"line":15,"character":48},"end":{"line":15,"character":48}},"newText":"\"\n\t\"github.com/hortbot/hortbot/internal/pkg/errgroupx"}]}]}}]

[Trace - 15:31:28.846 PM] Received response 'textDocument/codeAction - (16)' in 581ms.
Result: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"documentChanges":[{"textDocument":{"version":12,"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"edits":[{"range":{"start":{"line":10,"character":3},"end":{"line":11,"character":3}},"newText":""},{"range":{"start":{"line":17,"character":24},"end":{"line":17,"character":24}},"newText":"\"\n\t\"go.uber.org/zap"}]}]}}]

If we believe that VS Code is actually respecting the versions specified in the responses, we would see these as textDocument/didChange events for versions 3, 11, and 13.

The only time I see this happen is for the textDocument/didChange for version 11:

[Trace - 15:31:21.965 PM] Received response 'textDocument/codeAction - (10)' in 3570ms.
Result: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"documentChanges":[{"textDocument":{"version":10,"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"edits":[{"range":{"start":{"line":9,"character":3},"end":{"line":10,"character":3}},"newText":""},{"range":{"start":{"line":15,"character":48},"end":{"line":15,"character":48}},"newText":"\"\n\t\"github.com/hortbot/hortbot/internal/pkg/errgroupx"}]}]}}]

...

[Trace - 15:31:26.657 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go","version":11},"contentChanges":[{"range":{"start":{"line":16,"character":24},"end":{"line":17,"character":17}},"rangeLength":19,"text":""},{"range":{"start":{"line":16,"character":5},"end":{"line":16,"character":5}},"rangeLength":0,"text":"hub.com/hortbot/hortbot/internal/pkg/errgroupx\"\n\t\"go."}]}

The behavior here looks reasonable to me, though I might be mistaken.


On line 836, there is this textDocument/didChange event. It looks like an import being added, but there is no textDocument/codeAction response with this import being added.

[Trace - 15:31:27.556 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go","version":19},"contentChanges":[{"range":{"start":{"line":16,"character":18},"end":{"line":17,"character":25}},"rangeLength":26,"text":""},{"range":{"start":{"line":16,"character":0},"end":{"line":16,"character":0}},"rangeLength":0,"text":"\t\"go.opencensus.io/trace\"\n"}]}

Later on, we see the last codeAction that returns a response:

[Trace - 15:31:28.265 PM] Sending request 'textDocument/codeAction - (16)'.
Params: {"textDocument":{"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"range":{"start":{"line":0,"character":0},"end":{"line":89,"character":0}},"context":{"diagnostics":[]}}

[Trace - 15:31:28.846 PM] Received response 'textDocument/codeAction - (16)' in 581ms.
Result: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"documentChanges":[{"textDocument":{"version":12,"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"edits":[{"range":{"start":{"line":10,"character":3},"end":{"line":11,"character":3}},"newText":""},{"range":{"start":{"line":17,"character":24},"end":{"line":17,"character":24}},"newText":"\"\n\t\"go.uber.org/zap"}]}]}}]

[Trace - 15:31:28.854 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go","version":20},"contentChanges":[{"range":{"start":{"line":17,"character":18},"end":{"line":17,"character":18}},"rangeLength":0,"text":"\"\n\t\"go.uber.org/zap"},{"range":{"start":{"line":10,"character":3},"end":{"line":11,"character":3}},"rangeLength":58,"text":""}]}

It looks like this codeAction gets applied, even though the versions of the files are mismatched.


The final textDocument/didChange event looks like:

[Trace - 15:31:31.219 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go","version":21},"contentChanges":[{"range":{"start":{"line":16,"character":18},"end":{"line":17,"character":17}},"rangeLength":19,"text":""},{"range":{"start":{"line":10,"character":3},"end":{"line":10,"character":3}},"rangeLength":0,"text":"ithub.com/hortbot/hortbot/internal/cli/flags/nsqflags\"\n\t\"g"}]}

This also looks like an import modification, but without any corresponding codeAction.


Sorry that this long comment isn't particularly helpful - just wanted to write out the things I noticed before I forgot. Maybe I will make a CL with some additional log statements that you can use to get some more information. In the meantime I will focus on resolving #35584 so that we can be certain the versions are not incorrect.

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 15, 2019

Here is a fresh log and screencast:

All actions I performed were either line swaps, undos, or file saves. I captured my VS Code tabs so you can see when I saved. I'd do a recording with key presses, but I'm a bit limited to what I can do from wayland/sway.

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Nov 24, 2019

I recently ran into this myself on my Mac. Looking at the logs, it seems like VS Code is still applying code actions even if the versions of the files no longer match up. There is still a larger issue of gopls sending codeActions for older versions of the file.

@heschik
Copy link
Contributor

@heschik heschik commented Nov 26, 2019

I looked at the logs from https://golang.org/issue/35388#issuecomment-554172456. I'm going to focus on the moment between :19 and :20 where "go.ang.org/x/sync/sema" appears in the file.

That string appears in the log at 17:45:45.250, so we know that whatever happened probably happened in the few seconds before that. The most likely-looking code actions are:

[Trace - 17:45:43.943 PM] Sending request 'textDocument/codeAction - (38)'.
Params: {"textDocument":{"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"range":{"start":{"line":18,"character":18},"end":{"line":18,"character":18}},"context":{"diagnostics":[]}}
--
[Trace - 17:45:44.051 PM] Sending request 'textDocument/codeAction - (40)'.
Params: {"textDocument":{"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"range":{"start":{"line":0,"character":0},"end":{"line":89,"character":0}},"context":{"diagnostics":[]}}
--
[Trace - 17:45:44.487 PM] Received response 'textDocument/codeAction - (38)' in 544ms.
Result: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"documentChanges":[{"textDocument":{"version":14,"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"edits":[{"range":{"start":{"line":16,"character":5},"end":{"line":17,"character":5}},"newText":""},{"range":{"start":{"line":17,"character":24},"end":{"line":17,"character":24}},"newText":"\"\n\t\"go.uber.org/zap"}]}]}}]
--
[Trace - 17:45:44.490 PM] Received response 'textDocument/codeAction - (40)' in 439ms.
Result: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"documentChanges":[{"textDocument":{"version":14,"uri":"file:///home/jake/zikaeroh/hortbot/hortbot/internal/cli/subcommands/bot/bot.go"},"edits":[{"range":{"start":{"line":16,"character":5},"end":{"line":17,"character":5}},"newText":""},{"range":{"start":{"line":17,"character":24},"end":{"line":17,"character":24}},"newText":"\"\n\t\"go.uber.org/zap"}]}]}}]

Note that VS Code sent us two codeAction requests, one for a single character (38) and one for the whole file (40). We respond to both requests with fixes for the whole file. I think it's vaguely plausible that applying those edits twice would produce the file we see at :21.

I'm not sure what the bug is here. Maybe we should only return actions in the requested range? Or we shouldn't be sending code actions more than once for the same version? Or the client shouldn't be requesting them?

For the record, I also see the same pattern for the following pairs of requests: 10 and 12, 22 and 23, 64 and 63 (out of order responses), 71 and 73, 85 and 86. I haven't worked through any of the others but I think it's pretty plausible that this is the only thing going on.

@myitcv
Copy link
Member

@myitcv myitcv commented Nov 26, 2019

I'm not sure what the bug is here. Maybe we should only return actions in the requested range? Or we shouldn't be sending code actions more than once for the same version? Or the client shouldn't be requesting them?

Some observations from our experience with govim:

  • it's not a error to request code actions for the same version of a file. The user may choose to simply do nothing with the results for example
  • @leitzler will be able to confirm, but it's also possible to request code actions for a specific range or the entire file, and we do that in govim
  • the actions that are returned are almost certainly not composable. Unlike Formatting which returns []TextEdit, the results from different CodeAction requests are not, to my understanding, in any way related. Hence applying one CodeAction would, following the subsequent DidChange notification, require us to re-request CodeAction's.

Based on our experience in #35114, gopls is sending CodeAction and Formatting responses for previous versions of a file; we enforce this in govim and hence have started seeing #35114 (comment). Our findings are detailed more thoroughly in #35114 (comment).

We've also seen situations where diagnostics (as a result of analyses) are referring to the incorrect version: #35584.

To my mind the first thing to ensure here is that gopls is using the correct snapshot of file contents for all methods, and that methods only refer to file existence, contents etc from the snapshot. Because otherwise it's impossible to build assumptions on what VSCode/other editors may or may not be doing.

@leitzler
Copy link
Contributor

@leitzler leitzler commented Nov 26, 2019

@leitzler will be able to confirm, but it's also possible to request code actions for a specific range or the entire file, and we do that in govim

Yes, it wasn’t set how gopls should behave when I added this to govim (as in: it didn’t matter what it range it got). Currently govim sends the current cursor position as range, as well as all diagnostics that covers that position.

I haven’t used VSCode, could it be that it sends the entire file to be able to show the user an icon next to the lines that have suggested fixes?

@gopherbot
Copy link

@gopherbot gopherbot commented Nov 26, 2019

Change https://golang.org/cl/209057 mentions this issue: internal/lsp: don't re-run packages.Load if import order has changed

@heschik
Copy link
Contributor

@heschik heschik commented Nov 26, 2019

@myitcv True, the code actions in question are against stale versions of the file. But even if they were applied to the wrong version, no single insertion can produce the behavior in the video, because they all start with whitespace. I think they have to be getting composed incorrectly somehow, but looking again I don't see how.

@heschik
Copy link
Contributor

@heschik heschik commented Nov 27, 2019

@zikaeroh: hey, this is a bit of a guess, but can you try setting

    "[go]": {
        "editor.formatOnSave": false,
    }

in your settings? I have evidence that formatting and organize imports fight each other, at least in VS Code.

Edit: wait, never mind, all your formatting responses are empty...

@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Nov 27, 2019

For what it's worth, I went and tried to set this to get you an answer, and for some reason I can't reproduce this behavior anymore.

New logs and screencast:

The way sorting + formatting works is a bit subpar (edits applied pretty far apart in time, sometimes never without another save), but I don't see the sort of corruption I had seen previously.

I have no idea what could have changed. I read every commit to x/tools and can't recall seeing anything that would have changed this... vscode-go hasn't updated, so the LS client would be the same, and the most recent VS Code minor release changelog shows nothing interesting. I even deleted goimports and replaced it to a script which just echos "OOPS" to ensure my editor isn't falling back to it. No clue. Maybe the LSP logs will provide better info.

Version:

golang.org/x/tools/gopls master
    golang.org/x/tools/gopls@v0.1.8-0.20191127201027-ecd32218bd7f h1:bOnT1l4AnBGc7VW7rP2vS3EeKl9XNi/OCpXk65jpxdI=

I'll keep testing to see.

@stamblerre stamblerre modified the milestones: Unreleased, gopls v1.0 Dec 4, 2019
@heschik
Copy link
Contributor

@heschik heschik commented Dec 5, 2019

FWIW, I've spent a bunch of time trying to reproduce this, and while I did find a number of glitches, none of them were this one.

gopherbot pushed a commit to golang/tools that referenced this issue Dec 5, 2019
Previously, we would reload if a user's import list decreased or simply
changed order. This is not necessary. Now, we only re-run if a new import
needs to be loaded.

Updates golang/go#35388

Change-Id: I47874afe773dddb835ac27b18895e7a082950dc7
Reviewed-on: https://go-review.googlesource.com/c/tools/+/209057
Reviewed-by: Heschi Kreinick <heschi@google.com>
@zikaeroh
Copy link
Contributor Author

@zikaeroh zikaeroh commented Dec 7, 2019

I spent a little time doing a bisect (backwards, trying to find the CL that fixed it), and it appears that CL 208265 was the one that fixed the issue for me. Makes sense, as the CL was fixing diagnostics on snapshot clones and mentions the impact on code actions.

I'm not a big fan of the relative speed of save/format/organize compared to plain goimports, but I'm pretty sure this specific issue is fixed and I can close it.

Thanks for looking into this. One fewer race to figure out. 😄

@stamblerre
Copy link
Contributor

@stamblerre stamblerre commented Dec 7, 2019

Thanks for following up! I'm surprised to hear that gopls is slower than goimports, particularly because gopls has extra caching that goimports does not. I filed #36034 to follow up. Would you mind attaching some logs to that issue so we can investigate?

@stamblerre stamblerre modified the milestones: gopls/v1.0.0, gopls/v0.4.0 Jul 22, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
7 participants
You can’t perform that action at this time.