gopls: fix tests that depend on log sequencing

As noted recently in gopls/internal/lsp/protocol/context.go, log
messages are delivered asynchronously to other LSP events. This means
that any test relying on sequencing of log messages with respect to
other operations is fundamentally incorrect.

Searching for such tests turned up several known flakes.

Fixes golang/go#61521
Fixes golang/go#51549
Fixes golang/go#51772

Change-Id: I4cb5031140e34e1c816b221a90d5ffa4055ad76c
Reviewed-on: https://go-review.googlesource.com/c/tools/+/513097
Run-TryBot: Robert Findley <[email protected]>
Reviewed-by: Alan Donovan <[email protected]>
gopls-CI: kokoro <[email protected]>
TryBot-Result: Gopher Robot <[email protected]>

Author: findleyr

gopls/internal/lsp/regtest/expectation.go

@@ -212,20 +212,6 @@ func ReadAllDiagnostics(into *map[string]*protocol.PublishDiagnosticsParams) Exp
 	}
 }
 
-// ReadLogs is an expectation that may be used with AfterChange or OnceMet
-// conditions to copy logs into the provided slice.
-func ReadLogs(into *[]*protocol.LogMessageParams) Expectation {
-	check := func(s State) Verdict {
-		*into = make([]*protocol.LogMessageParams, len(s.logs))
-		copy(*into, s.logs)
-		return Met
-	}
-	return Expectation{
-		Check:       check,
-		Description: "read logs",
-	}
-}
-
 // NoOutstandingWork asserts that there is no work initiated using the LSP
 // $/progress API that has not completed.
 func NoOutstandingWork() Expectation {
@@ -521,6 +507,10 @@ func NoErrorLogs() Expectation {
 // The count argument specifies the expected number of matching logs. If
 // atLeast is set, this is a lower bound, otherwise there must be exactly count
 // matching logs.
+//
+// Logs are asynchronous to other LSP messages, so this expectation should not
+// be used with combinators such as OnceMet or AfterChange that assert on
+// ordering with respect to other operations.
 func LogMatching(typ protocol.MessageType, re string, count int, atLeast bool) Expectation {
 	rec, err := regexp.Compile(re)
 	if err != nil {
@@ -537,6 +527,11 @@ func LogMatching(typ protocol.MessageType, re string, count int, atLeast bool) E
 		if found == count || (found >= count && atLeast) {
 			return Met
 		}
+		// If we require an exact count, and have received more than expected, the
+		// expectation can never be met.
+		if found > count && !atLeast {
+			return Unmeetable
+		}
 		return Unmet
 	}
 	desc := fmt.Sprintf("log message matching %q expected %v times", re, count)

gopls/internal/regtest/diagnostics/diagnostics_test.go

@@ -8,7 +8,6 @@ import (
 	"context"
 	"fmt"
 	"os/exec"
-	"strings"
 	"testing"
 
 	"golang.org/x/tools/gopls/internal/bug"
@@ -433,7 +432,11 @@ func TestResolveDiagnosticWithDownload(t *testing.T) {
 func TestMissingDependency(t *testing.T) {
 	Run(t, testPackageWithRequire, func(t *testing.T, env *Env) {
 		env.OpenFile("print.go")
-		env.Await(LogMatching(protocol.Error, "initial workspace load failed", 1, false))
+		env.Await(
+			// Log messages are asynchronous to other events on the LSP stream, so we
+			// can't use OnceMet or AfterChange here.
+			LogMatching(protocol.Error, "initial workspace load failed", 1, false),
+		)
 	})
 }
 
@@ -1303,42 +1306,18 @@ func _() {
 		)
 		env.OpenFile("a/a_exclude.go")
 
-		countLoads := func(logs []*protocol.LogMessageParams) int {
-			count := 0
-			for _, log := range logs {
-				if strings.Contains(log.Message, `go/packages.Load`) {
-					count++
-				}
-			}
-			return count
-		}
-
-		var before []*protocol.LogMessageParams
-		env.AfterChange(
-			Diagnostics(env.AtRegexp("a/a_exclude.go", "package (a)")),
-			ReadLogs(&before),
-		)
+		loadOnce := LogMatching(protocol.Info, "query=.*file=.*a_exclude.go", 1, false)
+		env.Await(loadOnce) // can't use OnceMet or AfterChange as logs are async
 
 		// Check that orphaned files are not reloaded, by making a change in
 		// a.go file and confirming that the workspace diagnosis did not reload
 		// a_exclude.go.
 		//
-		// Currently, typing in a_exclude.go does result in a reload, because we
-		// aren't precise about which changes could result in an unloadable file
-		// becoming loadable.
-		loads0 := countLoads(before)
-		if loads0 == 0 {
-			t.Fatal("got 0 Load log messages, want at least 1", loads0)
-		}
+		// This is racy (but fails open) because logs are asynchronous to other LSP
+		// operations. There's a chance gopls _did_ log, and we just haven't seen
+		// it yet.
 		env.RegexpReplace("a/a.go", "package a", "package a // arbitrary comment")
-		var after []*protocol.LogMessageParams
-		env.AfterChange(
-			Diagnostics(env.AtRegexp("a/a_exclude.go", "package (a)")),
-			ReadLogs(&after),
-		)
-		if loads := countLoads(after); loads != loads0 {
-			t.Errorf("got %d Load log messages after change to orphaned file, want %d", loads, loads0)
-		}
+		env.AfterChange(loadOnce)
 	})
 }
 
@@ -1853,8 +1832,10 @@ func main() {}
 `
 	Run(t, files, func(t *testing.T, env *Env) {
 		env.OpenFile("go.mod")
-		env.AfterChange(
+		env.Await(
 			// Check that we have only loaded "<dir>/..." once.
+			// Log messages are asynchronous to other events on the LSP stream, so we
+			// can't use OnceMet or AfterChange here.
 			LogMatching(protocol.Info, `.*query=.*\.\.\..*`, 1, false),
 		)
 	})

gopls/internal/regtest/watch/watch_test.go

@@ -383,7 +383,9 @@ package a
 		).Run(t, pkg, func(t *testing.T, env *Env) {
 			env.OpenFile("a/a.go")
 			env.OpenFile("a/a_unneeded.go")
-			env.AfterChange(
+			env.Await(
+				// Log messages are asynchronous to other events on the LSP stream, so we
+				// can't use OnceMet or AfterChange here.
 				LogMatching(protocol.Info, "a_unneeded.go", 1, false),
 			)
 
@@ -395,7 +397,7 @@ package a
 				Diagnostics(env.AtRegexp("a/a.go", "fmt")),
 			)
 			env.SaveBuffer("a/a.go")
-			env.AfterChange(
+			env.Await(
 				// There should only be one log message containing
 				// a_unneeded.go, from the initial workspace load, which we
 				// check for earlier. If there are more, there's a bug.
@@ -411,7 +413,7 @@ package a
 		).Run(t, pkg, func(t *testing.T, env *Env) {
 			env.OpenFile("a/a.go")
 			env.OpenFile("a/a_unneeded.go")
-			env.AfterChange(
+			env.Await(
 				LogMatching(protocol.Info, "a_unneeded.go", 1, false),
 			)
 
@@ -423,7 +425,7 @@ package a
 				Diagnostics(env.AtRegexp("a/a.go", "fmt")),
 			)
 			env.SaveBuffer("a/a.go")
-			env.AfterChange(
+			env.Await(
 				// There should only be one log message containing
 				// a_unneeded.go, from the initial workspace load, which we
 				// check for earlier. If there are more, there's a bug.

gopls/internal/regtest/workspace/workspace_test.go

@@ -177,7 +177,7 @@ func TestReloadOnlyOnce(t *testing.T) {
 replace random.org => %s
 `, env.ReadWorkspaceFile("pkg/go.mod"), dir)
 		env.WriteWorkspaceFile("pkg/go.mod", goModWithReplace)
-		env.AfterChange(
+		env.Await(
 			LogMatching(protocol.Info, `packages\.Load #\d+\n`, 2, false),
 		)
 	})