package protocol import ( "context" "encoding/json" "fmt" "io" "strings" "sync" "time" "golang.org/x/tools/internal/jsonrpc2" ) type loggingStream struct { stream jsonrpc2.Stream log io.Writer } // LoggingStream returns a stream that does LSP protocol logging too func LoggingStream(str jsonrpc2.Stream, w io.Writer) jsonrpc2.Stream { return &loggingStream{str, w} } func (s *loggingStream) Read(ctx context.Context) ([]byte, int64, error) { data, count, err := s.stream.Read(ctx) if err == nil { logIn(s.log, data) } return data, count, err } func (s *loggingStream) Write(ctx context.Context, data []byte) (int64, error) { logOut(s.log, data) count, err := s.stream.Write(ctx, data) return count, err } // Combined has all the fields of both Request and Response. // We can decode this and then work out which it is. type Combined struct { VersionTag jsonrpc2.VersionTag `json:"jsonrpc"` ID *jsonrpc2.ID `json:"id,omitempty"` Method string `json:"method"` Params *json.RawMessage `json:"params,omitempty"` Result *json.RawMessage `json:"result,omitempty"` Error *jsonrpc2.Error `json:"error,omitempty"` } type req struct { method string start time.Time } type mapped struct { mu sync.Mutex clientCalls map[string]req serverCalls map[string]req } var maps = &mapped{ sync.Mutex{}, make(map[string]req), make(map[string]req), } // these 4 methods are each used exactly once, but it seemed // better to have the encapsulation rather than ad hoc mutex // code in 4 places func (m *mapped) client(id string, del bool) req { m.mu.Lock() defer m.mu.Unlock() v := m.clientCalls[id] if del { delete(m.clientCalls, id) } return v } func (m *mapped) server(id string, del bool) req { m.mu.Lock() defer m.mu.Unlock() v := m.serverCalls[id] if del { delete(m.serverCalls, id) } return v } func (m *mapped) setClient(id string, r req) { m.mu.Lock() defer m.mu.Unlock() m.clientCalls[id] = r } func (m *mapped) setServer(id string, r req) { m.mu.Lock() defer m.mu.Unlock() m.serverCalls[id] = r } const eor = "\r\n\r\n\r\n" func strID(x *jsonrpc2.ID) string { if x == nil { // should never happen, but we need a number return "999999999" } if x.Name != "" { return x.Name } return fmt.Sprintf("%d", x.Number) } func logCommon(outfd io.Writer, data []byte) (*Combined, time.Time, string) { if outfd == nil { return nil, time.Time{}, "" } var v Combined err := json.Unmarshal(data, &v) if err != nil { fmt.Fprintf(outfd, "Unmarshal %v\n", err) panic(err) // do better } tm := time.Now() tmfmt := tm.Format("15:04:05.000 PM") return &v, tm, tmfmt } // logOut and logIn could be combined. "received"<->"Sending", serverCalls<->clientCalls // but it wouldn't be a lot shorter or clearer and "shutdown" is a special case // Writing a message to the client, log it func logOut(outfd io.Writer, data []byte) { v, tm, tmfmt := logCommon(outfd, data) if v == nil { return } if v.Error != nil { id := strID(v.ID) fmt.Fprintf(outfd, "[Error - %s] Received #%s %s%s", tmfmt, id, v.Error, eor) return } buf := strings.Builder{} id := strID(v.ID) fmt.Fprintf(&buf, "[Trace - %s] ", tmfmt) // common beginning if v.ID != nil && v.Method != "" && v.Params != nil { fmt.Fprintf(&buf, "Received request '%s - (%s)'.\n", v.Method, id) fmt.Fprintf(&buf, "Params: %s%s", *v.Params, eor) maps.setServer(id, req{method: v.Method, start: tm}) } else if v.ID != nil && v.Method == "" && v.Params == nil { cc := maps.client(id, true) elapsed := tm.Sub(cc.start) fmt.Fprintf(&buf, "Received response '%s - (%s)' in %dms.\n", cc.method, id, elapsed/time.Millisecond) if v.Result == nil { fmt.Fprintf(&buf, "Result: {}%s", eor) } else { fmt.Fprintf(&buf, "Result: %s%s", string(*v.Result), eor) } } else if v.ID == nil && v.Method != "" && v.Params != nil { p := "null" if v.Params != nil { p = string(*v.Params) } fmt.Fprintf(&buf, "Received notification '%s'.\n", v.Method) fmt.Fprintf(&buf, "Params: %s%s", p, eor) } else { // for completeness, as it should never happen buf = strings.Builder{} // undo common Trace fmt.Fprintf(&buf, "[Error - %s] on write ID?%v method:%q Params:%v Result:%v Error:%v%s", tmfmt, v.ID != nil, v.Method, v.Params != nil, v.Result != nil, v.Error != nil, eor) p := "null" if v.Params != nil { p = string(*v.Params) } r := "null" if v.Result != nil { r = string(*v.Result) } fmt.Fprintf(&buf, "%s\n%s\n%s%s", p, r, v.Error, eor) } outfd.Write([]byte(buf.String())) } // Got a message from the client, log it func logIn(outfd io.Writer, data []byte) { v, tm, tmfmt := logCommon(outfd, data) if v == nil { return } // ID Method Params => Sending request // ID !Method Result(might be null, but !Params) => Sending response (could we get an Error?) // !ID Method Params => Sending notification if v.Error != nil { // does this ever happen? id := strID(v.ID) fmt.Fprintf(outfd, "[Error - %s] Sent #%s %s%s", tmfmt, id, v.Error, eor) return } buf := strings.Builder{} id := strID(v.ID) fmt.Fprintf(&buf, "[Trace - %s] ", tmfmt) // common beginning if v.ID != nil && v.Method != "" && (v.Params != nil || v.Method == "shutdown") { fmt.Fprintf(&buf, "Sending request '%s - (%s)'.\n", v.Method, id) x := "{}" if v.Params != nil { x = string(*v.Params) } fmt.Fprintf(&buf, "Params: %s%s", x, eor) maps.setClient(id, req{method: v.Method, start: tm}) } else if v.ID != nil && v.Method == "" && v.Params == nil { sc := maps.server(id, true) elapsed := tm.Sub(sc.start) fmt.Fprintf(&buf, "Sending response '%s - (%s)' took %dms.\n", sc.method, id, elapsed/time.Millisecond) if v.Result == nil { fmt.Fprintf(&buf, "Result: {}%s", eor) } else { fmt.Fprintf(&buf, "Result: %s%s", string(*v.Result), eor) } } else if v.ID == nil && v.Method != "" { p := "null" if v.Params != nil { p = string(*v.Params) } fmt.Fprintf(&buf, "Sending notification '%s'.\n", v.Method) fmt.Fprintf(&buf, "Params: %s%s", p, eor) } else { // for completeness, as it should never happen buf = strings.Builder{} // undo common Trace fmt.Fprintf(&buf, "[Error - %s] on read ID?%v method:%q Params:%v Result:%v Error:%v%s", tmfmt, v.ID != nil, v.Method, v.Params != nil, v.Result != nil, v.Error != nil, eor) p := "null" if v.Params != nil { p = string(*v.Params) } r := "null" if v.Result != nil { r = string(*v.Result) } fmt.Fprintf(&buf, "%s\n%s\n%s%s", p, r, v.Error, eor) } outfd.Write([]byte(buf.String())) }