Skip to content

Commit 3c49bb7

Browse files
findleyrfindleyr
committed
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]>
1 parent 2fa621c commit 3c49bb7

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

44 files changed

+267
-259
lines changed

‎gopls/internal/cache/analysis.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@ import (
3636
"golang.org/x/tools/gopls/internal/cache/parsego"
3737
"golang.org/x/tools/gopls/internal/file"
3838
"golang.org/x/tools/gopls/internal/filecache"
39+
"golang.org/x/tools/gopls/internal/label"
3940
"golang.org/x/tools/gopls/internal/progress"
4041
"golang.org/x/tools/gopls/internal/protocol"
4142
"golang.org/x/tools/gopls/internal/settings"
@@ -44,7 +45,6 @@ import (
4445
"golang.org/x/tools/gopls/internal/util/frob"
4546
"golang.org/x/tools/gopls/internal/util/maps"
4647
"golang.org/x/tools/internal/event"
47-
"golang.org/x/tools/internal/event/tag"
4848
"golang.org/x/tools/internal/facts"
4949
"golang.org/x/tools/internal/gcimporter"
5050
"golang.org/x/tools/internal/typesinternal"
@@ -186,7 +186,7 @@ func (s *Snapshot) Analyze(ctx context.Context, pkgs map[PackageID]*metadata.Pac
186186
sort.Strings(keys)
187187
tagStr = strings.Join(keys, ",")
188188
}
189-
ctx, done := event.Start(ctx, "snapshot.Analyze", tag.Package.Of(tagStr))
189+
ctx, done := event.Start(ctx, "snapshot.Analyze", label.Package.Of(tagStr))
190190
defer done()
191191

192192
// Filter and sort enabled root analyzers.

‎gopls/internal/cache/check.go

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -28,13 +28,13 @@ import (
2828
"golang.org/x/tools/gopls/internal/cache/typerefs"
2929
"golang.org/x/tools/gopls/internal/file"
3030
"golang.org/x/tools/gopls/internal/filecache"
31+
"golang.org/x/tools/gopls/internal/label"
3132
"golang.org/x/tools/gopls/internal/protocol"
3233
"golang.org/x/tools/gopls/internal/util/bug"
3334
"golang.org/x/tools/gopls/internal/util/safetoken"
3435
"golang.org/x/tools/gopls/internal/util/slices"
3536
"golang.org/x/tools/internal/analysisinternal"
3637
"golang.org/x/tools/internal/event"
37-
"golang.org/x/tools/internal/event/tag"
3838
"golang.org/x/tools/internal/gcimporter"
3939
"golang.org/x/tools/internal/packagesinternal"
4040
"golang.org/x/tools/internal/tokeninternal"
@@ -347,7 +347,7 @@ type (
347347
//
348348
// Both pre and post may be called concurrently.
349349
func (s *Snapshot) forEachPackage(ctx context.Context, ids []PackageID, pre preTypeCheck, post postTypeCheck) error {
350-
ctx, done := event.Start(ctx, "cache.forEachPackage", tag.PackageCount.Of(len(ids)))
350+
ctx, done := event.Start(ctx, "cache.forEachPackage", label.PackageCount.Of(len(ids)))
351351
defer done()
352352

353353
if len(ids) == 0 {
@@ -612,7 +612,7 @@ func storePackageResults(ctx context.Context, ph *packageHandle, p *Package) {
612612
// importPackage loads the given package from its export data in p.exportData
613613
// (which must already be populated).
614614
func (b *typeCheckBatch) importPackage(ctx context.Context, mp *metadata.Package, data []byte) (*types.Package, error) {
615-
ctx, done := event.Start(ctx, "cache.typeCheckBatch.importPackage", tag.Package.Of(string(mp.ID)))
615+
ctx, done := event.Start(ctx, "cache.typeCheckBatch.importPackage", label.Package.Of(string(mp.ID)))
616616
defer done()
617617

618618
impMap := b.importMap(mp.ID)
@@ -678,7 +678,7 @@ func (b *typeCheckBatch) importPackage(ctx context.Context, mp *metadata.Package
678678
// checkPackageForImport type checks, but skips function bodies and does not
679679
// record syntax information.
680680
func (b *typeCheckBatch) checkPackageForImport(ctx context.Context, ph *packageHandle) (*types.Package, error) {
681-
ctx, done := event.Start(ctx, "cache.typeCheckBatch.checkPackageForImport", tag.Package.Of(string(ph.mp.ID)))
681+
ctx, done := event.Start(ctx, "cache.typeCheckBatch.checkPackageForImport", label.Package.Of(string(ph.mp.ID)))
682682
defer done()
683683

684684
onError := func(e error) {
@@ -1469,7 +1469,7 @@ func localPackageKey(inputs typeCheckInputs) file.Hash {
14691469
// deps holds the future results of type-checking the direct dependencies.
14701470
func (b *typeCheckBatch) checkPackage(ctx context.Context, ph *packageHandle) (*Package, error) {
14711471
inputs := ph.localInputs
1472-
ctx, done := event.Start(ctx, "cache.typeCheckBatch.checkPackage", tag.Package.Of(string(inputs.id)))
1472+
ctx, done := event.Start(ctx, "cache.typeCheckBatch.checkPackage", label.Package.Of(string(inputs.id)))
14731473
defer done()
14741474

14751475
pkg := &syntaxPackage{
@@ -1586,7 +1586,7 @@ func (b *typeCheckBatch) checkPackage(ctx context.Context, ph *packageHandle) (*
15861586
for _, e := range pkg.parseErrors {
15871587
diags, err := parseErrorDiagnostics(pkg, e)
15881588
if err != nil {
1589-
event.Error(ctx, "unable to compute positions for parse errors", err, tag.Package.Of(string(inputs.id)))
1589+
event.Error(ctx, "unable to compute positions for parse errors", err, label.Package.Of(string(inputs.id)))
15901590
continue
15911591
}
15921592
for _, diag := range diags {

‎gopls/internal/cache/fs_memoized.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -11,9 +11,9 @@ import (
1111
"time"
1212

1313
"golang.org/x/tools/gopls/internal/file"
14+
"golang.org/x/tools/gopls/internal/label"
1415
"golang.org/x/tools/gopls/internal/protocol"
1516
"golang.org/x/tools/internal/event"
16-
"golang.org/x/tools/internal/event/tag"
1717
"golang.org/x/tools/internal/robustio"
1818
)
1919

@@ -149,7 +149,7 @@ func readFile(ctx context.Context, uri protocol.DocumentURI, mtime time.Time) (*
149149
}
150150
defer func() { <-ioLimit }()
151151

152-
ctx, done := event.Start(ctx, "cache.readFile", tag.File.Of(uri.Path()))
152+
ctx, done := event.Start(ctx, "cache.readFile", label.File.Of(uri.Path()))
153153
_ = ctx
154154
defer done()
155155

‎gopls/internal/cache/imports.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -11,9 +11,9 @@ import (
1111
"time"
1212

1313
"golang.org/x/tools/gopls/internal/file"
14+
"golang.org/x/tools/gopls/internal/label"
1415
"golang.org/x/tools/internal/event"
1516
"golang.org/x/tools/internal/event/keys"
16-
"golang.org/x/tools/internal/event/tag"
1717
"golang.org/x/tools/internal/imports"
1818
)
1919

@@ -95,7 +95,7 @@ func (c *sharedModCache) refreshDir(ctx context.Context, dir string, logf func(s
9595
timer, ok := c.timers[dir]
9696
if !ok {
9797
timer = newRefreshTimer(func() {
98-
_, done := event.Start(ctx, "cache.sharedModCache.refreshDir", tag.Directory.Of(dir))
98+
_, done := event.Start(ctx, "cache.sharedModCache.refreshDir", label.Directory.Of(dir))
9999
defer done()
100100
imports.ScanModuleCache(dir, cache, logf)
101101
})

‎gopls/internal/cache/load.go

Lines changed: 22 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -18,13 +18,13 @@ import (
1818
"golang.org/x/tools/go/packages"
1919
"golang.org/x/tools/gopls/internal/cache/metadata"
2020
"golang.org/x/tools/gopls/internal/file"
21+
"golang.org/x/tools/gopls/internal/label"
2122
"golang.org/x/tools/gopls/internal/protocol"
2223
"golang.org/x/tools/gopls/internal/util/bug"
2324
"golang.org/x/tools/gopls/internal/util/immutable"
2425
"golang.org/x/tools/gopls/internal/util/pathutil"
2526
"golang.org/x/tools/gopls/internal/util/slices"
2627
"golang.org/x/tools/internal/event"
27-
"golang.org/x/tools/internal/event/tag"
2828
"golang.org/x/tools/internal/gocommand"
2929
"golang.org/x/tools/internal/packagesinternal"
3030
"golang.org/x/tools/internal/xcontext"
@@ -113,9 +113,11 @@ func (s *Snapshot) load(ctx context.Context, allowNetwork bool, scopes ...loadSc
113113
}
114114
sort.Strings(query) // for determinism
115115

116-
ctx, done := event.Start(ctx, "cache.snapshot.load", tag.Query.Of(query))
116+
ctx, done := event.Start(ctx, "cache.snapshot.load", label.Query.Of(query))
117117
defer done()
118118

119+
startTime := time.Now()
120+
119121
flags := LoadWorkspace
120122
if allowNetwork {
121123
flags |= AllowNetwork
@@ -145,11 +147,17 @@ func (s *Snapshot) load(ctx context.Context, allowNetwork bool, scopes ...loadSc
145147
}
146148

147149
// This log message is sought for by TestReloadOnlyOnce.
148-
labels := append(s.Labels(), tag.Query.Of(query), tag.PackageCount.Of(len(pkgs)))
149-
if err != nil {
150-
event.Error(ctx, eventName, err, labels...)
151-
} else {
152-
event.Log(ctx, eventName, labels...)
150+
{
151+
lbls := append(s.Labels(),
152+
label.Query.Of(query),
153+
label.PackageCount.Of(len(pkgs)),
154+
label.Duration.Of(time.Since(startTime)),
155+
)
156+
if err != nil {
157+
event.Error(ctx, eventName, err, lbls...)
158+
} else {
159+
event.Log(ctx, eventName, lbls...)
160+
}
153161
}
154162

155163
if standalone {
@@ -228,8 +236,8 @@ func (s *Snapshot) load(ctx context.Context, allowNetwork bool, scopes ...loadSc
228236
if s.Options().VerboseOutput {
229237
event.Log(ctx, eventName, append(
230238
s.Labels(),
231-
tag.Package.Of(pkg.ID),
232-
tag.Files.Of(pkg.CompiledGoFiles))...)
239+
label.Package.Of(pkg.ID),
240+
label.Files.Of(pkg.CompiledGoFiles))...)
233241
}
234242

235243
// 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
289297
}
290298
}
291299

292-
event.Log(ctx, fmt.Sprintf("%s: updating metadata for %d packages", eventName, len(updates)))
300+
if s.Options().VerboseOutput {
301+
event.Log(ctx, fmt.Sprintf("%s: updating metadata for %d packages", eventName, len(updates)))
302+
}
293303

294304
meta := s.meta.Update(updates)
295305
workspacePackages := computeWorkspacePackagesLocked(ctx, s, meta)
@@ -560,7 +570,7 @@ func computeLoadDiagnostics(ctx context.Context, snapshot *Snapshot, mp *metadat
560570
if err != nil {
561571
// There are certain cases where the go command returns invalid
562572
// positions, so we cannot panic or even bug.Reportf here.
563-
event.Error(ctx, "unable to compute positions for list errors", err, tag.Package.Of(string(mp.ID)))
573+
event.Error(ctx, "unable to compute positions for list errors", err, label.Package.Of(string(mp.ID)))
564574
continue
565575
}
566576
diags = append(diags, pkgDiags...)
@@ -574,7 +584,7 @@ func computeLoadDiagnostics(ctx context.Context, snapshot *Snapshot, mp *metadat
574584
if ctx.Err() == nil {
575585
// TODO(rfindley): consider making this a bug.Reportf. depsErrors should
576586
// not normally fail.
577-
event.Error(ctx, "unable to compute deps errors", err, tag.Package.Of(string(mp.ID)))
587+
event.Error(ctx, "unable to compute deps errors", err, label.Package.Of(string(mp.ID)))
578588
}
579589
} else {
580590
diags = append(diags, depsDiags...)

‎gopls/internal/cache/mod.go

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -15,10 +15,10 @@ import (
1515
"golang.org/x/mod/modfile"
1616
"golang.org/x/mod/module"
1717
"golang.org/x/tools/gopls/internal/file"
18+
"golang.org/x/tools/gopls/internal/label"
1819
"golang.org/x/tools/gopls/internal/protocol"
1920
"golang.org/x/tools/gopls/internal/protocol/command"
2021
"golang.org/x/tools/internal/event"
21-
"golang.org/x/tools/internal/event/tag"
2222
"golang.org/x/tools/internal/gocommand"
2323
"golang.org/x/tools/internal/memoize"
2424
)
@@ -70,7 +70,7 @@ func (s *Snapshot) ParseMod(ctx context.Context, fh file.Handle) (*ParsedModule,
7070
// parseModImpl parses the go.mod file whose name and contents are in fh.
7171
// It may return partial results and an error.
7272
func parseModImpl(ctx context.Context, fh file.Handle) (*ParsedModule, error) {
73-
_, done := event.Start(ctx, "cache.ParseMod", tag.URI.Of(fh.URI()))
73+
_, done := event.Start(ctx, "cache.ParseMod", label.URI.Of(fh.URI()))
7474
defer done()
7575

7676
contents, err := fh.Content()
@@ -155,7 +155,7 @@ func (s *Snapshot) ParseWork(ctx context.Context, fh file.Handle) (*ParsedWorkFi
155155

156156
// parseWorkImpl parses a go.work file. It may return partial results and an error.
157157
func parseWorkImpl(ctx context.Context, fh file.Handle) (*ParsedWorkFile, error) {
158-
_, done := event.Start(ctx, "cache.ParseWork", tag.URI.Of(fh.URI()))
158+
_, done := event.Start(ctx, "cache.ParseWork", label.URI.Of(fh.URI()))
159159
defer done()
160160

161161
content, err := fh.Content()
@@ -265,7 +265,7 @@ func (s *Snapshot) ModWhy(ctx context.Context, fh file.Handle) (map[string]strin
265265

266266
// modWhyImpl returns the result of "go mod why -m" on the specified go.mod file.
267267
func modWhyImpl(ctx context.Context, snapshot *Snapshot, fh file.Handle) (map[string]string, error) {
268-
ctx, done := event.Start(ctx, "cache.ModWhy", tag.URI.Of(fh.URI()))
268+
ctx, done := event.Start(ctx, "cache.ModWhy", label.URI.Of(fh.URI()))
269269
defer done()
270270

271271
pm, err := snapshot.ParseMod(ctx, fh)

‎gopls/internal/cache/mod_tidy.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -18,11 +18,11 @@ import (
1818
"golang.org/x/mod/modfile"
1919
"golang.org/x/tools/gopls/internal/cache/parsego"
2020
"golang.org/x/tools/gopls/internal/file"
21+
"golang.org/x/tools/gopls/internal/label"
2122
"golang.org/x/tools/gopls/internal/protocol"
2223
"golang.org/x/tools/gopls/internal/protocol/command"
2324
"golang.org/x/tools/internal/diff"
2425
"golang.org/x/tools/internal/event"
25-
"golang.org/x/tools/internal/event/tag"
2626
"golang.org/x/tools/internal/gocommand"
2727
"golang.org/x/tools/internal/memoize"
2828
)
@@ -99,7 +99,7 @@ func (s *Snapshot) ModTidy(ctx context.Context, pm *ParsedModule) (*TidiedModule
9999

100100
// modTidyImpl runs "go mod tidy" on a go.mod file.
101101
func modTidyImpl(ctx context.Context, snapshot *Snapshot, filename string, pm *ParsedModule) (*TidiedModule, error) {
102-
ctx, done := event.Start(ctx, "cache.ModTidy", tag.URI.Of(filename))
102+
ctx, done := event.Start(ctx, "cache.ModTidy", label.File.Of(filename))
103103
defer done()
104104

105105
inv := &gocommand.Invocation{

‎gopls/internal/cache/parsego/parse.go

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -14,12 +14,12 @@ import (
1414
"go/token"
1515
"reflect"
1616

17+
"golang.org/x/tools/gopls/internal/label"
1718
"golang.org/x/tools/gopls/internal/protocol"
1819
"golang.org/x/tools/gopls/internal/util/astutil"
1920
"golang.org/x/tools/gopls/internal/util/safetoken"
2021
"golang.org/x/tools/internal/diff"
2122
"golang.org/x/tools/internal/event"
22-
"golang.org/x/tools/internal/event/tag"
2323
)
2424

2525
// 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
4242
if purgeFuncBodies {
4343
src = astutil.PurgeFuncBodies(src)
4444
}
45-
ctx, done := event.Start(ctx, "cache.ParseGoSrc", tag.File.Of(uri.Path()))
45+
ctx, done := event.Start(ctx, "cache.ParseGoSrc", label.File.Of(uri.Path()))
4646
defer done()
4747

4848
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
8484
// of the last changes we made to aid in debugging.
8585
if i == 9 {
8686
unified := diff.Unified("before", "after", string(src), string(newSrc))
87-
event.Log(ctx, fmt.Sprintf("fixSrc loop - last diff:\n%v", unified), tag.File.Of(tok.Name()))
87+
event.Log(ctx, fmt.Sprintf("fixSrc loop - last diff:\n%v", unified), label.File.Of(tok.Name()))
8888
}
8989

9090
newFile, newErr := parser.ParseFile(fset, uri.Path(), newSrc, mode)

‎gopls/internal/cache/session.go

Lines changed: 21 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,12 +20,14 @@ import (
2020
"golang.org/x/tools/gopls/internal/cache/metadata"
2121
"golang.org/x/tools/gopls/internal/cache/typerefs"
2222
"golang.org/x/tools/gopls/internal/file"
23+
"golang.org/x/tools/gopls/internal/label"
2324
"golang.org/x/tools/gopls/internal/protocol"
2425
"golang.org/x/tools/gopls/internal/util/bug"
2526
"golang.org/x/tools/gopls/internal/util/persistent"
2627
"golang.org/x/tools/gopls/internal/util/slices"
2728
"golang.org/x/tools/gopls/internal/vulncheck"
2829
"golang.org/x/tools/internal/event"
30+
"golang.org/x/tools/internal/event/keys"
2931
"golang.org/x/tools/internal/gocommand"
3032
"golang.org/x/tools/internal/imports"
3133
"golang.org/x/tools/internal/memoize"
@@ -263,7 +265,15 @@ func (s *Session) createView(ctx context.Context, def *viewDefinition) (*View, *
263265
}
264266

265267
// Record the environment of the newly created view in the log.
266-
event.Log(ctx, viewEnv(v))
268+
event.Log(ctx, fmt.Sprintf("Created View (#%s)", v.id),
269+
label.Directory.Of(v.folder.Dir.Path()),
270+
viewTypeKey.Of(v.typ.String()),
271+
rootDirKey.Of(string(v.root)),
272+
goVersionKey.Of(strings.TrimRight(v.folder.Env.GoVersionOutput, "\n")),
273+
buildFlagsKey.Of(fmt.Sprint(v.folder.Options.BuildFlags)),
274+
envKey.Of(fmt.Sprintf("%+v", v.folder.Env)),
275+
envOverlayKey.Of(v.EnvOverlay()),
276+
)
267277

268278
// Initialize the view without blocking.
269279
initCtx, initCancel := context.WithCancel(xcontext.Detach(ctx))
@@ -281,6 +291,16 @@ func (s *Session) createView(ctx context.Context, def *viewDefinition) (*View, *
281291
return v, snapshot, snapshot.Acquire()
282292
}
283293

294+
// These keys are used to log view metadata in createView.
295+
var (
296+
viewTypeKey = keys.NewString("view_type", "")
297+
rootDirKey = keys.NewString("root_dir", "")
298+
goVersionKey = keys.NewString("go_version", "")
299+
buildFlagsKey = keys.New("build_flags", "")
300+
envKey = keys.New("env", "")
301+
envOverlayKey = keys.New("env_overlay", "")
302+
)
303+
284304
// RemoveView removes from the session the view rooted at the specified directory.
285305
// It reports whether a view of that directory was removed.
286306
func (s *Session) RemoveView(dir protocol.DocumentURI) bool {

‎gopls/internal/cache/snapshot.go

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,7 @@ import (
3535
"golang.org/x/tools/gopls/internal/cache/xrefs"
3636
"golang.org/x/tools/gopls/internal/file"
3737
"golang.org/x/tools/gopls/internal/filecache"
38+
label1 "golang.org/x/tools/gopls/internal/label"
3839
"golang.org/x/tools/gopls/internal/protocol"
3940
"golang.org/x/tools/gopls/internal/protocol/command"
4041
"golang.org/x/tools/gopls/internal/settings"
@@ -47,7 +48,6 @@ import (
4748
"golang.org/x/tools/gopls/internal/vulncheck"
4849
"golang.org/x/tools/internal/event"
4950
"golang.org/x/tools/internal/event/label"
50-
"golang.org/x/tools/internal/event/tag"
5151
"golang.org/x/tools/internal/gocommand"
5252
"golang.org/x/tools/internal/memoize"
5353
"golang.org/x/tools/internal/packagesinternal"
@@ -269,7 +269,11 @@ func (s *Snapshot) SequenceID() uint64 {
269269
// SnapshotLabels returns a new slice of labels that should be used for events
270270
// related to a snapshot.
271271
func (s *Snapshot) Labels() []label.Label {
272-
return []label.Label{tag.Snapshot.Of(s.SequenceID()), tag.Directory.Of(s.Folder())}
272+
return []label.Label{
273+
label1.ViewID.Of(s.view.id),
274+
label1.Snapshot.Of(s.SequenceID()),
275+
label1.Directory.Of(s.Folder().Path()),
276+
}
273277
}
274278

275279
// Folder returns the folder at the base of this snapshot.

0 commit comments

Comments
 (0)