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>
diff --git a/cmd/golsp/main.go b/cmd/golsp/main.go
index 161e5f9..ce619ae 100644
--- a/cmd/golsp/main.go
+++ b/cmd/golsp/main.go
@@ -10,6 +10,7 @@
import (
"context"
+ "encoding/json"
"flag"
"fmt"
"io"
@@ -18,6 +19,7 @@
"runtime"
"runtime/pprof"
"runtime/trace"
+ "time"
"golang.org/x/tools/internal/jsonrpc2"
"golang.org/x/tools/internal/lsp"
@@ -86,6 +88,7 @@
}()
}
+ out := os.Stderr
if *logfile != "" {
f, err := os.Create(*logfile)
if err != nil {
@@ -93,12 +96,52 @@
}
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)
-}
diff --git a/internal/jsonrpc2/jsonrpc2.go b/internal/jsonrpc2/jsonrpc2.go
index f981e86..fd38f64 100644
--- a/internal/jsonrpc2/jsonrpc2.go
+++ b/internal/jsonrpc2/jsonrpc2.go
@@ -13,6 +13,7 @@
"fmt"
"sync"
"sync/atomic"
+ "time"
)
// Conn is a JSON RPC 2 client server connection.
@@ -47,10 +48,6 @@
// 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 @@
}
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 @@
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 @@
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 @@
// 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 @@
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 @@
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 @@
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 @@
// 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 @@
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"))
}
}
}
diff --git a/internal/jsonrpc2/log.go b/internal/jsonrpc2/log.go
index 3dbde8f..f0e8c7f 100644
--- a/internal/jsonrpc2/log.go
+++ b/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) {
- buf := &bytes.Buffer{}
- fmt.Fprint(buf, mode)
- if id == nil {
- fmt.Fprintf(buf, " []")
- } else {
- fmt.Fprintf(buf, " [%v]", id)
+func Log(direction Direction, id *ID, elapsed time.Duration, method string, payload *json.RawMessage, err *Error) {
+ switch {
+ case err != nil:
+ log.Printf("%v failure [%v] %s %v", direction, id, method, err)
+ case id == nil:
+ log.Printf("%v notification %s %s", direction, method, *payload)
+ 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)
}
diff --git a/internal/jsonrpc2/wire.go b/internal/jsonrpc2/wire.go
index 3ff0c38..bb59ad5 100644
--- a/internal/jsonrpc2/wire.go
+++ b/internal/jsonrpc2/wire.go
@@ -114,6 +114,9 @@
// 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)
}
