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: first Configuration does not happen as part of handling Initialized #35817

Closed
myitcv opened this issue Nov 25, 2019 · 5 comments

Comments

@myitcv
Copy link
Member

@myitcv myitcv commented Nov 25, 2019

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

$ go version
go version devel +6f7b96f6cb Sat Nov 23 11:00:41 2019 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20191113223546-95cb2a1a7eae => github.com/myitcvforks/tools v0.0.0-20191119111301-0222b4b716c6
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.1.8-0.20191115202509-3a792d9c32b2 => github.com/myitcvforks/tools/gopls v0.0.0-20191119111301-0222b4b716c6

Note that github.com/myitcvforks/tools v0.0.0-20191119111301-0222b4b716c6 and github.com/myitcvforks/tools/gopls v0.0.0-20191119111301-0222b4b716c6 correspond to the x/tools 95cb2a1a7eae2d74d8211d4930f76e8ccd5e124f with 80313e1ba7181ff88576941b25b4beb004e348db cherry picked on top. Reason being, we can't move beyond 95cb2a1a7eae2d74d8211d4930f76e8ccd5e124f because otherwise we start tripping over the mistmatched versions problem described in #35114

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

What did you do?

We have a govim test that is looking to verify the behaviour of setting the "env" config setting with GOFLAGS=-mod=reaonly.

However the issue we are seeing is that the initial Configuration call from gopls to govim happens as follows:

  • govim -> gopls: Initialize()
  • govim -> gopls: Initialized() (notification)
  • govim -> gopls: didOpen("main.go")
  • govim -> gopls: didChange("main.go")
  • gopls -> govim: Configuration()

i.e. it's not happening as part of handling the Initialized notification from govim.

What did you expect to see?

This doesn't appear to be specified in the LSP spec https://microsoft.github.io/language-server-protocol/specifications/specification-3-14/#initialized but not calling Configuration as part of handling the Initialized notification means that the client has no way of registering configuration that should be applied "from the start".

e.g. in this case, setting "env" to include GOFLAGS=-mod=reaonly. If this does not happen during the handling of Initialized then the go.mod file will likely already have been modified by the time the results of Configuration come to be processed.

One could argue that the client could instead send the DidChangeConfiguration notification immediately after Initialized but this is not specified either, so we can't be guaranteed that all clients will do this. Whereas calling Configuration as part of the handling of Initialized (not afterwards because otherwise this creates a race) seems safe.

What did you see instead?

As above.

gopls log as follows:
fail.log


cc @stamblerre

@gopherbot gopherbot added this to the Unreleased milestone Nov 25, 2019
@gopherbot gopherbot added the Tools label Nov 25, 2019
@myitcv myitcv changed the title x/tools/gopls: first Configuration does not happen as first call after Initialized x/tools/gopls: first Configuration does not happen as part of handling Initialized Nov 25, 2019
@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Nov 25, 2019

Another reason this needs to happen as part of the handling of Initialized is that gopls runs initial queries on startup. And because these queries can have side effects, gopls first needs to know any initial configuration settings before it can proceed: #35818

myitcv added a commit to govim/govim that referenced this issue Nov 25, 2019
As a temporary, fragile workaround for
golang/go#35817, we block the initialisation
of govim until we have received the Configuration call from gopls.

Per the TODO message in the code, this is fragile and best and built on
broken assumptions at worst. But it should suffice for now.
myitcv added a commit to govim/govim that referenced this issue Nov 25, 2019
As a temporary, fragile workaround for

This is a rather fragile workaround for
golang/go#35817, we block the initialisation
of govim until we have received the Configuration call from gopls.  It's
fragile because we are relying on gopls not handling any requests until
the response to Configuration is received and processed. In practice
this appears to currently be the case but there is no guarantee of this
going forward. Rather we hope that a fix for
golang/go#35817 lands sooner rather than later
at whic point this workaround can go.

We also use a lock here because, despite it appearing that will only be a single
Configuration call and that if there were more they would be serial, we can't rely on
this.

This is fragile and best and built on broken assumptions at worst. But
it should suffice for now.
myitcv added a commit to govim/govim that referenced this issue Nov 26, 2019
As a temporary, fragile workaround for

