gopls/internal/cache: fix module resolver cache refreshing

findleyr · gopherbot · commit 8bf61b85c2e3 · 2024-06-05T19:29:32.000Z
An apparent bad merge in CL 561235 caused the critical component-- clearing the resolver for a new scan--to be dropped. Fix this, so that the imports state is actually refreshed asynchronously. It is surprising that this was not reported, though I see perhaps two related comments in survey results. Most likely adding a new import is infrequent enough that users were simply confused, or learned to restart gopls (alas). Also, add more instrumentation that would help debug golang/go#67289. For golang/go#67289 Change-Id: I50d70a470eb393caf9e0b41856997942372b216f Reviewed-on: https://go-review.googlesource.com/c/tools/+/590377 Auto-Submit: Robert Findley <rfindley@google.com> Reviewed-by: Alan Donovan <adonovan@google.com> LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
diff --git a/gopls/internal/cache/imports.go b/gopls/internal/cache/imports.go
@@ -119,15 +119,15 @@ type importsState struct {
 // newImportsState constructs a new imports state for running goimports
 // functions via [runProcessEnvFunc].
 //
-// The returned state will automatically refresh itself following a call to
-// runProcessEnvFunc.
+// The returned state will automatically refresh itself following a delay.
 func newImportsState(backgroundCtx context.Context, modCache *sharedModCache, env *imports.ProcessEnv) *importsState {
 	s := &importsState{
 		ctx:        backgroundCtx,
 		modCache:   modCache,
 		processEnv: env,
 	}
 	s.refreshTimer = newRefreshTimer(s.refreshProcessEnv)
+	s.refreshTimer.schedule()
 	return s
 }
 
@@ -210,20 +210,22 @@ func (s *importsState) refreshProcessEnv() {
 	resolver, err := s.processEnv.GetResolver()
 	s.mu.Unlock()
 	if err != nil {
+		event.Error(s.ctx, "failed to get import resolver", err)
 		return
 	}
 
 	event.Log(s.ctx, "background imports cache refresh starting")
+	resolver2 := resolver.ClearForNewScan()
 
 	// Prime the new resolver before updating the processEnv, so that gopls
 	// doesn't wait on an unprimed cache.
-	if err := imports.PrimeCache(context.Background(), resolver); err == nil {
+	if err := imports.PrimeCache(context.Background(), resolver2); err == nil {
 		event.Log(ctx, fmt.Sprintf("background refresh finished after %v", time.Since(start)))
 	} else {
 		event.Log(ctx, fmt.Sprintf("background refresh finished after %v", time.Since(start)), keys.Err.Of(err))
 	}
 
 	s.mu.Lock()
-	s.processEnv.UpdateResolver(resolver)
+	s.processEnv.UpdateResolver(resolver2)
 	s.mu.Unlock()
 }
diff --git a/internal/gocommand/invoke.go b/internal/gocommand/invoke.go
@@ -200,12 +200,14 @@ func (i *Invocation) runWithFriendlyError(ctx context.Context, stdout, stderr io
 	return
 }
 
-func (i *Invocation) run(ctx context.Context, stdout, stderr io.Writer) error {
-	log := i.Logf
-	if log == nil {
-		log = func(string, ...interface{}) {}
+// logf logs if i.Logf is non-nil.
+func (i *Invocation) logf(format string, args ...any) {
+	if i.Logf != nil {
+		i.Logf(format, args...)
 	}
+}
 
+func (i *Invocation) run(ctx context.Context, stdout, stderr io.Writer) error {
 	goArgs := []string{i.Verb}
 
 	appendModFile := func() {
@@ -277,7 +279,12 @@ func (i *Invocation) run(ctx context.Context, stdout, stderr io.Writer) error {
 		cmd.Dir = i.WorkingDir
 	}
 
-	defer func(start time.Time) { log("%s for %v", time.Since(start), cmdDebugStr(cmd)) }(time.Now())
+	debugStr := cmdDebugStr(cmd)
+	i.logf("starting %v", debugStr)
+	start := time.Now()
+	defer func() {
+		i.logf("%s for %v", time.Since(start), debugStr)
+	}()
 
 	return runCmdContext(ctx, cmd)
 }
diff --git a/internal/imports/fix.go b/internal/imports/fix.go
@@ -365,9 +365,7 @@ func (p *pass) load() ([]*ImportFix, bool) {
 	if p.loadRealPackageNames {
 		err := p.loadPackageNames(append(imports, p.candidates...))
 		if err != nil {
-			if p.env.Logf != nil {
-				p.env.Logf("loading package names: %v", err)
-			}
+			p.env.logf("loading package names: %v", err)
 			return nil, false
 		}
 	}
@@ -580,9 +578,7 @@ func getFixes(ctx context.Context, fset *token.FileSet, f *ast.File, filename st
 		return nil, err
 	}
 	srcDir := filepath.Dir(abs)
-	if env.Logf != nil {
-		env.Logf("fixImports(filename=%q), abs=%q, srcDir=%q ...", filename, abs, srcDir)
-	}
+	env.logf("fixImports(filename=%q), abs=%q, srcDir=%q ...", filename, abs, srcDir)
 
 	// First pass: looking only at f, and using the naive algorithm to
 	// derive package names from import paths, see if the file is already
@@ -1014,16 +1010,26 @@ func (e *ProcessEnv) GetResolver() (Resolver, error) {
 		// already know the view type.
 		if len(e.Env["GOMOD"]) == 0 && len(e.Env["GOWORK"]) == 0 {
 			e.resolver = newGopathResolver(e)
+			e.logf("created gopath resolver")
 		} else if r, err := newModuleResolver(e, e.ModCache); err != nil {
 			e.resolverErr = err
+			e.logf("failed to create module resolver: %v", err)
 		} else {
 			e.resolver = Resolver(r)
+			e.logf("created module resolver")
 		}
 	}
 
 	return e.resolver, e.resolverErr
 }
 
+// logf logs if e.Logf is non-nil.
+func (e *ProcessEnv) logf(format string, args ...any) {
+	if e.Logf != nil {
+		e.Logf(format, args...)
+	}
+}
+
 // buildContext returns the build.Context to use for matching files.
 //
 // TODO(rfindley): support dynamic GOOS, GOARCH here, when doing cross-platform
@@ -1610,9 +1616,7 @@ func loadExportsFromFiles(ctx context.Context, env *ProcessEnv, dir string, incl
 		fullFile := filepath.Join(dir, fi.Name())
 		f, err := parser.ParseFile(fset, fullFile, nil, 0)
 		if err != nil {
-			if env.Logf != nil {
-				env.Logf("error parsing %v: %v", fullFile, err)
-			}
+			env.logf("error parsing %v: %v", fullFile, err)
 			continue
 		}
 		if f.Name.Name == "documentation" {
@@ -1648,9 +1652,7 @@ func loadExportsFromFiles(ctx context.Context, env *ProcessEnv, dir string, incl
 	}
 	sortSymbols(exports)
 
-	if env.Logf != nil {
-		env.Logf("loaded exports in dir %v (package %v): %v", dir, pkgName, exports)
-	}
+	env.logf("loaded exports in dir %v (package %v): %v", dir, pkgName, exports)
 	return pkgName, exports, nil
 }
 
@@ -1710,16 +1712,12 @@ func findImport(ctx context.Context, pass *pass, candidates []pkgDistance, pkgNa
 					wg.Done()
 				}()
 
-				if pass.env.Logf != nil {
-					pass.env.Logf("loading exports in dir %s (seeking package %s)", c.pkg.dir, pkgName)
-				}
+				pass.env.logf("loading exports in dir %s (seeking package %s)", c.pkg.dir, pkgName)
 				// If we're an x_test, load the package under test's test variant.
 				includeTest := strings.HasSuffix(pass.f.Name.Name, "_test") && c.pkg.dir == pass.srcDir
 				_, exports, err := resolver.loadExports(ctx, c.pkg, includeTest)
 				if err != nil {
-					if pass.env.Logf != nil {
-						pass.env.Logf("loading exports in dir %s (seeking package %s): %v", c.pkg.dir, pkgName, err)
-					}
+					pass.env.logf("loading exports in dir %s (seeking package %s): %v", c.pkg.dir, pkgName, err)
 					resc <- nil
 					return
 				}
diff --git a/internal/imports/mod.go b/internal/imports/mod.go
@@ -265,9 +265,7 @@ func (r *ModuleResolver) initAllMods() error {
 			return err
 		}
 		if mod.Dir == "" {
-			if r.env.Logf != nil {
-				r.env.Logf("module %v has not been downloaded and will be ignored", mod.Path)
-			}
+			r.env.logf("module %v has not been downloaded and will be ignored", mod.Path)
 			// Can't do anything with a module that's not downloaded.
 			continue
 		}
@@ -766,9 +764,7 @@ func (r *ModuleResolver) scanDirForPackage(root gopathwalk.Root, dir string) dir
 		}
 		modPath, err := module.UnescapePath(filepath.ToSlash(matches[1]))
 		if err != nil {
-			if r.env.Logf != nil {
-				r.env.Logf("decoding module cache path %q: %v", subdir, err)
-			}
+			r.env.logf("decoding module cache path %q: %v", subdir, err)
 			return directoryPackageInfo{
 				status: directoryScanned,
 				err:    fmt.Errorf("decoding module cache path %q: %v", subdir, err),
