blob: 1bb5c27fc0f13056c897be32ade29c1ff0f4834a [file] [log] [blame]
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()))
}