diff --git a/cmd/golsp/main.go b/cmd/golsp/main.go index 161e5f9e..ce619ae1 100644 --- a/cmd/golsp/main.go +++ b/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) -} diff --git a/internal/jsonrpc2/jsonrpc2.go b/internal/jsonrpc2/jsonrpc2.go index f981e868..fd38f643 100644 --- a/internal/jsonrpc2/jsonrpc2.go +++ b/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")) } } } diff --git a/internal/jsonrpc2/log.go b/internal/jsonrpc2/log.go index 3dbde8f7..f0e8c7f2 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 3ff0c384..bb59ad55 100644 --- a/internal/jsonrpc2/wire.go +++ b/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) }