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: stop logging context cancellation errors #34103

Closed
myitcv opened this issue Sep 5, 2019 · 23 comments
Closed

x/tools/gopls: stop logging context cancellation errors #34103

myitcv opened this issue Sep 5, 2019 · 23 comments

Comments

@myitcv
Copy link
Member

@myitcv myitcv commented Sep 5, 2019

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

$ go version
go version devel +9da7abd2eb Tue Sep 3 18:35:32 2019 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20190905035308-adb45749da8e
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.1.4-0.20190905035308-adb45749da8e

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"
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-build307597040=/tmp/go-build -gno-record-gcc-switches"

What did you do?

The symptoms look similar to #33647. However, whereas before I could reproduce this reliably, now it happens much more sporadically.

In govim we handle changes to (generated) files not loaded in the editing change via a file watcher (whilst we await #31553)

The test failures we are seeing manifest with the following errors on gopls's stderr:

2019/09/05 08:41:07 failed to check package: context canceled
2019/09/05 08:41:07 failed to compute diagnostics: no CheckPackageHandles for file:///tmp/go-test-script292517338/script-complete_watched/main.go

These errors then get reported via the LogMessage callback.

https://go-review.googlesource.com/c/tools/+/192719 improved this situation, however following that CL we still see this ~10% of the time.

Unfortunately we haven't yet been able to capture a gopls log for this, hence here is the log of calls from govim's perspective:

https://gist.github.com/myitcv/6a5550365272416fb4d8673ff7fa8460

What did you expect to see?

No errors.

What did you see instead?

The above errors.


cc @stamblerre @ianthehat @muirrn

FYI @leitzler

@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Sep 5, 2019

We're also seeing these errors as part of our hover tests.

So whilst they might be legitimate errors, is it also possible that we're spuriously logging non-error events as errors?

@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Sep 5, 2019

Hmm, now we're seeing it as part of our "go to def" tests. The call to Definition failed with:

no CheckPackageHandles for file://$WORK/q/q.go

It's unclear whether the other "errors" were in fact errors, or whether the user would have noticed.

But in this case the user would definitely have noticed: the call to Definition returned an error when it should not have done.

@muirdm

This comment has been minimized.

Copy link

@muirdm muirdm commented Sep 5, 2019

I occasionally see this myself, but never reproducibly. I haven't been able to dig into it, but I have a couple ideas of what might cause this.

It's unclear whether the other "errors" were in fact errors, or whether the user would have noticed.

In general context.Canceled shouldn't be logged as an error since it is expected, but given our track record for handling cancelation properly, we should probably leave the logs in for now.

@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented Sep 5, 2019

Change https://golang.org/cl/193480 mentions this issue: internal/lsp: avoid using the importer's context as much as possible

gopherbot pushed a commit to golang/tools that referenced this issue Sep 5, 2019
There are issues with contexts being propagated through the calls to
type-checking, and I think that a lot of these were related to us using
the importer's context. Instead, we should propagate the context from
the store as much as possible - only using the importer's context when
absolutely necessary (in the call to Import). This change propagates the
correct context where possible.

Updates golang/go#34103

Change-Id: I4bdc37d014ee1f775b720c9e7ad8abffffcf6ba3
Reviewed-on: https://go-review.googlesource.com/c/tools/+/193480
Run-TryBot: Rebecca Stambler <rstambler@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Ian Cottrell <iancottrell@google.com>
@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Sep 5, 2019

I occasionally see this myself, but never reproducibly

I can fairly reliably cause it to happen by repeatedly running the govim tests, but never on demand for a given run/test. So if there's some additional logging/whatever that will help to track this down we could create a CL and see how far we get.

we should probably leave the logs in for now.

Understood.

At the moment we're holding off upgrading gopls/x/tools because of this. https://go-review.googlesource.com/c/tools/+/192719 already improved the situation massively; this issue is what remains. Is the general feeling therefore that we should upgrade and manage these test "flakes", continuing to try and track down the root cause? That's a question for you, @muirrn, as well as @stamblerre and @ianthehat

@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Sep 5, 2019

I don't think I would feel comfortable tagging a new version (and in the same vein, having govim use an updated version), until we aren't seeing these issues anymore.

@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Sep 5, 2019

Just tried against 2a03e9e (merged result of https://go-review.googlesource.com/c/tools/+/193480/) and got a failure. Also had a ~15% failure rate on CI.

2019/09/05 17:16:48 failed to check package: context canceled
2019/09/05 17:16:48 failed to compute diagnostics: no CheckPackageHandles for file:///tmp/go-test-script854391406/script-function_hover/main.go
@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Sep 5, 2019

Following a couple of conversations with @muirrn and @stamblerre I've concluded I'm conflating two things here.

  1. spurious LogMessage callbacks with "errors that are not actually errors"
  2. "functional" errors, where a go-to-definition (in the instance we saw in #34103 (comment)) failed because of a context cancellation

I'm going to leave this issue for category 1. These spurious "errors" appear to manifest when changes to the same file happen in quick succession. The error is apparently reported because the attempt to compute diagnostics for the first change is cancelled by the second change. This is not an error.

I'll create an issue for real errors/failures that fall into category 2 when I have more details.

If we can solve this issue (i.e. the noise from "errors that are not errors") we can turn on more aggressive assertions about the number of errors that are reported to the LSP client.

@myitcv myitcv changed the title x/tools/cmd/gopls: context cancelled errors following CL 192719 x/tools/cmd/gopls: spurious context cancelled errors reported via LogMessage Sep 5, 2019
myitcv added a commit to govim/govim that referenced this issue Sep 5, 2019
In 3d166ac we fixed the fact that we had false-positive checks on the
number of errors being reported by gopls. However, fixing this uncovered
golang/go#34103. So for now, disable those
errlogmatch-based checks, pending a fix on the "noise" from gopls of
errors that are not actually errors.
myitcv added a commit to govim/govim that referenced this issue Sep 5, 2019
In 3d166ac we fixed the fact that we had false-positive checks on the
number of errors being reported by gopls. However, fixing this uncovered
golang/go#34103. So for now, disable those
errlogmatch-based checks, pending a fix on the "noise" from gopls of
errors that are not actually errors.
@myitcv myitcv modified the milestones: Unreleased, gopls v1.0 Sep 5, 2019
@stamblerre stamblerre added the Tools label Sep 9, 2019
@stamblerre stamblerre changed the title x/tools/cmd/gopls: spurious context cancelled errors reported via LogMessage x/tools/gopls: spurious context cancelled errors reported via LogMessage Dec 24, 2019
@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 8, 2020

@myitcv: Is this still an issue for you? We've added more handling to ensure that context cancellations aren't logged as errors.

@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Jan 8, 2020

Yes we're still seeing an issue here.

In the as-yet-unmerged govim/govim#661 we have turned our assertions that there should (in most of our test cases) be no errors/warnings at the end of the test back on. And we have test failures across the board, i.e. the assertions fail.

Per govim/govim@afa4918, this uses x/tools and gopls 53017a39 with 11e9d9cc cherry-picked on top.

Some of the errors/warnings we see logged are:

LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2020/01/08 12:55:45 failed to load snapshot: no packages found for query ./...\n\tdirectory = file:///artefacts/cmd/govim/scenario_default/go-test-script313459836/script-format_on_save_new_file"}
LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2020/01/08 12:55:46 diagnoseFile: could not generate diagnostics: couldn't exec 'go [list -e -json -compiled=true -test=true -export=false -deps=true -find=false -- /artefacts/cmd/govim/scenario_default/go-test-script313459836/script-format_on_save_new_file]': context canceled *errors.errorString"}
LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2020/01/08 12:57:16 : stat /artefacts/cmd/govim/scenario_goimports_local/go-test-script051104478/script-new_import/gopath/pkg/mod/rubbish.com/useless@v1.0.0.tmp-875641904/main.go: no such file or directory"}
LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2020/01/08 12:57:16 no diagnostics: context canceled\n\tURI = file:///artefacts/cmd/govim/scenario_goimports_local/go-test-script051104478/script-new_import/main.go"}
LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2020/01/08 12:55:14 diagnoseFile: could not generate diagnostics: go [list -f {{context.GOARCH}} {{context.Compiler}} -- unsafe]: signal: killed: "}

All of the gopls log files for this test run are available via:

cd $(mktemp -d) && curl -s https://gist.githubusercontent.com/myitcv/b75a1adc6b140d9f01175740e842920e/raw/adf8afc7922658a97dcfb206094b712b9725e394/logs.base64 | base64 -d | tar -zx
@stamblerre stamblerre changed the title x/tools/gopls: spurious context cancelled errors reported via LogMessage x/tools/gopls: stop logging context cancellation errors Jan 8, 2020
@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 8, 2020

Thanks for following up. These logged errors are probably the result of go/packages.Load not returning the pure context.Canceled, but we can add some workarounds.

@sbromberger

This comment has been minimized.

Copy link

@sbromberger sbromberger commented Jan 9, 2020

Hi there,

I just updated to latest gopls master and am getting these errors when opening a file in neovim (if it matters, I'm using neovim's built-in lsp client):

LSP[gopls] 2020/01/08 21:10:56 no diagnostics: context canceled
^IURI = file:///home/seth/dev/go/src/github.com/sbromberger/vt1/main.go
Press ENTER or type command to continue

This wasn't happening with my previous gopls install (master from a week or so ago).

@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 9, 2020

@sbromberger: My guess is that the errors you are seeing are related to #36463. I will hopefully have a fix for that issue in the next few days. In the meantime, I'd recommend sticking with the version of gopls tagged latest, since master can be broken at times.

@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 15, 2020

@myitcv: These errors should be handled correctly now, as of https://golang.org/cl/214581.

@stamblerre stamblerre removed this from the gopls v1.0 milestone Jan 15, 2020
@stamblerre stamblerre added this to the gopls/v0.3.0 milestone Jan 15, 2020
@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Jan 16, 2020

The only errors we're now seeing (as of 473961ec044c) are:

LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2020/01/16 12:12:55 diagnose: no workspace packages: context canceled\n\tdirectory = 0xa8d010"}
@gopherbot

This comment has been minimized.

Copy link

@gopherbot gopherbot commented Jan 16, 2020

Change https://golang.org/cl/215019 mentions this issue: internal/lsp: don't log context.Cancelation in diagnostics

@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 16, 2020

Thanks - one more log statement to clean up then.

@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Jan 20, 2020

I've just done a test against 0cba7a3a with partial revert of CL 214586 applied on top, in the form of CL 215239, and we're seeing the following error log messages:

LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2020/01/20 13:37:31 diagnose: no workspace packages: go [list -f {{context.GOARCH}} {{context.Compiler}} -- unsafe]: exit status 1: go: updates to go.mod needed, but contents have changed\n\n\tdirectory = 0xa98af0"}

Figured I'd just re-open this issue because it's basically the same theme as above, albeit it not context cancellation this time.

gopls log file as follows: fail.log

@myitcv myitcv reopened this Jan 20, 2020
@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 22, 2020

This looks like a legitimate error from go list - are you able to consistently reproduce it?

@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Jan 23, 2020

are you able to consistently reproduce it?

No, it's just showing up in a PR where we cause tests to fail if we see error/warning log messages when they're not expected: govim/govim#661

For example, two failures in this test run:

cd $(mktemp -d) && curl -s https://gist.githubusercontent.com/myitcv/7df92147095b99b1b9ce2c2cb5c9d6c8/raw/a95aab6b4446fd6690414c150e91ddc02b17e834/logs.base64 | base64 -d | tar -zx

Log files that show errors are:

govim/cmd/govim/scenario_default/script-go_to_def_same_file/_tmp/gopls.log
govim/cmd/govim/scenario_default/script-go_to_def_usetab/_tmp/gopls.log
@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 23, 2020

Hm, well this does seem to be a legitimate error coming from go list, so it seems fair to me that we are logging it. I think I'll go ahead and close this issue, and if you have a test where this repros consistently, please open a new issue so we can investigate it. I know it looks like the context cancellation errors because of this part: go [list -f {{context.GOARCH}} {{context.Compiler}} -- unsafe], but this is actually just one of the calls to go list done by go/packages, so it is a real error.

@stamblerre stamblerre closed this Jan 23, 2020
@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Jan 23, 2020

Ok, but in this case we are not expecting any calls to go/packages to fail. So whilst I defer to you on whether this is a real error or not, it's a real problem from my perspective because there should be no reason why these calls are failing here. I'll raise a separate issue tomorrow.

@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Jan 23, 2020

Sorry, yes I agree that the error should not be happening. But I don't think that this falls under the issue, since this was about our sporadic logging of useless context cancellation errors. This sounds like a separate issue entirely to me.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
5 participants
You can’t perform that action at this time.