This is a rather fragile workaround for
golang/go#35817, we block the initialisation
of govim until we have received the Configuration call from gopls.  It's
fragile because we are relying on gopls not handling any requests until
the response to Configuration is received and processed. In practice
this appears to currently be the case but there is no guarantee of this
going forward. Rather we hope that a fix for
golang/go#35817 lands sooner rather than later
at whic point this workaround can go.

We also use a lock here because, despite it appearing that will only be a single
Configuration call and that if there were more they would be serial, we can't rely on
this.

This is fragile and best and built on broken assumptions at worst. But
it should suffice for now.
myitcv added a commit to govim/govim that referenced this issue Nov 27, 2019
As a temporary, fragile workaround for

This is a rather fragile workaround for
golang/go#35817, we block the initialisation
of govim until we have received the Configuration call from gopls.  It's
fragile because we are relying on gopls not handling any requests until
the response to Configuration is received and processed. In practice
this appears to currently be the case but there is no guarantee of this
going forward. Rather we hope that a fix for
golang/go#35817 lands sooner rather than later
at whic point this workaround can go.

We also use a lock here because, despite it appearing that will only be a single
Configuration call and that if there were more they would be serial, we can't rely on
this.

This is fragile and best and built on broken assumptions at worst. But
it should suffice for now.
myitcv added a commit to govim/govim that referenced this issue Nov 27, 2019
…593)

As a temporary, fragile workaround for

This is a rather fragile workaround for
golang/go#35817, we block the initialisation
of govim until we have received the Configuration call from gopls.  It's
fragile because we are relying on gopls not handling any requests until
the response to Configuration is received and processed. In practice
this appears to currently be the case but there is no guarantee of this
going forward. Rather we hope that a fix for
golang/go#35817 lands sooner rather than later
at whic point this workaround can go.

We also use a lock here because, despite it appearing that will only be a single
Configuration call and that if there were more they would be serial, we can't rely on
this.

This is fragile and best and built on broken assumptions at worst. But
it should suffice for now.
@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Nov 30, 2019

I expect that this is more likely an issue in the way that we are writing out the logs, because the initialized request definitely asks for configurations before proceeding. The (*Server).addView function calls (*Server).fetchConfig before proceeding (see here). Do you have a repro where configurations are not applied correctly?

@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Dec 2, 2019

I expect that this is more likely an issue in the way that we are writing out the logs

I'm not entirely sure on that, because this was also confirmed by the govim logs which show the sequence of calls as above.

Here's a similar snippet from our govim log:

