internal/event: improve the logging of events

This extracts the printing code from the log writer so it can be re-used
and then changes the loggers in the lsp to use it.
This means that messages that used to look like

  date:
    message=text

now print as

  date: text

which makes the logs a lot easier to read.

Change-Id: I9dfbae47cdc9aeb7d3ca3279e445f39f2e590827
Reviewed-on: https://go-review.googlesource.com/c/tools/+/232989
Run-TryBot: Ian Cottrell <iancottrell@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Robert Findley <rfindley@google.com>

4 files changed, 56 insertions, 27 deletions

diff --git a/internal/event/export/log.go b/internal/event/export/log.go
index d36bb0c49..96110e718 100644
--- a/internal/event/export/log.go
+++ b/internal/event/export/log.go
@@ -12,7 +12,6 @@ import (
 
 	"golang.org/x/tools/internal/event"
 	"golang.org/x/tools/internal/event/core"
-	"golang.org/x/tools/internal/event/keys"
 	"golang.org/x/tools/internal/event/label"
 )
 
@@ -27,7 +26,7 @@ func LogWriter(w io.Writer, onlyErrors bool) event.Exporter {
 
 type logWriter struct {
 	mu         sync.Mutex
-	buffer     [128]byte
+	printer    Printer
 	writer     io.Writer
 	onlyErrors bool
 }
@@ -40,28 +39,7 @@ func (w *logWriter) ProcessEvent(ctx context.Context, ev core.Event, lm label.Ma
 		}
 		w.mu.Lock()
 		defer w.mu.Unlock()
-
-		buf := w.buffer[:0]
-		if !ev.At().IsZero() {
-			w.writer.Write(ev.At().AppendFormat(buf, "2006/01/02 15:04:05 "))
-		}
-		msg := keys.Msg.Get(lm)
-		io.WriteString(w.writer, msg)
-		if err := keys.Err.Get(lm); err != nil {
-			io.WriteString(w.writer, ": ")
-			io.WriteString(w.writer, err.Error())
-		}
-		for index := 0; ev.Valid(index); index++ {
-			l := ev.Label(index)
-			if !l.Valid() || l.Key() == keys.Msg || l.Key() == keys.Err {
-				continue
-			}
-			io.WriteString(w.writer, "\n\t")
-			io.WriteString(w.writer, l.Key().Name())
-			io.WriteString(w.writer, "=")
-			l.Key().Format(w.writer, buf, l)
-		}
-		io.WriteString(w.writer, "\n")
+		w.printer.WriteEvent(w.writer, ev, lm)
 
 	case event.IsStart(ev):
 		if span := GetSpan(ctx); span != nil {
diff --git a/internal/event/export/printer.go b/internal/event/export/printer.go
new file mode 100644
index 000000000..9fb6f9eb9
--- /dev/null
+++ b/internal/event/export/printer.go
@@ -0,0 +1,43 @@
+// Copyright 2020 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 export
+
+import (
+	"io"
+
+	"golang.org/x/tools/internal/event/core"
+	"golang.org/x/tools/internal/event/keys"
+	"golang.org/x/tools/internal/event/label"
+)
+
+type Printer struct {
+	buffer [128]byte
+}
+
+func (p *Printer) WriteEvent(w io.Writer, ev core.Event, lm label.Map) {
+	buf := p.buffer[:0]
+	if !ev.At().IsZero() {
+		w.Write(ev.At().AppendFormat(buf, "2006/01/02 15:04:05 "))
+	}
+	msg := keys.Msg.Get(lm)
+	io.WriteString(w, msg)
+	if err := keys.Err.Get(lm); err != nil {
+		if msg != "" {
+			io.WriteString(w, ": ")
+		}
+		io.WriteString(w, err.Error())
+	}
+	for index := 0; ev.Valid(index); index++ {
+		l := ev.Label(index)
+		if !l.Valid() || l.Key() == keys.Msg || l.Key() == keys.Err {
+			continue
+		}
+		io.WriteString(w, "\n\t")
+		io.WriteString(w, l.Key().Name())
+		io.WriteString(w, "=")
+		l.Key().Format(w, buf, l)
+	}
+	io.WriteString(w, "\n")
+}
diff --git a/internal/lsp/debug/serve.go b/internal/lsp/debug/serve.go
index 64b644790..15c0d3001 100644
--- a/internal/lsp/debug/serve.go
+++ b/internal/lsp/debug/serve.go
@@ -545,6 +545,8 @@ func (i *Instance) writeMemoryDebug(threshold uint64) error {
 }
 
 func makeGlobalExporter(stderr io.Writer) event.Exporter {
+	p := export.Printer{}
+	var pMu sync.Mutex
 	return func(ctx context.Context, ev core.Event, lm label.Map) context.Context {
 		i := GetInstance(ctx)
 
@@ -555,7 +557,9 @@ func makeGlobalExporter(stderr io.Writer) event.Exporter {
 			}
 			// Make sure any log messages without an instance go to stderr.
 			if i == nil {
-				fmt.Fprintf(stderr, "%v\n", ev)
+				pMu.Lock()
+				p.WriteEvent(stderr, ev, lm)
+				pMu.Unlock()
 			}
 		}
 		ctx = protocol.LogEvent(ctx, ev, lm)
diff --git a/internal/lsp/protocol/context.go b/internal/lsp/protocol/context.go
index 5feeb3457..5a87dd249 100644
--- a/internal/lsp/protocol/context.go
+++ b/internal/lsp/protocol/context.go
@@ -1,11 +1,12 @@
 package protocol
 
 import (
+	"bytes"
 	"context"
-	"fmt"
 
 	"golang.org/x/tools/internal/event"
 	"golang.org/x/tools/internal/event/core"
+	"golang.org/x/tools/internal/event/export"
 	"golang.org/x/tools/internal/event/label"
 	"golang.org/x/tools/internal/xcontext"
 )
@@ -28,7 +29,10 @@ func LogEvent(ctx context.Context, ev core.Event, tags label.Map) context.Contex
 	if !ok {
 		return ctx
 	}
-	msg := &LogMessageParams{Type: Info, Message: fmt.Sprint(ev)}
+	buf := &bytes.Buffer{}
+	p := export.Printer{}
+	p.WriteEvent(buf, ev, tags)
+	msg := &LogMessageParams{Type: Info, Message: buf.String()}
 	if event.IsError(ev) {
 		msg.Type = Error
 	}