internal/lsp: instrument work done reporting to use in regtests

In order for regtests to wait until file diagnostics are complete,
instrument diagnostics with verbose WorkDone reporting. In order for
this to be granular enough for use, the modification source needed to be
threaded through to the didModifyFiles function (which is where the
diagnostic goroutine is spun off).

A new expectation is added: CompletedWork, to allow specifying that a
specific work item has been completed. The problem with using
NoOutstandingWork was that it required a continuous chain of work to
prevent the regtest from succeeding when the bug was present, meaning
that by the time we have sent the didChange notification successfully
the server must have started work on its behalf. This was inherently
racy, and too tricky to get right.

Additionally, a couple bugs are fixed:
 - EmptyDiagnostics is corrected to account for the case where we have
   received zero diagnostics for a given file.
 - A deadlock is fixed in Await when expectations are immediately met.

Updates golang/go#36879
Fixes golang/go#32149

Change-Id: I49ee011860351eed96a3b4f6795804b57a10dc60
Reviewed-on: https://go-review.googlesource.com/c/tools/+/229777
Run-TryBot: Robert Findley <[email protected]>
TryBot-Result: Gobot Gobot <[email protected]>
Reviewed-by: Rebecca Stambler <[email protected]>

Author: findleyr

internal/lsp/diagnostics.go