Details
2019-12-02T22:34:44.196829_#1: Running gopls: /tmp/gobin-gopls-installdir759634052/gopls -rpc.trace -logfile /tmp/gopls_log_20191202_2234_44_042180694
2019-12-02T22:34:44.197832_#1: gopls server start =======================
2019-12-02T22:34:44.197832_#1: gopls.Initialize() call; params:
2019-12-02T22:34:44.197832_#1: &protocol.ParamInitia{
2019-12-02T22:34:44.197832_#1:     InitializeParams: protocol.InitializeParams{
2019-12-02T22:34:44.197832_#1:         ProcessID:    0,
2019-12-02T22:34:44.197832_#1:         ClientInfo:   (*struct { Name string "json:\"name\""; Version string "json:\"version,omitempty\"" })(nil),
2019-12-02T22:34:44.197832_#1:         RootPath:     "",
2019-12-02T22:34:44.197832_#1:         RootURI:      "file:///tmp/go-test-script102301715/script-config_set_env_goflags_mod_readonly",
2019-12-02T22:34:44.197832_#1:         Capabilities: protocol.ClientCapabilities{
2019-12-02T22:34:44.197832_#1:             Workspace: struct { ApplyEdit bool "json:\"applyEdit,omitempty\""; WorkspaceEdit protocol.WorkspaceEditClientCapabilities "json:\"workspaceEdit,omit
empty\""; DidChangeConfiguration protocol.DidChangeConfigurationClientCapabilities "json:\"didChangeConfiguration,omitempty\""; DidChangeWatchedFiles protocol.DidChangeWatchedFilesClientCapab
ilities "json:\"didChangeWatchedFiles,omitempty\""; Symbol protocol.WorkspaceSymbolClientCapabilities "json:\"symbol,omitempty\""; ExecuteCommand protocol.ExecuteCommandClientCapabilities "js
on:\"executeCommand,omitempty\""; WorkspaceFolders bool "json:\"workspaceFolders,omitempty\""; Configuration bool "json:\"configuration,omitempty\"" }{
2019-12-02T22:34:44.197832_#1:                 ApplyEdit:              false,
2019-12-02T22:34:44.197832_#1:                 WorkspaceEdit:          protocol.WorkspaceEditClientCapabilities{},
2019-12-02T22:34:44.197832_#1:                 DidChangeConfiguration: protocol.DidChangeConfigurationClientCapabilities{DynamicRegistration:true},
2019-12-02T22:34:44.197832_#1:                 DidChangeWatchedFiles:  protocol.DidChangeWatchedFilesClientCapabilities{},
2019-12-02T22:34:44.197832_#1:                 Symbol:                 protocol.WorkspaceSymbolClientCapabilities{},
2019-12-02T22:34:44.197832_#1:                 ExecuteCommand:         protocol.ExecuteCommandClientCapabilities{},
2019-12-02T22:34:44.197832_#1:                 WorkspaceFolders:       false,
2019-12-02T22:34:44.197832_#1:                 Configuration:          true,
2019-12-02T22:34:44.197832_#1:             },
2019-12-02T22:34:44.197832_#1:             TextDocument: protocol.TextDocumentClientCapabilities{
2019-12-02T22:34:44.197832_#1:                 Synchronization: (*protocol.TextDocumentSyncClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 Completion:      (*protocol.CompletionClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 Hover:           &protocol.HoverClientCapabilities{
2019-12-02T22:34:44.197832_#1:                     DynamicRegistration: false,
2019-12-02T22:34:44.197832_#1:                     ContentFormat:       {"plaintext"},
2019-12-02T22:34:44.197832_#1:                 },
2019-12-02T22:34:44.197832_#1:                 SignatureHelp:      (*protocol.SignatureHelpClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 Declaration:        (*protocol.DeclarationClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 Definition:         (*protocol.DefinitionClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 TypeDefinition:     (*protocol.TypeDefinitionClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 Implementation:     (*protocol.ImplementationClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 References:         (*protocol.ReferenceClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 DocumentHighlight:  (*protocol.DocumentHighlightClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 DocumentSymbol:     (*protocol.DocumentSymbolClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 CodeAction:         (*protocol.CodeActionClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 CodeLens:           (*protocol.CodeLensClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 DocumentLink:       (*protocol.DocumentLinkClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 ColorProvider:      (*protocol.DocumentColorClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 Formatting:         (*protocol.DocumentFormattingClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 RangeFormatting:    (*protocol.DocumentRangeFormattingClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 OnTypeFormatting:   (*protocol.DocumentOnTypeFormattingClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 Rename:             (*protocol.RenameClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 FoldingRange:       (*protocol.FoldingRangeClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 SelectionRange:     (*protocol.SelectionRangeClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:                 PublishDiagnostics: (*protocol.PublishDiagnosticsClientCapabilities)(nil),
2019-12-02T22:34:44.197832_#1:             },
2019-12-02T22:34:44.197832_#1:             Window:              nil,
2019-12-02T22:34:44.197832_#1:             Experimental:        nil,
2019-12-02T22:34:44.197832_#1:             DynamicRegistration: false,
2019-12-02T22:34:44.197832_#1:         },
2019-12-02T22:34:44.197832_#1:         InitializationOptions: map[string]interface {}{
2019-12-02T22:34:44.197832_#1:             "incrementalSync": bool(true),
2019-12-02T22:34:44.197832_#1:             "noDocsOnHover":   bool(true),
2019-12-02T22:34:44.197832_#1:         },
2019-12-02T22:34:44.197832_#1:         Trace:            "",
2019-12-02T22:34:44.197832_#1:         WorkspaceFolders: nil,
2019-12-02T22:34:44.197832_#1:     },
2019-12-02T22:34:44.197832_#1:     WorkDoneProgressParams: protocol.WorkDoneProgressParams{},
2019-12-02T22:34:44.197832_#1: }
2019-12-02T22:34:44.197832_#1: gopls server end =======================
2019-12-02T22:34:44.250695_#1: gopls server start =======================
2019-12-02T22:34:44.250695_#1: gopls.Initialize() return; err: ; res:
2019-12-02T22:34:44.250695_#1: &protocol.InitializeResult{
2019-12-02T22:34:44.250695_#1:     Capabilities: protocol.ServerCapabilities{
2019-12-02T22:34:44.250695_#1:         TextDocumentSync: map[string]interface {}{
2019-12-02T22:34:44.250695_#1:             "openClose": bool(true),
2019-12-02T22:34:44.250695_#1:             "change":    float64(2),
2019-12-02T22:34:44.250695_#1:             "save":      map[string]interface {}{
2019-12-02T22:34:44.250695_#1:             },
2019-12-02T22:34:44.250695_#1:         },
2019-12-02T22:34:44.250695_#1:         CompletionProvider: &protocol.CompletionOptions{
2019-12-02T22:34:44.250695_#1:             TriggerCharacters:       {"."},
2019-12-02T22:34:44.250695_#1:             AllCommitCharacters:     nil,
2019-12-02T22:34:44.250695_#1:             ResolveProvider:         false,
2019-12-02T22:34:44.250695_#1:             WorkDoneProgressOptions: protocol.WorkDoneProgressOptions{},
2019-12-02T22:34:44.250695_#1:         },
2019-12-02T22:34:44.250695_#1:         HoverProvider:         true,
2019-12-02T22:34:44.250695_#1:         SignatureHelpProvider: &protocol.SignatureHelpOptions{
2019-12-02T22:34:44.250695_#1:             TriggerCharacters:       {"(", ","},
2019-12-02T22:34:44.250695_#1:             RetriggerCharacters:     nil,
2019-12-02T22:34:44.250695_#1:             WorkDoneProgressOptions: protocol.WorkDoneProgressOptions{},
2019-12-02T22:34:44.250695_#1:         },
2019-12-02T22:34:44.250695_#1:         DeclarationProvider:              false,
2019-12-02T22:34:44.250695_#1:         DefinitionProvider:               true,
2019-12-02T22:34:44.250695_#1:         TypeDefinitionProvider:           true,
2019-12-02T22:34:44.250695_#1:         ImplementationProvider:           true,
2019-12-02T22:34:44.250695_#1:         ReferencesProvider:               true,
2019-12-02T22:34:44.250695_#1:         DocumentHighlightProvider:        true,
2019-12-02T22:34:44.250695_#1:         DocumentSymbolProvider:           true,
2019-12-02T22:34:44.250695_#1:         CodeActionProvider:               bool(true),
2019-12-02T22:34:44.250695_#1:         CodeLensProvider:                 (*protocol.CodeLensOptions)(nil),
2019-12-02T22:34:44.250695_#1:         DocumentLinkProvider:             &protocol.DocumentLinkOptions{},
2019-12-02T22:34:44.250695_#1:         ColorProvider:                    false,
2019-12-02T22:34:44.250695_#1:         WorkspaceSymbolProvider:          false,
2019-12-02T22:34:44.250695_#1:         DocumentFormattingProvider:       true,
2019-12-02T22:34:44.250695_#1:         DocumentRangeFormattingProvider:  false,
2019-12-02T22:34:44.250695_#1:         DocumentOnTypeFormattingProvider: (*protocol.DocumentOnTypeFormattingOptions)(nil),
2019-12-02T22:34:44.250695_#1:         RenameProvider:                   bool(true),
2019-12-02T22:34:44.250695_#1:         FoldingRangeProvider:             true,
2019-12-02T22:34:44.250695_#1:         SelectionRangeProvider:           false,
2019-12-02T22:34:44.250695_#1:         ExecuteCommandProvider:           &protocol.ExecuteCommandOptions{
2019-12-02T22:34:44.250695_#1:             Commands:                {"tidy"},
2019-12-02T22:34:44.250695_#1:             WorkDoneProgressOptions: protocol.WorkDoneProgressOptions{},
2019-12-02T22:34:44.250695_#1:         },
2019-12-02T22:34:44.250695_#1:         Experimental: nil,
2019-12-02T22:34:44.250695_#1:         Workspace:    &struct { WorkspaceFolders *struct { Supported bool "json:\"supported,omitempty\""; ChangeNotifications string "json:\"changeNotifications
,omitempty\"" } "json:\"workspaceFolders,omitempty\"" }{
2019-12-02T22:34:44.250695_#1:             WorkspaceFolders: &struct { Supported bool "json:\"supported,omitempty\""; ChangeNotifications string "json:\"changeNotifications,omitempty\"" }{Sup
ported:true, ChangeNotifications:"workspace/didChangeWorkspaceFolders"},
2019-12-02T22:34:44.250695_#1:         },
2019-12-02T22:34:44.250695_#1:     },
2019-12-02T22:34:44.250695_#1:     ServerInfo: (*struct { Name string "json:\"name\""; Version string "json:\"version,omitempty\"" })(nil),
2019-12-02T22:34:44.250695_#1:     Custom:     {},
2019-12-02T22:34:44.250695_#1: }
2019-12-02T22:34:44.250695_#1: gopls server end =======================
2019-12-02T22:34:44.250735_#1: gopls server start =======================
2019-12-02T22:34:44.250735_#1: gopls.Initialized() call; params:
2019-12-02T22:34:44.250735_#1: &protocol.InitializedParams{}
2019-12-02T22:34:44.250735_#1: gopls server end =======================
2019-12-02T22:34:44.250775_#1: gopls server start =======================
2019-12-02T22:34:44.250775_#1: gopls.Initialized() return; err: 
2019-12-02T22:34:44.250775_#1: gopls server end =======================
2019-12-02T22:34:44.251401_#1: gopls client start =======================
2019-12-02T22:34:44.251401_#1: RegisterCapability: &protocol.RegistrationParams{
2019-12-02T22:34:44.251401_#1:     Registrations: {
2019-12-02T22:34:44.251401_#1:         {
2019-12-02T22:34:44.251401_#1:             ID:              "workspace/didChangeConfiguration",
2019-12-02T22:34:44.251401_#1:             Method:          "workspace/didChangeConfiguration",
2019-12-02T22:34:44.251401_#1:             RegisterOptions: nil,
2019-12-02T22:34:44.251401_#1:         },
2019-12-02T22:34:44.251401_#1:         {
2019-12-02T22:34:44.251401_#1:             ID:              "workspace/didChangeWorkspaceFolders",
2019-12-02T22:34:44.251401_#1:             Method:          "workspace/didChangeWorkspaceFolders",
2019-12-02T22:34:44.251401_#1:             RegisterOptions: nil,
2019-12-02T22:34:44.251401_#1:         },
2019-12-02T22:34:44.251401_#1:     },
2019-12-02T22:34:44.251401_#1: }
2019-12-02T22:34:44.251401_#1: gopls client end =======================
2019-12-02T22:34:44.259644_#1: vim start =======================
2019-12-02T22:34:44.259644_#1: sendJSONMsg: [0,[44,"initcomplete"]]
2019-12-02T22:34:44.259644_#1: vim end =======================
2019-12-02T22:34:44.261043_#1: vim start =======================
2019-12-02T22:34:44.261043_#1: recvJSONMsg: [45] ["callback",44,[""]]
2019-12-02T22:34:44.261043_#1: vim end =======================
2019-12-02T22:34:44.261068_#1: run: waiting to read a JSON message
Accepted driver connection on 0.0.0.0:43099
2019-12-02T22:34:44.263774_#1: vim start =======================
2019-12-02T22:34:44.263774_#1: sendJSONMsg: [0,[45,"call","s:schedule",1]]
2019-12-02T22:34:44.263774_#1: vim end =======================
2019-12-02T22:34:44.264179_#1: vim start =======================
2019-12-02T22:34:44.264179_#1: recvJSONMsg: [46] ["schedule",1]
2019-12-02T22:34:44.264179_#1: vim end =======================
2019-12-02T22:34:44.264246_#1: run: waiting to read a JSON message
2019-12-02T22:34:44.264292_#1: vim start =======================
2019-12-02T22:34:44.264292_#1: sendJSONMsg: [0,[46,"ex","e main.go"]]
2019-12-02T22:34:44.264292_#1: vim end =======================
2019-12-02T22:34:44.264878_#1: vim start =======================
2019-12-02T22:34:44.264878_#1: recvJSONMsg: [47] ["function","autocommand:0",[1]]
2019-12-02T22:34:44.264878_#1: vim end =======================
2019-12-02T22:34:44.264937_#1: run: waiting to read a JSON message
2019-12-02T22:34:44.264966_#1: vim start =======================
2019-12-02T22:34:44.264966_#1: sendJSONMsg: [47,["",null]]
2019-12-02T22:34:44.264966_#1: vim end =======================
2019-12-02T22:34:44.267078_#1: vim start =======================
2019-12-02T22:34:44.267078_#1: recvJSONMsg: [48] ["function","autocommand:1",[{"Num":1,"Name":"/tmp/go-test-script102301715/script-config_set_env_goflags_mod_readonly/main.go","Loaded":1,"Con
tents":"package main\n\nimport \"example.com/blah\"\n\nfunc main() {\n\tprintln(blah.Name)\n}\n"}]]
2019-12-02T22:34:44.267078_#1: vim end =======================
2019-12-02T22:34:44.267156_#1: run: waiting to read a JSON message
2019-12-02T22:34:44.267221_#1: vim start =======================
2019-12-02T22:34:44.267221_#1: sendJSONMsg: [0,[47,"call","listener_add","GOVIM_internal_EnrichDelta",1]]
2019-12-02T22:34:44.267221_#1: vim end =======================
2019-12-02T22:34:44.267537_#1: vim start =======================
2019-12-02T22:34:44.267537_#1: recvJSONMsg: [49] ["callback",47,["",1]]
2019-12-02T22:34:44.267537_#1: vim end =======================
2019-12-02T22:34:44.267577_#1: run: waiting to read a JSON message
2019-12-02T22:34:44.267631_#1: vim start =======================
2019-12-02T22:34:44.267631_#1: sendJSONMsg: [0,[48,"call","s:batchCall",[["call","s:mustNothing","sign_getplaced",1,{"group":"govim"}]]]]
2019-12-02T22:34:44.267631_#1: vim end =======================
2019-12-02T22:34:44.268006_#1: vim start =======================
2019-12-02T22:34:44.268006_#1: recvJSONMsg: [50] ["callback",48,["",[[{"signs":[],"bufnr":1}]]]]
2019-12-02T22:34:44.268006_#1: vim end =======================
2019-12-02T22:34:44.268027_#1: run: waiting to read a JSON message
2019-12-02T22:34:44.268142_#1: gopls server start =======================
2019-12-02T22:34:44.268142_#1: gopls.DidOpen() call; params:
2019-12-02T22:34:44.268142_#1: &protocol.DidOpenTextDocumentParams{
2019-12-02T22:34:44.268142_#1:     TextDocument: protocol.TextDocumentItem{URI:"file:///tmp/go-test-script102301715/script-config_set_env_goflags_mod_readonly/main.go", LanguageID:"go", Versi
on:1, Text:"package main\n\nimport \"example.com/blah\"\n\nfunc main() {\n\tprintln(blah.Name)\n}\n"},
2019-12-02T22:34:44.268142_#1: }
2019-12-02T22:34:44.268142_#1: gopls server end =======================
2019-12-02T22:34:44.268209_#1: gopls server start =======================
2019-12-02T22:34:44.268209_#1: gopls.DidOpen() return; err: 
2019-12-02T22:34:44.268209_#1: gopls server end =======================
2019-12-02T22:34:44.268218_#1: vim start =======================
2019-12-02T22:34:44.268218_#1: sendJSONMsg: [48,["",null]]
2019-12-02T22:34:44.268218_#1: vim end =======================
2019-12-02T22:34:44.269581_#1: vim start =======================
2019-12-02T22:34:44.269581_#1: recvJSONMsg: [51] ["callback",46,[""]]
2019-12-02T22:34:44.269581_#1: vim end =======================
2019-12-02T22:34:44.269627_#1: run: waiting to read a JSON message
2019-12-02T22:34:44.269650_#1: vim start =======================
2019-12-02T22:34:44.269650_#1: sendJSONMsg: [46,["",""]]
2019-12-02T22:34:44.269650_#1: vim end =======================
2019-12-02T22:34:44.269896_#1: vim start =======================
2019-12-02T22:34:44.269896_#1: recvJSONMsg: [52] ["callback",45,["",0]]
2019-12-02T22:34:44.269896_#1: vim end =======================
2019-12-02T22:34:44.269934_#1: run: waiting to read a JSON message
Waiting for govim driver connection on 0.0.0.0:43099...
2019-12-02T22:34:44.304673_#1: gopls client start =======================
2019-12-02T22:34:44.304673_#1: Configuration: &protocol.ParamConfig{
2019-12-02T22:34:44.304673_#1:     ConfigurationParams: protocol.ConfigurationParams{
2019-12-02T22:34:44.304673_#1:         Items: {
2019-12-02T22:34:44.304673_#1:             {ScopeURI:"file:///tmp/go-test-script102301715/script-config_set_env_goflags_mod_readonly", Section:"gopls"},
2019-12-02T22:34:44.304673_#1:             {ScopeURI:"file:///tmp/go-test-script102301715/script-config_set_env_goflags_mod_readonly", Section:"gopls-script-config_set_env_goflags_mod_readonl
y"},
2019-12-02T22:34:44.304673_#1:         },
2019-12-02T22:34:44.304673_#1:     },
2019-12-02T22:34:44.304673_#1:     PartialResultParams: protocol.PartialResultParams{},
2019-12-02T22:34:44.304673_#1: }
2019-12-02T22:34:44.304673_#1: gopls client end =======================
2019-12-02T22:34:44.304729_#1: gopls client start =======================
2019-12-02T22:34:44.304729_#1: Configuration response: []interface {}{
2019-12-02T22:34:44.304729_#1:     map[string]interface {}{
2019-12-02T22:34:44.304729_#1:         "hoverKind": "FullDocumentation",
2019-12-02T22:34:44.304729_#1:         "env":       map[string]string{"GOFLAGS":"-mod=readonly"},
2019-12-02T22:34:44.304729_#1:     },
2019-12-02T22:34:44.304729_#1:     nil,
2019-12-02T22:34:44.304729_#1: }
2019-12-02T22:34:44.304729_#1: gopls client end =======================
2019-12-02T22:34:44.304920_#1: gopls client start =======================
2019-12-02T22:34:44.304920_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/02 22:34:44 Build info\n----------\ngolang.org/x/tools/gopls master\n    golang.org/x/t
ools/gopls@v0.1.8-0.20191115202509-3a792d9c32b2 h1:kFRWan3AZ/AzCvlyjno1vs7523G6WyF4KFjtWEFOP+E=\n    github.com/BurntSushi/toml@v0.3.1 h1:WXkYYl6Yr3qBf1K79EBnL4mak0OimBfB0XUf9Vl28OQ=\n    git
hub.com/sergi/go-diff@v1.0.0 h1:Kpca3qRNrduNnOQeazBd0ysaKrUJiIuISHxogkT9RPQ=\n    golang.org/x/sync@v0.0.0-20190423024810-112230192c58 h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU=\n    gol
ang.org/x/tools@v0.0.0-20191113223546-95cb2a1a7eae => github.com/myitcvforks/tools\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 +22688f740d Wed Nov 27 04:05:12 2019 +0000 linux/amd64\n\nGO111M
ODULE=\"\"\nGOARCH=\"amd64\"\nGOBIN=\"\"\nGOCACHE=\"/tmp/go-test-script102301715/script-config_set_env_goflags_mod_readonly/.home/.cache/go-build\"\nGOENV=\"/tmp/go-test-script102301715/scrip
t-config_set_env_goflags_mod_readonly/.home/.config/go/env\"\nGOEXE=\"\"\nGOFLAGS=\"\"\nGOHOSTARCH=\"amd64\"\nGOHOSTOS=\"linux\"\nGOINSECURE=\"\"\nGONOPROXY=\"\"\nGONOSUMDB=\"*\"\nGOOS=\"linu
x\"\nGOPATH=\"/tmp/go-test-script102301715/script-config_set_env_goflags_mod_readonly/.home/go\"\nGOPRIVATE=\"\"\nGOPROXY=\"http://127.0.0.1:35255/mod\"\nGOROOT=\"/home/myitcv/dev/go\"\nGOSUM
DB=\"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/gost
uff/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\"\nGOGCCFLA
GS=\"-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-test-script102301715/script-config_set_env_goflags_mod_readonly/_tmp/go-build263614088=/tmp/go-build -gno-record-gcc-swi
tches\"\n"}
2019-12-02T22:34:44.304920_#1: gopls client end =======================
2019-12-02T22:34:44.348730_#1: gopls stderr: 2019/12/02 22:34:44 no dep handle: no metadata for example.com/blah
2019-12-02T22:34:44.348742_#1: gopls stderr:    package = example.com/blah
2019-12-02T22:34:44.348749_#1: gopls client start =======================
2019-12-02T22:34:44.348749_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/02 22:34:44 go/packages.Load\n\tpackages = 1"}
2019-12-02T22:34:44.348749_#1: gopls client end =======================
2019-12-02T22:34:44.348868_#1: gopls client start =======================
2019-12-02T22:34:44.348868_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/02 22:34:44 go/packages.Load\n\tpackage = mod.com\n\tfiles = [/tmp/go-test-script102301
715/script-config_set_env_goflags_mod_readonly/main.go]"}
2019-12-02T22:34:44.348868_#1: gopls client end =======================
2019-12-02T22:34:44.348955_#1: gopls client start =======================
2019-12-02T22:34:44.348955_#1: LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2019/12/02 22:34:44 no dep handle: no metadata for example.com/blah\n\tpackage = example.com/bl
ah"}
2019-12-02T22:34:44.348955_#1: gopls client end =======================
2019-12-02T22:34:44.391815_#1: gopls stderr: 2019/12/02 22:34:44 no dep handle: no metadata for example.com/blah
2019-12-02T22:34:44.391849_#1: gopls stderr:    package = example.com/blah
2019-12-02T22:34:44.391936_#1: gopls client start =======================
2019-12-02T22:34:44.391936_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/02 22:34:44 go/packages.Load\n\tpackages = 1"}
2019-12-02T22:34:44.391936_#1: gopls client end =======================
2019-12-02T22:34:44.391999_#1: gopls client start =======================
2019-12-02T22:34:44.391999_#1: LogMessage callback: &protocol.LogMessageParams{Type:3, Message:"2019/12/02 22:34:44 go/packages.Load\n\tpackage = mod.com\n\tfiles = [/tmp/go-test-script102301
715/script-config_set_env_goflags_mod_readonly/main.go]"}
2019-12-02T22:34:44.391999_#1: gopls client end =======================
2019-12-02T22:34:44.392430_#1: gopls client start =======================
2019-12-02T22:34:44.392430_#1: LogMessage callback: &protocol.LogMessageParams{Type:1, Message:"2019/12/02 22:34:44 no dep handle: no metadata for example.com/blah\n\tpackage = example.com/bl
ah"}
2019-12-02T22:34:44.392430_#1: gopls client end =======================
2019-12-02T22:34:44.396733_#1: gopls client start =======================
2019-12-02T22:34:44.396733_#1: PublishDiagnostics callback: &protocol.PublishDiagnosticsParams{
2019-12-02T22:34:44.396733_#1:     URI:         "file:///tmp/go-test-script102301715/script-config_set_env_goflags_mod_readonly/main.go",
2019-12-02T22:34:44.396733_#1:     Version:     0,
2019-12-02T22:34:44.396733_#1:     Diagnostics: {
2019-12-02T22:34:44.396733_#1:         {
2019-12-02T22:34:44.396733_#1:             Range: protocol.Range{
2019-12-02T22:34:44.396733_#1:                 Start: protocol.Position{Line:2, Character:7},
2019-12-02T22:34:44.396733_#1:                 End:   protocol.Position{Line:2, Character:25},
2019-12-02T22:34:44.396733_#1:             },
2019-12-02T22:34:44.396733_#1:             Severity:           1,
2019-12-02T22:34:44.396733_#1:             Code:               nil,
2019-12-02T22:34:44.396733_#1:             Source:             "compiler",
2019-12-02T22:34:44.396733_#1:             Message:            "could not import example.com/blah (no package for import example.com/blah)",
2019-12-02T22:34:44.396733_#1:             Tags:               nil,
2019-12-02T22:34:44.396733_#1:             RelatedInformation: nil,
2019-12-02T22:34:44.396733_#1:         },
2019-12-02T22:34:44.396733_#1:     },
2019-12-02T22:34:44.396733_#1: }
2019-12-02T22:34:44.396733_#1: gopls client end =======================

You can see the didOpen notification from client to server at 2019-12-02T22:34:44.268142 and the Configuration call from server to client at 2019-12-02T22:34:44.304673.

@stamblerre

This comment has been minimized.

Copy link
Contributor

@stamblerre stamblerre commented Dec 4, 2019

Can you try reproducing this on a file with build tags or some other configuration you would expect gopls to respect?

@myitcv

This comment has been minimized.

Copy link
Member Author

@myitcv myitcv commented Dec 5, 2019

@stamblerre kindly explained offline that this ordering of these notifications/calls is actually not significant, because all aspects in gopls that rely on configuration block on the first return from the client.

I therefore incorrectly attributed these seemingly "out of order" logs to be the root cause of #35933.

But adding a sleep in govim's implementation of Configuration confirms gopls is blocking until its return.

Hence closing.

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