cmd/golsp: format logging for the lsp inspector

This improves the logging capabilities of the jsonrpc 2 library to always
include the method and also an optional elapsed time.
This is used to implement an lsp inspector compatible logging mode in the golsp.

Change-Id: I2f7ac8b9298c4364b1b89cf6f696b534557ed139
Reviewed-on: https://go-review.googlesource.com/c/146157
Reviewed-by: Rebecca Stambler <rstambler@golang.org>

cmd/golsp/main.go

@@ -10,6 +10,7 @@ package main // import "golang.org/x/tools/cmd/golsp"
 
 import (
 	"context"
+	"encoding/json"
 	"flag"
 	"fmt"
 	"io"
@@ -18,6 +19,7 @@ import (
 	"runtime"
 	"runtime/pprof"
 	"runtime/trace"
+	"time"
 
 	"golang.org/x/tools/internal/jsonrpc2"
 	"golang.org/x/tools/internal/lsp"
@@ -86,6 +88,7 @@ func main() {
 		}()
 	}
 
+	out := os.Stderr
 	if *logfile != "" {
 		f, err := os.Create(*logfile)
 		if err != nil {
@@ -93,12 +96,52 @@ func main() {
 		}
 		defer f.Close()
 		log.SetOutput(io.MultiWriter(os.Stderr, f))
+		out = f
 	}
-	if err := run(context.Background()); err != nil {
+	if err := lsp.RunServer(
+		context.Background(),
+		jsonrpc2.NewHeaderStream(os.Stdin, os.Stdout),
+		func(direction jsonrpc2.Direction, id *jsonrpc2.ID, elapsed time.Duration, method string, payload *json.RawMessage, err *jsonrpc2.Error) {
+
+			if err != nil {
+				fmt.Fprintf(out, "[Error - %v] %s %s%s %v", time.Now().Format("3:04:05 PM"), direction, method, id, err)
+				return
+			}
+			fmt.Fprintf(out, "[Trace - %v] ", time.Now().Format("3:04:05 PM"))
+			switch direction {
+			case jsonrpc2.Send:
+				fmt.Fprint(out, "Received ")
+			case jsonrpc2.Receive:
+				fmt.Fprint(out, "Sending ")
+			}
+			switch {
+			case id == nil:
+				fmt.Fprint(out, "notification ")
+			case elapsed >= 0:
+				fmt.Fprint(out, "response ")
+			default:
+				fmt.Fprint(out, "request ")
+			}
+			fmt.Fprintf(out, "'%s", method)
+			switch {
+			case id == nil:
+				// do nothing
+			case id.Name != "":
+				fmt.Fprintf(out, " - (%s)", id.Name)
+			default:
+				fmt.Fprintf(out, " - (%d)", id.Number)
+			}
+			fmt.Fprint(out, "'")
+			if elapsed >= 0 {
+				fmt.Fprintf(out, " in %vms", elapsed.Nanoseconds()/1000)
+			}
+			params := string(*payload)
+			if params == "null" {
+				params = "{}"
+			}
+			fmt.Fprintf(out, ".\r\nParams: %s\r\n\r\n\r\n", params)
+		},
+	); err != nil {
 		log.Fatal(err)
 	}
 }
-
-func run(ctx context.Context) error {
-	return lsp.RunServer(ctx, jsonrpc2.NewHeaderStream(os.Stdin, os.Stdout), jsonrpc2.Log)
-}

internal/jsonrpc2/jsonrpc2.go

@@ -13,6 +13,7 @@ import (
 	"fmt"
 	"sync"
 	"sync/atomic"
+	"time"
 )
 
 // Conn is a JSON RPC 2 client server connection.
@@ -47,10 +48,6 @@ type Handler = func(context.Context, *Conn, *Request) (interface{}, *Error)
 // instead.
 type Canceler = func(context.Context, *Conn, *Request)
 
-// Logger is an option you can pass to NewConn which is invoked for
-// all messages flowing through a Conn.
-type Logger = func(mode string, id *ID, method string, payload *json.RawMessage, err *Error)
-
 // NewErrorf builds a Error struct for the suppied message and code.
 // If args is not empty, message and args will be passed to Sprintf.
 func NewErrorf(code int64, format string, args ...interface{}) *Error {
@@ -102,7 +99,7 @@ func NewConn(ctx context.Context, s Stream, options ...interface{}) *Conn {
 	}
 	if conn.log == nil {
 		// the default logger does nothing
-		conn.log = func(string, *ID, string, *json.RawMessage, *Error) {}
+		conn.log = func(Direction, *ID, time.Duration, string, *json.RawMessage, *Error) {}
 	}
 	go func() {
 		conn.err = conn.run(ctx)
@@ -152,7 +149,7 @@ func (c *Conn) Notify(ctx context.Context, method string, params interface{}) er
 	if err != nil {
 		return fmt.Errorf("marshalling notify request: %v", err)
 	}
-	c.log("notify <=", nil, request.Method, request.Params, nil)
+	c.log(Send, nil, -1, request.Method, request.Params, nil)
 	return c.stream.Write(ctx, data)
 }
 
@@ -189,7 +186,8 @@ func (c *Conn) Call(ctx context.Context, method string, params, result interface
 		c.pendingMu.Unlock()
 	}()
 	// now we are ready to send
-	c.log("call <=", request.ID, request.Method, request.Params, nil)
+	before := time.Now()
+	c.log(Send, request.ID, -1, request.Method, request.Params, nil)
 	if err := c.stream.Write(ctx, data); err != nil {
 		// sending failed, we will never get a response, so don't leave it pending
 		return err
@@ -197,6 +195,8 @@ func (c *Conn) Call(ctx context.Context, method string, params, result interface
 	// now wait for the response
 	select {
 	case response := <-rchan:
+		elapsed := time.Since(before)
+		c.log(Send, response.ID, elapsed, request.Method, response.Result, response.Error)
 		// is it an error response?
 		if response.Error != nil {
 			return response.Error
@@ -243,7 +243,7 @@ func (c *Conn) run(ctx context.Context) error {
 		if err := json.Unmarshal(data, msg); err != nil {
 			// a badly formed message arrived, log it and continue
 			// we trust the stream to have isolated the error to just this message
-			c.log("read", nil, "", nil, NewErrorf(0, "unmarshal failed: %v", err))
+			c.log(Receive, nil, -1, "", nil, NewErrorf(0, "unmarshal failed: %v", err))
 			continue
 		}
 		// work out which kind of message we have
@@ -256,13 +256,13 @@ func (c *Conn) run(ctx context.Context) error {
 				ID:     msg.ID,
 			}
 			if request.IsNotify() {
-				c.log("notify =>", request.ID, request.Method, request.Params, nil)
+				c.log(Receive, request.ID, -1, request.Method, request.Params, nil)
 				// we have a Notify, forward to the handler in a go routine
 				go func() {
 					if _, err := c.handle(ctx, c, request); err != nil {
 						// notify produced an error, we can't forward it to the other side
 						// because there is no id, so we just log it
-						c.log("notify failed", nil, request.Method, nil, err)
+						c.log(Receive, nil, -1, request.Method, nil, err)
 					}
 				}()
 			} else {
@@ -279,8 +279,10 @@ func (c *Conn) run(ctx context.Context) error {
 						c.handlingMu.Unlock()
 						cancelReq()
 					}()
-					c.log("call =>", request.ID, request.Method, request.Params, nil)
+					c.log(Receive, request.ID, -1, request.Method, request.Params, nil)
+					before := time.Now()
 					resp, callErr := c.handle(reqCtx, c, request)
+					elapsed := time.Since(before)
 					var result *json.RawMessage
 					if result, err = marshalToRaw(resp); err != nil {
 						callErr = &Error{Message: err.Error()}
@@ -295,14 +297,14 @@ func (c *Conn) run(ctx context.Context) error {
 						// failure to marshal leaves the call without a response
 						// possibly we could attempt to respond with a different message
 						// but we can probably rely on timeouts instead
-						c.log("respond =!>", request.ID, request.Method, nil, NewErrorf(0, "%s", err))
+						c.log(Send, request.ID, elapsed, request.Method, nil, NewErrorf(0, "%s", err))
 						return
 					}
-					c.log("respond =>", response.ID, "", response.Result, response.Error)
+					c.log(Send, response.ID, elapsed, request.Method, response.Result, response.Error)
 					if err = c.stream.Write(ctx, data); err != nil {
 						// if a stream write fails, we really need to shut down the whole
 						// stream and return from the run
-						c.log("respond =!>", nil, request.Method, nil, NewErrorf(0, "%s", err))
+						c.log(Send, request.ID, elapsed, request.Method, nil, NewErrorf(0, "%s", err))
 						cancelRun()
 						return
 					}
@@ -322,11 +324,10 @@ func (c *Conn) run(ctx context.Context) error {
 				Error:  msg.Error,
 				ID:     msg.ID,
 			}
-			c.log("response =>", response.ID, "", response.Result, response.Error)
 			rchan <- response
 			close(rchan)
 		default:
-			c.log("invalid =>", nil, "", nil, NewErrorf(0, "message not a call, notify or response, ignoring"))
+			c.log(Receive, nil, -1, "", nil, NewErrorf(0, "message not a call, notify or response, ignoring"))
 		}
 	}
 }

internal/jsonrpc2/log.go

@@ -5,30 +5,55 @@
 package jsonrpc2
 
 import (
-	"bytes"
 	"encoding/json"
-	"fmt"
 	"log"
+	"time"
 )
 
+// Logger is an option you can pass to NewConn which is invoked for
+// all messages flowing through a Conn.
+// direction indicates if the message being recieved or sent
+// id is the message id, if not set it was a notification
+// elapsed is the time between a call being seen and the response, and is
+// negative for anything that is not a response.
+// method is the method name specified in the message
+// payload is the parameters for a call or notification, and the result for a
+// response
+type Logger = func(direction Direction, id *ID, elapsed time.Duration, method string, payload *json.RawMessage, err *Error)
+
+// Direction is used to indicate to a logger whether the logged message was being
+// sent or received.
+type Direction bool
+
+const (
+	// Send indicates the message is outgoing.
+	Send = Direction(true)
+	// Receive indicates the message is incoming.
+	Receive = Direction(false)
+)
+
+func (d Direction) String() string {
+	switch d {
+	case Send:
+		return "send"
+	case Receive:
+		return "receive"
+	default:
+		panic("unreachable")
+	}
+}
+
 // Log is an implementation of Logger that outputs using log.Print
 // It is not used by default, but is provided for easy logging in users code.
-func Log(mode string, id *ID, method string, payload *json.RawMessage, err *Error) {
+func Log(direction Direction, id *ID, elapsed time.Duration, method string, payload *json.RawMessage, err *Error) {
-	buf := &bytes.Buffer{}
+	switch {
-	fmt.Fprint(buf, mode)
+	case err != nil:
-	if id == nil {
+		log.Printf("%v failure [%v] %s %v", direction, id, method, err)
-		fmt.Fprintf(buf, " []")
+	case id == nil:
-	} else {
+		log.Printf("%v notification %s %s", direction, method, *payload)
-		fmt.Fprintf(buf, " [%v]", id)
+	case elapsed >= 0:
+		log.Printf("%v response in %v [%v] %s %s", direction, elapsed, id, method, *payload)
+	default:
+		log.Printf("%v call [%v] %s %s", direction, id, method, *payload)
 	}
-	if method != "" {
-		fmt.Fprintf(buf, " %s", method)
-	}
-	if payload != nil {
-		fmt.Fprintf(buf, " %s", *payload)
-	}
-	if err != nil {
-		fmt.Fprintf(buf, " failed: %s", err)
-	}
-	log.Print(buf)
 }

internal/jsonrpc2/wire.go

@@ -114,6 +114,9 @@ func (VersionTag) UnmarshalJSON(data []byte) error {
 // The representation is non ambiguous, string forms are quoted, number forms
 // are preceded by a #
 func (id *ID) String() string {
+	if id == nil {
+		return ""
+	}
 	if id.Name != "" {
 		return strconv.Quote(id.Name)
 	}