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 <iancottrell@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Rebecca Stambler <rstambler@golang.org>

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
+}

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 {

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
 }

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),

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)
+	}
+}

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
+}

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.

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 {