From ed968f66bdf283030037de9d0014845ed0dcde56 Mon Sep 17 00:00:00 2001 From: Robert Findley Date: Mon, 11 Apr 2022 13:05:28 -0400 Subject: [PATCH] internal/lsp/bug: add a package for bug reporting The existing debug.Bug mechanism for reporting internal bugs is insufficient for several reasons: - It requires a context, which is not always available. - By being defined in the debug package, it is subject to import cycles. - It is too complicated. Listening for bugs requires understanding the event package. Replace this with a simpler 'bug' package with no dependencies, that allows reporting, listing, and listening on internal bugs. Hopefully this will fulfill the goal of debug.Bug, to help us track down rare bugs. Change-Id: I30cab58429b29bd2d944d62e94f5657e40a760fc Reviewed-on: https://go-review.googlesource.com/c/tools/+/399623 Reviewed-by: Hyang-Ah Hana Kim Reviewed-by: Alan Donovan gopls-CI: kokoro TryBot-Result: Gopher Robot Run-TryBot: Robert Findley --- internal/lsp/bug/bug.go | 106 ++++++++++++++++++++++ internal/lsp/bug/bug_test.go | 65 +++++++++++++ internal/lsp/debug/serve.go | 54 +++-------- internal/lsp/debug/tag/tag.go | 4 - internal/lsp/source/completion/package.go | 10 +- internal/lsp/source/hover.go | 14 +-- internal/lsp/source/identifier.go | 4 + 7 files changed, 202 insertions(+), 55 deletions(-) create mode 100644 internal/lsp/bug/bug.go create mode 100644 internal/lsp/bug/bug_test.go diff --git a/internal/lsp/bug/bug.go b/internal/lsp/bug/bug.go new file mode 100644 index 0000000000..147b8e818c --- /dev/null +++ b/internal/lsp/bug/bug.go @@ -0,0 +1,106 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +// Package bug provides utilities for reporting internal bugs, and being +// notified when they occur. +// +// Philosophically, because gopls runs as a sidecar process that the user does +// not directly control, sometimes it keeps going on broken invariants rather +// than panicking. In those cases, bug reports provide a mechanism to alert +// developers and capture relevant metadata. +package bug + +import ( + "fmt" + "runtime" + "runtime/debug" + "sort" + "sync" +) + +var ( + mu sync.Mutex + exemplars map[string]Bug + waiters []chan<- Bug +) + +// A Bug represents an unexpected event or broken invariant. They are used for +// capturing metadata that helps us understand the event. +type Bug struct { + File string // file containing the call to bug.Report + Line int // line containing the call to bug.Report + Description string // description of the bug + Data Data // additional metadata + Key string // key identifying the bug (file:line if available) + Stack string // call stack +} + +// Data is additional metadata to record for a bug. +type Data map[string]interface{} + +// Report records a new bug encountered on the server. +// It uses reflection to report the position of the immediate caller. +func Report(description string, data Data) { + _, file, line, ok := runtime.Caller(1) + + key := "" + if ok { + key = fmt.Sprintf("%s:%d", file, line) + } + + bug := Bug{ + File: file, + Line: line, + Description: description, + Data: data, + Key: key, + Stack: string(debug.Stack()), + } + + mu.Lock() + defer mu.Unlock() + + if exemplars == nil { + exemplars = make(map[string]Bug) + } + + if _, ok := exemplars[key]; !ok { + exemplars[key] = bug // capture one exemplar per key + } + + for _, waiter := range waiters { + waiter <- bug + } + waiters = nil +} + +// Notify returns a channel that will be sent the next bug to occur on the +// server. This channel only ever receives one bug. +func Notify() <-chan Bug { + mu.Lock() + defer mu.Unlock() + + ch := make(chan Bug, 1) // 1-buffered so that bug reporting is non-blocking + waiters = append(waiters, ch) + return ch +} + +// List returns a slice of bug exemplars -- the first bugs to occur at each +// callsite. +func List() []Bug { + mu.Lock() + defer mu.Unlock() + + var bugs []Bug + + for _, bug := range exemplars { + bugs = append(bugs, bug) + } + + sort.Slice(bugs, func(i, j int) bool { + return bugs[i].Key < bugs[j].Key + }) + + return bugs +} diff --git a/internal/lsp/bug/bug_test.go b/internal/lsp/bug/bug_test.go new file mode 100644 index 0000000000..edfc10386b --- /dev/null +++ b/internal/lsp/bug/bug_test.go @@ -0,0 +1,65 @@ +// Copyright 2022 The Go Authors. All rights reserved. +// Use of this source code is governed by a BSD-style +// license that can be found in the LICENSE file. + +package bug + +import ( + "fmt" + "testing" +) + +func resetForTesting() { + exemplars = nil + waiters = nil +} + +func TestListBugs(t *testing.T) { + defer resetForTesting() + + Report("bad", nil) + + wantBugs(t, "bad") + + for i := 0; i < 3; i++ { + Report(fmt.Sprintf("index:%d", i), nil) + } + + wantBugs(t, "bad", "index:0") +} + +func wantBugs(t *testing.T, want ...string) { + t.Helper() + + bugs := List() + if got, want := len(bugs), len(want); got != want { + t.Errorf("List(): got %d bugs, want %d", got, want) + return + } + + for i, b := range bugs { + if got, want := b.Description, want[i]; got != want { + t.Errorf("bug.List()[%d] = %q, want %q", i, got, want) + } + } +} + +func TestBugNotification(t *testing.T) { + defer resetForTesting() + + Report("unseen", nil) + + notify1 := Notify() + notify2 := Notify() + + Report("seen", Data{"answer": 42}) + + for _, got := range []Bug{<-notify1, <-notify2} { + if got, want := got.Description, "seen"; got != want { + t.Errorf("Saw bug %q, want %q", got, want) + } + if got, want := got.Data["answer"], 42; got != want { + t.Errorf(`bug.Data["answer"] = %v, want %v`, got, want) + } + } +} diff --git a/internal/lsp/debug/serve.go b/internal/lsp/debug/serve.go index 97790fc18e..0bdee92c5e 100644 --- a/internal/lsp/debug/serve.go +++ b/internal/lsp/debug/serve.go @@ -21,7 +21,6 @@ import ( "path/filepath" "runtime" rpprof "runtime/pprof" - "sort" "strconv" "strings" "sync" @@ -35,6 +34,7 @@ import ( "golang.org/x/tools/internal/event/export/prometheus" "golang.org/x/tools/internal/event/keys" "golang.org/x/tools/internal/event/label" + "golang.org/x/tools/internal/lsp/bug" "golang.org/x/tools/internal/lsp/cache" "golang.org/x/tools/internal/lsp/debug/log" "golang.org/x/tools/internal/lsp/debug/tag" @@ -77,45 +77,10 @@ type State struct { mu sync.Mutex clients []*Client servers []*Server - - // bugs maps bug description -> formatted event - bugs map[string]string } -func Bug(ctx context.Context, desc, format string, args ...interface{}) { - labels := []label.Label{tag.Bug.Of(desc)} - _, file, line, ok := runtime.Caller(1) - if ok { - labels = append(labels, tag.Callsite.Of(fmt.Sprintf("%s:%d", file, line))) - } - msg := fmt.Sprintf(format, args...) - event.Log(ctx, msg, labels...) -} - -type bug struct { - Description, Event string -} - -func (st *State) Bugs() []bug { - st.mu.Lock() - defer st.mu.Unlock() - var bugs []bug - for k, v := range st.bugs { - bugs = append(bugs, bug{k, v}) - } - sort.Slice(bugs, func(i, j int) bool { - return bugs[i].Description < bugs[j].Description - }) - return bugs -} - -func (st *State) recordBug(description, event string) { - st.mu.Lock() - defer st.mu.Unlock() - if st.bugs == nil { - st.bugs = make(map[string]string) - } - st.bugs[description] = event +func (st *State) Bugs() []bug.Bug { + return bug.List() } // Caches returns the set of Cache objects currently being served. @@ -502,6 +467,12 @@ func (i *Instance) Serve(ctx context.Context, addr string) (string, error) { mux.HandleFunc("/file/", render(FileTmpl, i.getFile)) mux.HandleFunc("/info", render(InfoTmpl, i.getInfo)) mux.HandleFunc("/memory", render(MemoryTmpl, getMemory)) + + mux.HandleFunc("/_makeabug", func(w http.ResponseWriter, r *http.Request) { + bug.Report("bug here", nil) + http.Error(w, "made a bug", http.StatusOK) + }) + if err := http.Serve(listener, mux); err != nil { event.Error(ctx, "Debug server failed", err) return @@ -676,9 +647,6 @@ func makeInstanceExporter(i *Instance) event.Exporter { } } } - if b := tag.Bug.Get(ev); b != "" { - i.State.recordBug(b, fmt.Sprintf("%v", ev)) - } return ctx } // StdTrace must be above export.Spans below (by convention, export @@ -809,8 +777,8 @@ var MainTmpl = template.Must(template.Must(BaseTemplate.Clone()).Parse(`
    {{range .State.Clients}}
  • {{template "clientlink" .Session.ID}}
    • {{end}}

