gopls: normalize logging attributes

As part of the log audit in golang/go#66746, I noticed several
irregularities addressed by this CL:
- Move "tags" (domain-specific event keys, which are used construct
  labels) closer to the packages that use them. Specifically, the
  internal/event/tag package contained gopls-specific tags, but x/tools
  should not care about gopls.
- Use consistent values for log attributes. For example, "method" was
  being used to mean jsonrpc2 method and Go method. Also, "directory"
  was being used as both file path and URI.
- Use log attributes for the view attributes logged when views are
  created.
- Eliminate (yet another) redundant log during Load.
- Include the ViewID with snapshot.Labels, since snapshot IDs are only
  meaningful relative to a View.

With these changes, my audit of logging is complete.

Fixes golang/go#66746

Change-Id: Iaa60797a7412fb8e222e78e2e58eff2da9563bbb
Reviewed-on: https://go-review.googlesource.com/c/tools/+/579335
LUCI-TryBot-Result: Go LUCI <[email protected]>
Reviewed-by: Alan Donovan <[email protected]>

gopls/internal/cache/analysis.go

@@ -36,6 +36,7 @@ import (
 	"golang.org/x/tools/gopls/internal/cache/parsego"
 	"golang.org/x/tools/gopls/internal/file"
 	"golang.org/x/tools/gopls/internal/filecache"
+	"golang.org/x/tools/gopls/internal/label"
 	"golang.org/x/tools/gopls/internal/progress"
 	"golang.org/x/tools/gopls/internal/protocol"
 	"golang.org/x/tools/gopls/internal/settings"
@@ -44,7 +45,6 @@ import (
 	"golang.org/x/tools/gopls/internal/util/frob"
 	"golang.org/x/tools/gopls/internal/util/maps"
 	"golang.org/x/tools/internal/event"
-	"golang.org/x/tools/internal/event/tag"
 	"golang.org/x/tools/internal/facts"
 	"golang.org/x/tools/internal/gcimporter"
 	"golang.org/x/tools/internal/typesinternal"
@@ -186,7 +186,7 @@ func (s *Snapshot) Analyze(ctx context.Context, pkgs map[PackageID]*metadata.Pac
 		sort.Strings(keys)
 		tagStr = strings.Join(keys, ",")
 	}
-	ctx, done := event.Start(ctx, "snapshot.Analyze", tag.Package.Of(tagStr))
+	ctx, done := event.Start(ctx, "snapshot.Analyze", label.Package.Of(tagStr))
 	defer done()
 
 	// Filter and sort enabled root analyzers.

gopls/internal/cache/check.go

@@ -28,13 +28,13 @@ import (
 	"golang.org/x/tools/gopls/internal/cache/typerefs"
 	"golang.org/x/tools/gopls/internal/file"
 	"golang.org/x/tools/gopls/internal/filecache"
+	"golang.org/x/tools/gopls/internal/label"
 	"golang.org/x/tools/gopls/internal/protocol"
 	"golang.org/x/tools/gopls/internal/util/bug"
 	"golang.org/x/tools/gopls/internal/util/safetoken"
 	"golang.org/x/tools/gopls/internal/util/slices"
 	"golang.org/x/tools/internal/analysisinternal"
 	"golang.org/x/tools/internal/event"
-	"golang.org/x/tools/internal/event/tag"
 	"golang.org/x/tools/internal/gcimporter"
 	"golang.org/x/tools/internal/packagesinternal"
 	"golang.org/x/tools/internal/tokeninternal"
@@ -347,7 +347,7 @@ type (
 //
 // Both pre and post may be called concurrently.
 func (s *Snapshot) forEachPackage(ctx context.Context, ids []PackageID, pre preTypeCheck, post postTypeCheck) error {
-	ctx, done := event.Start(ctx, "cache.forEachPackage", tag.PackageCount.Of(len(ids)))
+	ctx, done := event.Start(ctx, "cache.forEachPackage", label.PackageCount.Of(len(ids)))
 	defer done()
 
 	if len(ids) == 0 {
@@ -612,7 +612,7 @@ func storePackageResults(ctx context.Context, ph *packageHandle, p *Package) {
 // importPackage loads the given package from its export data in p.exportData
 // (which must already be populated).
 func (b *typeCheckBatch) importPackage(ctx context.Context, mp *metadata.Package, data []byte) (*types.Package, error) {
-	ctx, done := event.Start(ctx, "cache.typeCheckBatch.importPackage", tag.Package.Of(string(mp.ID)))
+	ctx, done := event.Start(ctx, "cache.typeCheckBatch.importPackage", label.Package.Of(string(mp.ID)))
 	defer done()
 
 	impMap := b.importMap(mp.ID)
@@ -678,7 +678,7 @@ func (b *typeCheckBatch) importPackage(ctx context.Context, mp *metadata.Package
 // checkPackageForImport type checks, but skips function bodies and does not
 // record syntax information.
 func (b *typeCheckBatch) checkPackageForImport(ctx context.Context, ph *packageHandle) (*types.Package, error) {
-	ctx, done := event.Start(ctx, "cache.typeCheckBatch.checkPackageForImport", tag.Package.Of(string(ph.mp.ID)))
+	ctx, done := event.Start(ctx, "cache.typeCheckBatch.checkPackageForImport", label.Package.Of(string(ph.mp.ID)))
 	defer done()
 
 	onError := func(e error) {
@@ -1469,7 +1469,7 @@ func localPackageKey(inputs typeCheckInputs) file.Hash {
 // deps holds the future results of type-checking the direct dependencies.
 func (b *typeCheckBatch) checkPackage(ctx context.Context, ph *packageHandle) (*Package, error) {
 	inputs := ph.localInputs
-	ctx, done := event.Start(ctx, "cache.typeCheckBatch.checkPackage", tag.Package.Of(string(inputs.id)))
+	ctx, done := event.Start(ctx, "cache.typeCheckBatch.checkPackage", label.Package.Of(string(inputs.id)))
 	defer done()
 
 	pkg := &syntaxPackage{
@@ -1586,7 +1586,7 @@ func (b *typeCheckBatch) checkPackage(ctx context.Context, ph *packageHandle) (*
 	for _, e := range pkg.parseErrors {
 		diags, err := parseErrorDiagnostics(pkg, e)
 		if err != nil {
-			event.Error(ctx, "unable to compute positions for parse errors", err, tag.Package.Of(string(inputs.id)))
+			event.Error(ctx, "unable to compute positions for parse errors", err, label.Package.Of(string(inputs.id)))
 			continue
 		}
 		for _, diag := range diags {

gopls/internal/cache/fs_memoized.go

@@ -11,9 +11,9 @@ import (
 	"time"
 
 	"golang.org/x/tools/gopls/internal/file"
+	"golang.org/x/tools/gopls/internal/label"
 	"golang.org/x/tools/gopls/internal/protocol"
 	"golang.org/x/tools/internal/event"
-	"golang.org/x/tools/internal/event/tag"
 	"golang.org/x/tools/internal/robustio"
 )
 
@@ -149,7 +149,7 @@ func readFile(ctx context.Context, uri protocol.DocumentURI, mtime time.Time) (*
 	}
 	defer func() { <-ioLimit }()
 
-	ctx, done := event.Start(ctx, "cache.readFile", tag.File.Of(uri.Path()))
+	ctx, done := event.Start(ctx, "cache.readFile", label.File.Of(uri.Path()))
 	_ = ctx
 	defer done()
 

gopls/internal/cache/imports.go

@@ -11,9 +11,9 @@ import (
 	"time"
 
 	"golang.org/x/tools/gopls/internal/file"
+	"golang.org/x/tools/gopls/internal/label"
 	"golang.org/x/tools/internal/event"
 	"golang.org/x/tools/internal/event/keys"
-	"golang.org/x/tools/internal/event/tag"
 	"golang.org/x/tools/internal/imports"
 )
 
@@ -95,7 +95,7 @@ func (c *sharedModCache) refreshDir(ctx context.Context, dir string, logf func(s
 	timer, ok := c.timers[dir]
 	if !ok {
 		timer = newRefreshTimer(func() {
-			_, done := event.Start(ctx, "cache.sharedModCache.refreshDir", tag.Directory.Of(dir))
+			_, done := event.Start(ctx, "cache.sharedModCache.refreshDir", label.Directory.Of(dir))
 			defer done()
 			imports.ScanModuleCache(dir, cache, logf)
 		})

gopls/internal/cache/load.go

@@ -18,13 +18,13 @@ import (
 	"golang.org/x/tools/go/packages"
 	"golang.org/x/tools/gopls/internal/cache/metadata"
 	"golang.org/x/tools/gopls/internal/file"
+	"golang.org/x/tools/gopls/internal/label"
 	"golang.org/x/tools/gopls/internal/protocol"
 	"golang.org/x/tools/gopls/internal/util/bug"
 	"golang.org/x/tools/gopls/internal/util/immutable"
 	"golang.org/x/tools/gopls/internal/util/pathutil"
 	"golang.org/x/tools/gopls/internal/util/slices"
 	"golang.org/x/tools/internal/event"
-	"golang.org/x/tools/internal/event/tag"
 	"golang.org/x/tools/internal/gocommand"
 	"golang.org/x/tools/internal/packagesinternal"
 	"golang.org/x/tools/internal/xcontext"
@@ -113,9 +113,11 @@ func (s *Snapshot) load(ctx context.Context, allowNetwork bool, scopes ...loadSc
 	}
 	sort.Strings(query) // for determinism
 
-	ctx, done := event.Start(ctx, "cache.snapshot.load", tag.Query.Of(query))
+	ctx, done := event.Start(ctx, "cache.snapshot.load", label.Query.Of(query))
 	defer done()
 
+	startTime := time.Now()
+
 	flags := LoadWorkspace
 	if allowNetwork {
 		flags |= AllowNetwork
@@ -145,11 +147,17 @@ func (s *Snapshot) load(ctx context.Context, allowNetwork bool, scopes ...loadSc
 	}
 
 	// This log message is sought for by TestReloadOnlyOnce.
-	labels := append(s.Labels(), tag.Query.Of(query), tag.PackageCount.Of(len(pkgs)))
-	if err != nil {
-		event.Error(ctx, eventName, err, labels...)
-	} else {
-		event.Log(ctx, eventName, labels...)
+	{
+		lbls := append(s.Labels(),
+			label.Query.Of(query),
+			label.PackageCount.Of(len(pkgs)),
+			label.Duration.Of(time.Since(startTime)),
+		)
+		if err != nil {
+			event.Error(ctx, eventName, err, lbls...)
+		} else {
+			event.Log(ctx, eventName, lbls...)
+		}
 	}
 
 	if standalone {
@@ -228,8 +236,8 @@ func (s *Snapshot) load(ctx context.Context, allowNetwork bool, scopes ...loadSc
 		if s.Options().VerboseOutput {
 			event.Log(ctx, eventName, append(
 				s.Labels(),
-				tag.Package.Of(pkg.ID),
-				tag.Files.Of(pkg.CompiledGoFiles))...)
+				label.Package.Of(pkg.ID),
+				label.Files.Of(pkg.CompiledGoFiles))...)
 		}
 
 		// Ignore packages with no sources, since we will never be able to
@@ -289,7 +297,9 @@ func (s *Snapshot) load(ctx context.Context, allowNetwork bool, scopes ...loadSc
 		}
 	}
 
-	event.Log(ctx, fmt.Sprintf("%s: updating metadata for %d packages", eventName, len(updates)))
+	if s.Options().VerboseOutput {
+		event.Log(ctx, fmt.Sprintf("%s: updating metadata for %d packages", eventName, len(updates)))
+	}
 
 	meta := s.meta.Update(updates)
 	workspacePackages := computeWorkspacePackagesLocked(ctx, s, meta)
@@ -560,7 +570,7 @@ func computeLoadDiagnostics(ctx context.Context, snapshot *Snapshot, mp *metadat
 		if err != nil {
 			// There are certain cases where the go command returns invalid
 			// positions, so we cannot panic or even bug.Reportf here.
-			event.Error(ctx, "unable to compute positions for list errors", err, tag.Package.Of(string(mp.ID)))
+			event.Error(ctx, "unable to compute positions for list errors", err, label.Package.Of(string(mp.ID)))
 			continue
 		}
 		diags = append(diags, pkgDiags...)
@@ -574,7 +584,7 @@ func computeLoadDiagnostics(ctx context.Context, snapshot *Snapshot, mp *metadat
 		if ctx.Err() == nil {
 			// TODO(rfindley): consider making this a bug.Reportf. depsErrors should
 			// not normally fail.
-			event.Error(ctx, "unable to compute deps errors", err, tag.Package.Of(string(mp.ID)))
+			event.Error(ctx, "unable to compute deps errors", err, label.Package.Of(string(mp.ID)))
 		}
 	} else {
 		diags = append(diags, depsDiags...)

gopls/internal/cache/mod.go

@@ -15,10 +15,10 @@ import (
 	"golang.org/x/mod/modfile"
 	"golang.org/x/mod/module"
 	"golang.org/x/tools/gopls/internal/file"
+	"golang.org/x/tools/gopls/internal/label"
 	"golang.org/x/tools/gopls/internal/protocol"
 	"golang.org/x/tools/gopls/internal/protocol/command"
 	"golang.org/x/tools/internal/event"
-	"golang.org/x/tools/internal/event/tag"
 	"golang.org/x/tools/internal/gocommand"
 	"golang.org/x/tools/internal/memoize"
 )
@@ -70,7 +70,7 @@ func (s *Snapshot) ParseMod(ctx context.Context, fh file.Handle) (*ParsedModule,
 // parseModImpl parses the go.mod file whose name and contents are in fh.
 // It may return partial results and an error.
 func parseModImpl(ctx context.Context, fh file.Handle) (*ParsedModule, error) {
-	_, done := event.Start(ctx, "cache.ParseMod", tag.URI.Of(fh.URI()))
+	_, done := event.Start(ctx, "cache.ParseMod", label.URI.Of(fh.URI()))
 	defer done()
 
 	contents, err := fh.Content()
@@ -155,7 +155,7 @@ func (s *Snapshot) ParseWork(ctx context.Context, fh file.Handle) (*ParsedWorkFi
 
 // parseWorkImpl parses a go.work file. It may return partial results and an error.
 func parseWorkImpl(ctx context.Context, fh file.Handle) (*ParsedWorkFile, error) {
-	_, done := event.Start(ctx, "cache.ParseWork", tag.URI.Of(fh.URI()))
+	_, done := event.Start(ctx, "cache.ParseWork", label.URI.Of(fh.URI()))
 	defer done()
 
 	content, err := fh.Content()
@@ -265,7 +265,7 @@ func (s *Snapshot) ModWhy(ctx context.Context, fh file.Handle) (map[string]strin
 
 // modWhyImpl returns the result of "go mod why -m" on the specified go.mod file.
 func modWhyImpl(ctx context.Context, snapshot *Snapshot, fh file.Handle) (map[string]string, error) {
-	ctx, done := event.Start(ctx, "cache.ModWhy", tag.URI.Of(fh.URI()))
+	ctx, done := event.Start(ctx, "cache.ModWhy", label.URI.Of(fh.URI()))
 	defer done()
 
 	pm, err := snapshot.ParseMod(ctx, fh)

gopls/internal/cache/mod_tidy.go

@@ -18,11 +18,11 @@ import (
 	"golang.org/x/mod/modfile"
 	"golang.org/x/tools/gopls/internal/cache/parsego"
 	"golang.org/x/tools/gopls/internal/file"
+	"golang.org/x/tools/gopls/internal/label"
 	"golang.org/x/tools/gopls/internal/protocol"
 	"golang.org/x/tools/gopls/internal/protocol/command"
 	"golang.org/x/tools/internal/diff"
 	"golang.org/x/tools/internal/event"
-	"golang.org/x/tools/internal/event/tag"
 	"golang.org/x/tools/internal/gocommand"
 	"golang.org/x/tools/internal/memoize"
 )
@@ -99,7 +99,7 @@ func (s *Snapshot) ModTidy(ctx context.Context, pm *ParsedModule) (*TidiedModule
 
 // modTidyImpl runs "go mod tidy" on a go.mod file.
 func modTidyImpl(ctx context.Context, snapshot *Snapshot, filename string, pm *ParsedModule) (*TidiedModule, error) {
-	ctx, done := event.Start(ctx, "cache.ModTidy", tag.URI.Of(filename))
+	ctx, done := event.Start(ctx, "cache.ModTidy", label.File.Of(filename))
 	defer done()
 
 	inv := &gocommand.Invocation{

gopls/internal/cache/parsego/parse.go

@@ -14,12 +14,12 @@ import (
 	"go/token"
 	"reflect"
 
+	"golang.org/x/tools/gopls/internal/label"
 	"golang.org/x/tools/gopls/internal/protocol"
 	"golang.org/x/tools/gopls/internal/util/astutil"
 	"golang.org/x/tools/gopls/internal/util/safetoken"
 	"golang.org/x/tools/internal/diff"
 	"golang.org/x/tools/internal/event"
-	"golang.org/x/tools/internal/event/tag"
 )
 
 // Common parse modes; these should be reused wherever possible to increase
@@ -42,7 +42,7 @@ func Parse(ctx context.Context, fset *token.FileSet, uri protocol.DocumentURI, s
 	if purgeFuncBodies {
 		src = astutil.PurgeFuncBodies(src)
 	}
-	ctx, done := event.Start(ctx, "cache.ParseGoSrc", tag.File.Of(uri.Path()))
+	ctx, done := event.Start(ctx, "cache.ParseGoSrc", label.File.Of(uri.Path()))
 	defer done()
 
 	file, err := parser.ParseFile(fset, uri.Path(), src, mode)
@@ -84,7 +84,7 @@ func Parse(ctx context.Context, fset *token.FileSet, uri protocol.DocumentURI, s
 			// of the last changes we made to aid in debugging.
 			if i == 9 {
 				unified := diff.Unified("before", "after", string(src), string(newSrc))
-				event.Log(ctx, fmt.Sprintf("fixSrc loop - last diff:\n%v", unified), tag.File.Of(tok.Name()))
+				event.Log(ctx, fmt.Sprintf("fixSrc loop - last diff:\n%v", unified), label.File.Of(tok.Name()))
 			}
 
 			newFile, newErr := parser.ParseFile(fset, uri.Path(), newSrc, mode)

gopls/internal/cache/session.go

@@ -20,12 +20,14 @@ import (
 	"golang.org/x/tools/gopls/internal/cache/metadata"
 	"golang.org/x/tools/gopls/internal/cache/typerefs"
 	"golang.org/x/tools/gopls/internal/file"
+	"golang.org/x/tools/gopls/internal/label"
 	"golang.org/x/tools/gopls/internal/protocol"
 	"golang.org/x/tools/gopls/internal/util/bug"
 	"golang.org/x/tools/gopls/internal/util/persistent"
 	"golang.org/x/tools/gopls/internal/util/slices"
 	"golang.org/x/tools/gopls/internal/vulncheck"
 	"golang.org/x/tools/internal/event"
+	"golang.org/x/tools/internal/event/keys"
 	"golang.org/x/tools/internal/gocommand"
 	"golang.org/x/tools/internal/imports"
 	"golang.org/x/tools/internal/memoize"
@@ -263,7 +265,15 @@ func (s *Session) createView(ctx context.Context, def *viewDefinition) (*View, *
 	}
 
 	// Record the environment of the newly created view in the log.
-	event.Log(ctx, viewEnv(v))
+	event.Log(ctx, fmt.Sprintf("Created View (#%s)", v.id),
+		label.Directory.Of(v.folder.Dir.Path()),
+		viewTypeKey.Of(v.typ.String()),
+		rootDirKey.Of(string(v.root)),
+		goVersionKey.Of(strings.TrimRight(v.folder.Env.GoVersionOutput, "\n")),
+		buildFlagsKey.Of(fmt.Sprint(v.folder.Options.BuildFlags)),
+		envKey.Of(fmt.Sprintf("%+v", v.folder.Env)),
+		envOverlayKey.Of(v.EnvOverlay()),
+	)
 
 	// Initialize the view without blocking.
 	initCtx, initCancel := context.WithCancel(xcontext.Detach(ctx))
@@ -281,6 +291,16 @@ func (s *Session) createView(ctx context.Context, def *viewDefinition) (*View, *
 	return v, snapshot, snapshot.Acquire()
 }
 
+// These keys are used to log view metadata in createView.
+var (
+	viewTypeKey   = keys.NewString("view_type", "")
+	rootDirKey    = keys.NewString("root_dir", "")
+	goVersionKey  = keys.NewString("go_version", "")
+	buildFlagsKey = keys.New("build_flags", "")
+	envKey        = keys.New("env", "")
+	envOverlayKey = keys.New("env_overlay", "")
+)
+
 // RemoveView removes from the session the view rooted at the specified directory.
 // It reports whether a view of that directory was removed.
 func (s *Session) RemoveView(dir protocol.DocumentURI) bool {

gopls/internal/cache/snapshot.go

@@ -35,6 +35,7 @@ import (
 	"golang.org/x/tools/gopls/internal/cache/xrefs"
 	"golang.org/x/tools/gopls/internal/file"
 	"golang.org/x/tools/gopls/internal/filecache"
+	label1 "golang.org/x/tools/gopls/internal/label"
 	"golang.org/x/tools/gopls/internal/protocol"
 	"golang.org/x/tools/gopls/internal/protocol/command"
 	"golang.org/x/tools/gopls/internal/settings"
@@ -47,7 +48,6 @@ import (
 	"golang.org/x/tools/gopls/internal/vulncheck"
 	"golang.org/x/tools/internal/event"
 	"golang.org/x/tools/internal/event/label"
-	"golang.org/x/tools/internal/event/tag"
 	"golang.org/x/tools/internal/gocommand"
 	"golang.org/x/tools/internal/memoize"
 	"golang.org/x/tools/internal/packagesinternal"
@@ -269,7 +269,11 @@ func (s *Snapshot) SequenceID() uint64 {
 // SnapshotLabels returns a new slice of labels that should be used for events
 // related to a snapshot.
 func (s *Snapshot) Labels() []label.Label {
-	return []label.Label{tag.Snapshot.Of(s.SequenceID()), tag.Directory.Of(s.Folder())}
+	return []label.Label{
+		label1.ViewID.Of(s.view.id),
+		label1.Snapshot.Of(s.SequenceID()),
+		label1.Directory.Of(s.Folder().Path()),
+	}
 }
 
 // Folder returns the folder at the base of this snapshot.