From 7ec096a1122469269330911b24bb7db048b83649 Mon Sep 17 00:00:00 2001 From: Ian Cottrell Date: Wed, 10 Jul 2019 15:19:29 -0400 Subject: [PATCH] internal/lsp: add a new telemetry based logging system Also add enough support that using it from within the context of the lsp will report back to the original client. Change-Id: I081f157c289642454e9f0476747b2131dcd4e16c Reviewed-on: https://go-review.googlesource.com/c/tools/+/185996 Run-TryBot: Ian Cottrell TryBot-Result: Gobot Gobot Reviewed-by: Rebecca Stambler --- internal/lsp/protocol/context.go | 42 +++++++++++++ internal/lsp/protocol/log.go | 7 --- internal/lsp/protocol/protocol.go | 4 +- internal/lsp/server.go | 3 +- internal/lsp/telemetry/log/entry.go | 51 ++++++++++++++++ internal/lsp/telemetry/log/log.go | 92 +++++++++++++++++++++++++++++ internal/lsp/telemetry/tag/key.go | 12 ++++ internal/lsp/telemetry/tag/tag.go | 23 ++++++++ 8 files changed, 223 insertions(+), 11 deletions(-) create mode 100644 internal/lsp/protocol/context.go create mode 100644 internal/lsp/telemetry/log/entry.go create mode 100644 internal/lsp/telemetry/log/log.go diff --git a/internal/lsp/protocol/context.go b/internal/lsp/protocol/context.go new file mode 100644 index 0000000000..6112ca65fd --- /dev/null +++ b/internal/lsp/protocol/context.go @@ -0,0 +1,42 @@ +package protocol + +import ( + "context" + "fmt" + "time" + + "golang.org/x/tools/internal/lsp/telemetry/log" + "golang.org/x/tools/internal/lsp/telemetry/tag" + "golang.org/x/tools/internal/lsp/xlog" + "golang.org/x/tools/internal/xcontext" +) + +func init() { + log.AddLogger(logger) +} + +type contextKey int + +const ( + clientKey = contextKey(iota) +) + +func WithClient(ctx context.Context, client Client) context.Context { + ctx = xlog.With(ctx, logSink{client: client}) + return context.WithValue(ctx, clientKey, client) +} + +// logger implements log.Logger in terms of the LogMessage call to a client. +func logger(ctx context.Context, at time.Time, tags tag.List) bool { + client, ok := ctx.Value(clientKey).(Client) + if !ok { + return false + } + entry := log.ToEntry(ctx, time.Time{}, tags) + msg := &LogMessageParams{Type: Info, Message: fmt.Sprint(entry)} + if entry.Error != nil { + msg.Type = Error + } + client.LogMessage(xcontext.Detach(ctx), msg) + return true +} diff --git a/internal/lsp/protocol/log.go b/internal/lsp/protocol/log.go index 71725c9359..dfd80d0a55 100644 --- a/internal/lsp/protocol/log.go +++ b/internal/lsp/protocol/log.go @@ -11,13 +11,6 @@ type logSink struct { client Client } -// NewLogger returns an xlog.Sink that sends its messages using client.LogMessage. -// It maps Debug to the Log level, Info and Error to their matching levels, and -// does not support warnings. -func NewLogger(client Client) xlog.Sink { - return logSink{client: client} -} - func (s logSink) Log(ctx context.Context, level xlog.Level, message string) { typ := Log switch level { diff --git a/internal/lsp/protocol/protocol.go b/internal/lsp/protocol/protocol.go index 731f8bc7a6..8c3ef9524e 100644 --- a/internal/lsp/protocol/protocol.go +++ b/internal/lsp/protocol/protocol.go @@ -39,7 +39,7 @@ func (canceller) Cancel(ctx context.Context, conn *jsonrpc2.Conn, id jsonrpc2.ID } func NewClient(ctx context.Context, stream jsonrpc2.Stream, client Client) (context.Context, *jsonrpc2.Conn, Server) { - ctx = xlog.With(ctx, NewLogger(client)) + ctx = WithClient(ctx, client) conn := jsonrpc2.NewConn(stream) conn.AddHandler(&clientHandler{client: client}) return ctx, conn, &serverDispatcher{Conn: conn} @@ -48,7 +48,7 @@ func NewClient(ctx context.Context, stream jsonrpc2.Stream, client Client) (cont func NewServer(ctx context.Context, stream jsonrpc2.Stream, server Server) (context.Context, *jsonrpc2.Conn, Client) { conn := jsonrpc2.NewConn(stream) client := &clientDispatcher{Conn: conn} - ctx = xlog.With(ctx, NewLogger(client)) + ctx = WithClient(ctx, client) conn.AddHandler(&serverHandler{server: server}) return ctx, conn, client } diff --git a/internal/lsp/server.go b/internal/lsp/server.go index 8d38423514..088bdcaed2 100644 --- a/internal/lsp/server.go +++ b/internal/lsp/server.go @@ -13,13 +13,12 @@ import ( "golang.org/x/tools/internal/jsonrpc2" "golang.org/x/tools/internal/lsp/protocol" "golang.org/x/tools/internal/lsp/source" - "golang.org/x/tools/internal/lsp/xlog" "golang.org/x/tools/internal/span" ) // NewClientServer func NewClientServer(ctx context.Context, cache source.Cache, client protocol.Client) (context.Context, *Server) { - ctx = xlog.With(ctx, protocol.NewLogger(client)) + ctx = protocol.WithClient(ctx, client) return ctx, &Server{ client: client, session: cache.NewSession(ctx), diff --git a/internal/lsp/telemetry/log/entry.go b/internal/lsp/telemetry/log/entry.go new file mode 100644 index 0000000000..3f392cf3bb --- /dev/null +++ b/internal/lsp/telemetry/log/entry.go @@ -0,0 +1,51 @@ +// Copyright 2019 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 log + +import ( + "context" + "fmt" + "time" + + "golang.org/x/tools/internal/lsp/telemetry/tag" +) + +type Entry struct { + At time.Time + Message string + Error error + Tags tag.List +} + +func ToEntry(ctx context.Context, at time.Time, tags tag.List) Entry { + //TODO: filter more efficiently for the common case of stripping prefixes only + entry := Entry{ + At: at, + } + for _, t := range tags { + switch t.Key { + case MessageTag: + entry.Message = t.Value.(string) + case ErrorTag: + entry.Error = t.Value.(error) + default: + entry.Tags = append(entry.Tags, t) + } + } + return entry +} + +func (e Entry) Format(f fmt.State, r rune) { + if !e.At.IsZero() { + fmt.Fprint(f, e.At.Format("2006/01/02 15:04:05 ")) + } + fmt.Fprint(f, e.Message) + if e.Error != nil { + fmt.Fprintf(f, ": %v", e.Error) + } + for _, tag := range e.Tags { + fmt.Fprintf(f, "\n\t%v = %v", tag.Key, tag.Value) + } +} diff --git a/internal/lsp/telemetry/log/log.go b/internal/lsp/telemetry/log/log.go new file mode 100644 index 0000000000..8391ad7cec --- /dev/null +++ b/internal/lsp/telemetry/log/log.go @@ -0,0 +1,92 @@ +// Copyright 2019 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 log is a context based logging package, designed to interact well +// with both the lsp protocol and the other telemetry packages. +package log + +import ( + "context" + "fmt" + "os" + "time" + + "golang.org/x/tools/internal/lsp/telemetry/tag" + "golang.org/x/tools/internal/lsp/telemetry/worker" +) + +const ( + // The well known tag keys for the logging system. + MessageTag = tag.Key("message") + ErrorTag = tag.Key("error") +) + +// Logger is a function that handles logging messages. +// Loggers are registered at start up, and may use information in the context +// to decide what to do with a given log message. +type Logger func(ctx context.Context, at time.Time, tags tag.List) bool + +// With sends a tag list to the installed loggers. +func With(ctx context.Context, tags ...tag.Tag) { + at := time.Now() + worker.Do(func() { + deliver(ctx, at, tags) + }) +} + +// Print takes a message and a tag list and combines them into a single tag +// list before delivering them to the loggers. +func Print(ctx context.Context, message string, tags ...tag.Tagger) { + at := time.Now() + worker.Do(func() { + tags := append(tag.Tags(ctx, tags...), MessageTag.Of(message)) + deliver(ctx, at, tags) + }) +} + +type errorString string + +// Error allows errorString to conform to the error interface. +func (err errorString) Error() string { return string(err) } + +// Print takes a message and a tag list and combines them into a single tag +// list before delivering them to the loggers. +func Error(ctx context.Context, message string, err error, tags ...tag.Tagger) { + at := time.Now() + worker.Do(func() { + if err == nil { + err = errorString(message) + message = "" + } + tags := append(tag.Tags(ctx, tags...), MessageTag.Of(message), ErrorTag.Of(err)) + deliver(ctx, at, tags) + }) +} + +func deliver(ctx context.Context, at time.Time, tags tag.List) { + delivered := false + for _, logger := range loggers { + if logger(ctx, at, tags) { + delivered = true + } + } + if !delivered { + // no logger processed the message, so we log to stderr just in case + Stderr(ctx, at, tags) + } +} + +var loggers = []Logger{} + +func AddLogger(logger Logger) { + worker.Do(func() { + loggers = append(loggers, logger) + }) +} + +// Stderr is a logger that logs to stderr in the standard format. +func Stderr(ctx context.Context, at time.Time, tags tag.List) bool { + fmt.Fprintf(os.Stderr, "%v\n", ToEntry(ctx, at, tags)) + return true +} diff --git a/internal/lsp/telemetry/tag/key.go b/internal/lsp/telemetry/tag/key.go index 65a4ee0ec8..971500498b 100644 --- a/internal/lsp/telemetry/tag/key.go +++ b/internal/lsp/telemetry/tag/key.go @@ -17,12 +17,24 @@ import ( // those values in the context. type Key string +// Of returns a Tag for a key and value. +// This is a trivial helper that makes common logging easier to read. +func Of(key interface{}, value interface{}) Tag { + return Tag{Key: key, Value: value} +} + // Of creates a new Tag with this key and the supplied value. // You can use this when building a tag list. func (k Key) Of(v interface{}) Tag { return Tag{Key: k, Value: v} } +// Tag can be used to get a tag for the key from a context. +// It makes Key conform to the Tagger interface. +func (k Key) Tag(ctx context.Context) Tag { + return Tag{Key: k, Value: ctx.Value(k)} +} + // With applies sets this key to the supplied value on the context and // returns the new context generated. // It uses the With package level function so that observers are also notified. diff --git a/internal/lsp/telemetry/tag/tag.go b/internal/lsp/telemetry/tag/tag.go index 5a2b88293d..201c65e746 100644 --- a/internal/lsp/telemetry/tag/tag.go +++ b/internal/lsp/telemetry/tag/tag.go @@ -25,6 +25,14 @@ type Tag struct { Value interface{} } +// Tagger is the interface to somthing that returns a Tag given a context. +// Both Tag itself and Key support this interface, allowing methods that can +// take either (and other implementations as well) +type Tagger interface { + // Tag returns a Tag potentially using information from the Context. + Tag(context.Context) Tag +} + // List is a way of passing around a collection of key value pairs. // It is an alternative to the less efficient and unordered method of using // maps. @@ -64,6 +72,15 @@ func Get(ctx context.Context, keys ...interface{}) List { return tags } +// Tags collects a list of tags for the taggers from the context. +func Tags(ctx context.Context, taggers ...Tagger) List { + tags := make(List, len(taggers)) + for i, t := range taggers { + tags[i] = t.Tag(ctx) + } + return tags +} + var observers = []Observer{} // Observe adds a new tag observer to the registered set. @@ -80,6 +97,12 @@ func (t Tag) Format(f fmt.State, r rune) { fmt.Fprintf(f, `%v="%v"`, t.Key, t.Value) } +// Get returns the tag unmodified. +// It makes Key conform to the Tagger interface. +func (t Tag) Tag(ctx context.Context) Tag { + return t +} + // Get will get a single key's value from the list. func (l List) Get(k interface{}) interface{} { for _, t := range l {