Servers

    {{range .State.Servers}}
  • {{template "serverlink" .ID}}
    • {{end}}
-

Known bugs encountered

-
{{range .State.Bugs}}
{{.Description}}
{{.Event}}
{{end}}
+

Bug reports

+
{{range .State.Bugs}}
{{.Key}}
{{.Description}}
{{end}}
{{end}} `)) diff --git a/internal/lsp/debug/tag/tag.go b/internal/lsp/debug/tag/tag.go index 1d00038f0a..ff2f2ecd38 100644 --- a/internal/lsp/debug/tag/tag.go +++ b/internal/lsp/debug/tag/tag.go @@ -43,10 +43,6 @@ var ( ClientID = keys.NewString("client_id", "") Level = keys.NewInt("level", "The logging level") - - // Bug tracks occurrences of known bugs in the server. - Bug = keys.NewString("bug", "A bug has occurred") - Callsite = keys.NewString("callsite", "gopls function call site") ) var ( diff --git a/internal/lsp/source/completion/package.go b/internal/lsp/source/completion/package.go index 39495e6a54..7a05153e80 100644 --- a/internal/lsp/source/completion/package.go +++ b/internal/lsp/source/completion/package.go @@ -18,7 +18,7 @@ import ( "strings" "unicode" - "golang.org/x/tools/internal/lsp/debug" + "golang.org/x/tools/internal/lsp/bug" "golang.org/x/tools/internal/lsp/fuzzy" "golang.org/x/tools/internal/lsp/protocol" "golang.org/x/tools/internal/lsp/safetoken" @@ -86,7 +86,13 @@ func packageCompletionSurrounding(ctx context.Context, fset *token.FileSet, pgf return nil, err } if offset > tok.Size() { - debug.Bug(ctx, "out of bounds cursor", "cursor offset (%d) out of bounds for %s (size: %d)", offset, pgf.URI, tok.Size()) + // internal bug: we should never get an offset that exceeds the size of our + // file. + bug.Report("out of bounds cursor", bug.Data{ + "offset": offset, + "URI": pgf.URI, + "size": tok.Size(), + }) return nil, fmt.Errorf("cursor out of bounds") } cursor := tok.Pos(offset) diff --git a/internal/lsp/source/hover.go b/internal/lsp/source/hover.go index 277933ca50..dff906056c 100644 --- a/internal/lsp/source/hover.go +++ b/internal/lsp/source/hover.go @@ -22,6 +22,7 @@ import ( "golang.org/x/text/unicode/runenames" "golang.org/x/tools/internal/event" + "golang.org/x/tools/internal/lsp/bug" "golang.org/x/tools/internal/lsp/protocol" "golang.org/x/tools/internal/lsp/safetoken" "golang.org/x/tools/internal/typeparams" @@ -407,8 +408,11 @@ func linkData(obj types.Object, enclosing *types.TypeName) (name, importPath, an } // golang/go#52211: somehow we get here with a nil obj.Pkg - // TODO: allow using debug.Bug here, to catch this bug. if obj.Pkg() == nil { + bug.Report("object with nil pkg", bug.Data{ + "name": obj.Name(), + "type": fmt.Sprintf("%T", obj), + }) return "", "", "" } @@ -598,11 +602,9 @@ func FindHoverContext(ctx context.Context, s Snapshot, pkg Package, obj types.Ob info.signatureSource = "func " + sig.name + sig.Format() } else { // Fall back on the object as a signature source. - - // TODO(rfindley): refactor so that we can report bugs from the source - // package. - - // debug.Bug(ctx, "invalid builtin hover", "did not find builtin signature: %v", err) + bug.Report("invalid builtin hover", bug.Data{ + "err": err.Error(), + }) info.signatureSource = obj } case *types.Var: diff --git a/internal/lsp/source/identifier.go b/internal/lsp/source/identifier.go index fd1fd3b4e6..d5aa0a5a8b 100644 --- a/internal/lsp/source/identifier.go +++ b/internal/lsp/source/identifier.go @@ -17,6 +17,7 @@ import ( "golang.org/x/tools/go/ast/astutil" "golang.org/x/tools/internal/event" + "golang.org/x/tools/internal/lsp/bug" "golang.org/x/tools/internal/lsp/protocol" "golang.org/x/tools/internal/lsp/safetoken" "golang.org/x/tools/internal/span" @@ -98,6 +99,9 @@ func Identifier(ctx context.Context, snapshot Snapshot, fh FileHandle, pos proto for _, pkg := range pkgs { pgf, err := pkg.File(fh.URI()) if err != nil { + // We shouldn't get a package from PackagesForFile that doesn't actually + // contain the file. + bug.Report("missing package file", bug.Data{"pkg": pkg.ID(), "file": fh.URI()}) return nil, err } spn, err := pgf.Mapper.PointSpan(pos)