@@ -25,14 +25,12 @@ type diagnosticKey struct {
 func (s *Server) diagnoseDetached(snapshot source.Snapshot) {
 	ctx := snapshot.View().BackgroundContext()
 	ctx = xcontext.Detach(ctx)
-
 	reports := s.diagnose(ctx, snapshot, false)
 	s.publishReports(ctx, snapshot, reports)
 }
 
 func (s *Server) diagnoseSnapshot(snapshot source.Snapshot) {
 	ctx := snapshot.View().BackgroundContext()
-
 	reports := s.diagnose(ctx, snapshot, false)
 	s.publishReports(ctx, snapshot, reports)
 }

internal/lsp/regtest/diagnostics_test.go

@@ -7,6 +7,7 @@ package regtest
 import (
 	"testing"
 
+	"golang.org/x/tools/internal/lsp"
 	"golang.org/x/tools/internal/lsp/fake"
 	"golang.org/x/tools/internal/lsp/protocol"
 )
@@ -269,13 +270,19 @@ package foo
 func main() {}
 `
 
-func TestPackageChange(t *testing.T) {
-	t.Skip("skipping due to golang.org/issues/32149")
+func TestPackageChange_Issue38328(t *testing.T) {
 	runner.Run(t, packageChange, func(t *testing.T, env *Env) {
 		env.OpenFile("a.go")
 		env.RegexpReplace("a.go", "foo", "foox")
-		// TODO: there should be no error
-		env.Await(EmptyDiagnostics("a.go"))
+		env.Await(
+			// When the bug reported in #38328 was present, we didn't get erroneous
+			// file diagnostics until after the didChange message generated by the
+			// package renaming was fully processed. Therefore, in order for this
+			// test to actually exercise the bug, we must wait until that work has
+			// completed.
+			EmptyDiagnostics("a.go"),
+			CompletedWork(lsp.DiagnosticWorkTitle(lsp.FromDidChange), 1),
+		)
 	})
 }
 

internal/lsp/regtest/env.go

@@ -203,6 +203,8 @@ func WithModes(modes EnvMode) RunOption {
 	})
 }
 
+// WithEnv overlays environment variables encoded by "<var>=<value" on top of
+// the default regtest environment.
 func WithEnv(env ...string) RunOption {
 	return optionSetter(func(opts *runConfig) {
 		opts.env = env
@@ -350,6 +352,7 @@ type State struct {
 	// be string, though the spec allows for numeric tokens as well.  When work
 	// completes, it is deleted from this map.
 	outstandingWork map[string]*workProgress
+	completedWork   map[string]int
 }
 
 type workProgress struct {
@@ -416,6 +419,7 @@ func NewEnv(ctx context.Context, t *testing.T, ws *fake.Workspace, ts servertest
 		state: State{
 			diagnostics:     make(map[string]*protocol.PublishDiagnosticsParams),
 			outstandingWork: make(map[string]*workProgress),
+			completedWork:   make(map[string]int),
 		},
 		waiters: make(map[int]*condition),
 	}
@@ -439,6 +443,7 @@ func (e *Env) onDiagnostics(_ context.Context, d *protocol.PublishDiagnosticsPar
 func (e *Env) onLogMessage(_ context.Context, m *protocol.LogMessageParams) error {
 	e.mu.Lock()
 	defer e.mu.Unlock()
+
 	e.state.logs = append(e.state.logs, m)
 	e.checkConditionsLocked()
 	return nil
@@ -447,7 +452,7 @@ func (e *Env) onLogMessage(_ context.Context, m *protocol.LogMessageParams) erro
 func (e *Env) onWorkDoneProgressCreate(_ context.Context, m *protocol.WorkDoneProgressCreateParams) error {
 	e.mu.Lock()
 	defer e.mu.Unlock()
-	// panic if we don't have a string token.
+
 	token := m.Token.(string)
 	e.state.outstandingWork[token] = &workProgress{}
 	return nil
@@ -459,7 +464,7 @@ func (e *Env) onProgress(_ context.Context, m *protocol.ProgressParams) error {
 	token := m.Token.(string)
 	work, ok := e.state.outstandingWork[token]
 	if !ok {
-		panic(fmt.Sprintf("got progress report for unknown report %s", token))
+		panic(fmt.Sprintf("got progress report for unknown report %s: %v", token, m))
 	}
 	v := m.Value.(map[string]interface{})
 	switch kind := v["kind"]; kind {
@@ -470,6 +475,8 @@ func (e *Env) onProgress(_ context.Context, m *protocol.ProgressParams) error {
 			work.percent = pct.(float64)
 		}
 	case "end":
+		title := e.state.outstandingWork[token].title
+		e.state.completedWork[title] = e.state.completedWork[title] + 1
 		delete(e.state.outstandingWork, token)
 	}
 	e.checkConditionsLocked()
@@ -567,12 +574,12 @@ func (v Verdict) String() string {
 
 // SimpleExpectation holds an arbitrary check func, and implements the Expectation interface.
 type SimpleExpectation struct {
-	check       func(State) Verdict
+	check       func(State) (Verdict, interface{})
 	description string
 }
 
 // Check invokes e.check.
-func (e SimpleExpectation) Check(s State) Verdict {
+func (e SimpleExpectation) Check(s State) (Verdict, interface{}) {
 	return e.check(s)
 }
 
@@ -584,18 +591,35 @@ func (e SimpleExpectation) Description() string {
 // NoOutstandingWork asserts that there is no work initiated using the LSP
 // $/progress API that has not completed.
 func NoOutstandingWork() SimpleExpectation {
-	check := func(s State) Verdict {
+	check := func(s State) (Verdict, interface{}) {
 		if len(s.outstandingWork) == 0 {
-			return Met
+			return Met, nil
 		}
-		return Unmet
+		return Unmet, nil
 	}
 	return SimpleExpectation{
 		check:       check,
 		description: "no outstanding work",
 	}
 }
 
+// CompletedWork expects a work item to have been completed >= atLeast times.
+//
+// Since the Progress API doesn't include any hidden metadata, we must use the
+// progress notification title to identify the work we expect to be completed.
+func CompletedWork(title string, atLeast int) SimpleExpectation {
+	check := func(s State) (Verdict, interface{}) {
+		if s.completedWork[title] >= atLeast {
+			return Met, title
+		}
+		return Unmet, nil
+	}
+	return SimpleExpectation{
+		check:       check,
+		description: fmt.Sprintf("completed work %q at least %d time(s)", title, atLeast),
+	}
+}
+
 // LogExpectation is an expectation on the log messages received by the editor
 // from gopls.
 type LogExpectation struct {
@@ -678,14 +702,16 @@ func (e DiagnosticExpectation) Description() string {
 
 // EmptyDiagnostics asserts that diagnostics are empty for the
 // workspace-relative path name.
-func EmptyDiagnostics(name string) DiagnosticExpectation {
-	isMet := func(diags *protocol.PublishDiagnosticsParams) bool {
-		return len(diags.Diagnostics) == 0
+func EmptyDiagnostics(name string) Expectation {
+	check := func(s State) (Verdict, interface{}) {
+		if diags, ok := s.diagnostics[name]; !ok || len(diags.Diagnostics) == 0 {
+			return Met, nil
+		}
+		return Unmet, nil
 	}
-	return DiagnosticExpectation{
-		isMet:       isMet,
+	return SimpleExpectation{
+		check:       check,
 		description: "empty diagnostics",
-		path:        name,
 	}
 }
 
@@ -742,6 +768,7 @@ func (e *Env) Await(expectations ...Expectation) []interface{} {
 	// called.
 	switch verdict, summary, metBy := checkExpectations(e.state, expectations); verdict {
 	case Met:
+		e.mu.Unlock()
 		return metBy
 	case Unmeetable:
 		e.mu.Unlock()
@@ -771,7 +798,7 @@ func (e *Env) Await(expectations ...Expectation) []interface{} {
 	// Debugging an unmet expectation can be tricky, so we put some effort into
 	// nicely formatting the failure.
 	if err != nil {
-		e.T.Fatalf("waiting on:\n%s\nerr:%v\nstate:\n%v", err, summary, e.state)
+		e.T.Fatalf("waiting on:\n%s\nerr:%v\n\nstate:\n%v", summary, err, e.state)
 	}
 	return metBy
 }

internal/lsp/regtest/env_test.go

@@ -16,6 +16,7 @@ func TestProgressUpdating(t *testing.T) {
 	e := &Env{
 		state: State{
 			outstandingWork: make(map[string]*workProgress),
+			completedWork:   make(map[string]int),
 		},
 	}
 	ctx := context.Background()

internal/lsp/text_synchronization.go

@@ -16,6 +16,37 @@ import (
 	errors "golang.org/x/xerrors"
 )
 
+// ModificationSource identifies the originating cause of a file modification.
+type ModificationSource int
+
+const (
+	// FromDidOpen is a file modification caused by opening a file.
+	FromDidOpen = ModificationSource(iota)
+	// FromDidChange is a file modification caused by changing a file.
+	FromDidChange
+	// FromDidChangeWatchedFiles is a file modification caused by a change to a watched file.
+	FromDidChangeWatchedFiles
+	// FromDidSave is a file modification caused by a file save.
+	FromDidSave
+	// FromDidClose is a file modification caused by closing a file.
+	FromDidClose
+)
+
+func (m ModificationSource) String() string {
+	switch m {
+	case FromDidOpen:
+		return "opened files"
+	case FromDidChange:
+		return "changed files"
+	case FromDidChangeWatchedFiles:
+		return "files changed on disk"
+	case FromDidSave:
+		return "saved files"
+	default:
+		return "unknown file modification"
+	}
+}
+
 func (s *Server) didOpen(ctx context.Context, params *protocol.DidOpenTextDocumentParams) error {
 	uri := params.TextDocument.URI.SpanURI()
 	if !uri.IsFile() {
@@ -30,7 +61,7 @@ func (s *Server) didOpen(ctx context.Context, params *protocol.DidOpenTextDocume
 			Text:       []byte(params.TextDocument.Text),
 			LanguageID: params.TextDocument.LanguageID,
 		},
-	})
+	}, FromDidOpen)
 	return err
 }
 
@@ -50,7 +81,7 @@ func (s *Server) didChange(ctx context.Context, params *protocol.DidChangeTextDo
 		Version: params.TextDocument.Version,
 		Text:    text,
 	}
-	snapshots, err := s.didModifyFiles(ctx, []source.FileModification{c})
+	snapshots, err := s.didModifyFiles(ctx, []source.FileModification{c}, FromDidChange)
 	if err != nil {
 		return err
 	}
@@ -96,7 +127,7 @@ func (s *Server) didChangeWatchedFiles(ctx context.Context, params *protocol.Did
 			delete(deletions, uri)
 		}
 	}
-	snapshots, err := s.didModifyFiles(ctx, modifications)
+	snapshots, err := s.didModifyFiles(ctx, modifications, FromDidChangeWatchedFiles)
 	if err != nil {
 		return err
 	}
@@ -129,7 +160,7 @@ func (s *Server) didSave(ctx context.Context, params *protocol.DidSaveTextDocume
 	if params.Text != nil {
 		c.Text = []byte(*params.Text)
 	}
-	_, err := s.didModifyFiles(ctx, []source.FileModification{c})
+	_, err := s.didModifyFiles(ctx, []source.FileModification{c}, FromDidSave)
 	return err
 }
 
@@ -145,7 +176,7 @@ func (s *Server) didClose(ctx context.Context, params *protocol.DidCloseTextDocu
 			Version: -1,
 			Text:    nil,
 		},
-	})
+	}, FromDidClose)
 	if err != nil {
 		return err
 	}
@@ -168,7 +199,7 @@ func (s *Server) didClose(ctx context.Context, params *protocol.DidCloseTextDocu
 	return nil
 }
 
-func (s *Server) didModifyFiles(ctx context.Context, modifications []source.FileModification) (map[span.URI]source.Snapshot, error) {
+func (s *Server) didModifyFiles(ctx context.Context, modifications []source.FileModification, cause ModificationSource) (map[span.URI]source.Snapshot, error) {
 	snapshots, err := s.session.DidModifyFiles(ctx, modifications)
 	if err != nil {
 		return nil, err
@@ -228,11 +259,23 @@ func (s *Server) didModifyFiles(ctx context.Context, modifications []source.File
 				}
 			}
 		}
-		go s.diagnoseSnapshot(snapshot)
+		go func(snapshot source.Snapshot) {
+			if s.session.Options().VerboseWorkDoneProgress {
+				work := s.StartWork(ctx, DiagnosticWorkTitle(cause), "Calculating file diagnostics...", nil)
+				defer work.End(ctx, "Done.")
+			}
+			s.diagnoseSnapshot(snapshot)
+		}(snapshot)
 	}
 	return snapshotByURI, nil
 }
 
+// DiagnosticWorkTitle returns the title of the diagnostic work resulting from a
+// file change originating from the given cause.
+func DiagnosticWorkTitle(cause ModificationSource) string {
+	return fmt.Sprintf("diagnosing %v", cause)
+}
+
 func (s *Server) wasFirstChange(uri span.URI) bool {
 	if s.changedFiles == nil {
 		s.changedFiles = make(map[span.URI]struct{})