1// Copyright 2018 The Go Authors. 2// 3// Licensed under the Apache License, Version 2.0 (the "License"); 4// you may not use this file except in compliance with the License. 5// You may obtain a copy of the License at 6// 7// http://www.apache.org/licenses/LICENSE-2.0 8// 9// Unless required by applicable law or agreed to in writing, software 10// distributed under the License is distributed on an "AS IS" BASIS, 11// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 12// See the License for the specific language governing permissions and 13// limitations under the License. 14 15package protocol 16 17import ( 18 "context" 19 "encoding/json" 20 "fmt" 21 "io" 22 "strings" 23 "sync" 24 "time" 25 26 "github.com/KhronosGroup/SPIRV-Tools/utils/vscode/src/lsp/jsonrpc2" 27) 28 29type loggingStream struct { 30 stream jsonrpc2.Stream 31 log io.Writer 32} 33 34// LoggingStream returns a stream that does LSP protocol logging too 35func LoggingStream(str jsonrpc2.Stream, w io.Writer) jsonrpc2.Stream { 36 return &loggingStream{str, w} 37} 38 39func (s *loggingStream) Read(ctx context.Context) ([]byte, int64, error) { 40 data, count, err := s.stream.Read(ctx) 41 if err == nil { 42 logIn(s.log, data) 43 } 44 return data, count, err 45} 46 47func (s *loggingStream) Write(ctx context.Context, data []byte) (int64, error) { 48 logOut(s.log, data) 49 count, err := s.stream.Write(ctx, data) 50 return count, err 51} 52 53// Combined has all the fields of both Request and Response. 54// We can decode this and then work out which it is. 55type Combined struct { 56 VersionTag jsonrpc2.VersionTag `json:"jsonrpc"` 57 ID *jsonrpc2.ID `json:"id,omitempty"` 58 Method string `json:"method"` 59 Params *json.RawMessage `json:"params,omitempty"` 60 Result *json.RawMessage `json:"result,omitempty"` 61 Error *jsonrpc2.Error `json:"error,omitempty"` 62} 63 64type req struct { 65 method string 66 start time.Time 67} 68 69type mapped struct { 70 mu sync.Mutex 71 clientCalls map[string]req 72 serverCalls map[string]req 73} 74 75var maps = &mapped{ 76 sync.Mutex{}, 77 make(map[string]req), 78 make(map[string]req), 79} 80 81// these 4 methods are each used exactly once, but it seemed 82// better to have the encapsulation rather than ad hoc mutex 83// code in 4 places 84func (m *mapped) client(id string, del bool) req { 85 m.mu.Lock() 86 defer m.mu.Unlock() 87 v := m.clientCalls[id] 88 if del { 89 delete(m.clientCalls, id) 90 } 91 return v 92} 93 94func (m *mapped) server(id string, del bool) req { 95 m.mu.Lock() 96 defer m.mu.Unlock() 97 v := m.serverCalls[id] 98 if del { 99 delete(m.serverCalls, id) 100 } 101 return v 102} 103 104func (m *mapped) setClient(id string, r req) { 105 m.mu.Lock() 106 defer m.mu.Unlock() 107 m.clientCalls[id] = r 108} 109 110func (m *mapped) setServer(id string, r req) { 111 m.mu.Lock() 112 defer m.mu.Unlock() 113 m.serverCalls[id] = r 114} 115 116const eor = "\r\n\r\n\r\n" 117 118func strID(x *jsonrpc2.ID) string { 119 if x == nil { 120 // should never happen, but we need a number 121 return "999999999" 122 } 123 if x.Name != "" { 124 return x.Name 125 } 126 return fmt.Sprintf("%d", x.Number) 127} 128 129func logCommon(outfd io.Writer, data []byte) (*Combined, time.Time, string) { 130 if outfd == nil { 131 return nil, time.Time{}, "" 132 } 133 var v Combined 134 err := json.Unmarshal(data, &v) 135 if err != nil { 136 fmt.Fprintf(outfd, "Unmarshal %v\n", err) 137 panic(err) // do better 138 } 139 tm := time.Now() 140 tmfmt := tm.Format("15:04:05.000 PM") 141 return &v, tm, tmfmt 142} 143 144// logOut and logIn could be combined. "received"<->"Sending", serverCalls<->clientCalls 145// but it wouldn't be a lot shorter or clearer and "shutdown" is a special case 146 147// Writing a message to the client, log it 148func logOut(outfd io.Writer, data []byte) { 149 v, tm, tmfmt := logCommon(outfd, data) 150 if v == nil { 151 return 152 } 153 if v.Error != nil { 154 id := strID(v.ID) 155 fmt.Fprintf(outfd, "[Error - %s] Received #%s %s%s", tmfmt, id, v.Error, eor) 156 return 157 } 158 buf := strings.Builder{} 159 id := strID(v.ID) 160 fmt.Fprintf(&buf, "[Trace - %s] ", tmfmt) // common beginning 161 if v.ID != nil && v.Method != "" && v.Params != nil { 162 fmt.Fprintf(&buf, "Received request '%s - (%s)'.\n", v.Method, id) 163 fmt.Fprintf(&buf, "Params: %s%s", *v.Params, eor) 164 maps.setServer(id, req{method: v.Method, start: tm}) 165 } else if v.ID != nil && v.Method == "" && v.Params == nil { 166 cc := maps.client(id, true) 167 elapsed := tm.Sub(cc.start) 168 fmt.Fprintf(&buf, "Received response '%s - (%s)' in %dms.\n", 169 cc.method, id, elapsed/time.Millisecond) 170 if v.Result == nil { 171 fmt.Fprintf(&buf, "Result: {}%s", eor) 172 } else { 173 fmt.Fprintf(&buf, "Result: %s%s", string(*v.Result), eor) 174 } 175 } else if v.ID == nil && v.Method != "" && v.Params != nil { 176 p := "null" 177 if v.Params != nil { 178 p = string(*v.Params) 179 } 180 fmt.Fprintf(&buf, "Received notification '%s'.\n", v.Method) 181 fmt.Fprintf(&buf, "Params: %s%s", p, eor) 182 } else { // for completeness, as it should never happen 183 buf = strings.Builder{} // undo common Trace 184 fmt.Fprintf(&buf, "[Error - %s] on write ID?%v method:%q Params:%v Result:%v Error:%v%s", 185 tmfmt, v.ID != nil, v.Method, v.Params != nil, 186 v.Result != nil, v.Error != nil, eor) 187 p := "null" 188 if v.Params != nil { 189 p = string(*v.Params) 190 } 191 r := "null" 192 if v.Result != nil { 193 r = string(*v.Result) 194 } 195 fmt.Fprintf(&buf, "%s\n%s\n%s%s", p, r, v.Error, eor) 196 } 197 outfd.Write([]byte(buf.String())) 198} 199 200// Got a message from the client, log it 201func logIn(outfd io.Writer, data []byte) { 202 v, tm, tmfmt := logCommon(outfd, data) 203 if v == nil { 204 return 205 } 206 // ID Method Params => Sending request 207 // ID !Method Result(might be null, but !Params) => Sending response (could we get an Error?) 208 // !ID Method Params => Sending notification 209 if v.Error != nil { // does this ever happen? 210 id := strID(v.ID) 211 fmt.Fprintf(outfd, "[Error - %s] Sent #%s %s%s", tmfmt, id, v.Error, eor) 212 return 213 } 214 buf := strings.Builder{} 215 id := strID(v.ID) 216 fmt.Fprintf(&buf, "[Trace - %s] ", tmfmt) // common beginning 217 if v.ID != nil && v.Method != "" && (v.Params != nil || v.Method == "shutdown") { 218 fmt.Fprintf(&buf, "Sending request '%s - (%s)'.\n", v.Method, id) 219 x := "{}" 220 if v.Params != nil { 221 x = string(*v.Params) 222 } 223 fmt.Fprintf(&buf, "Params: %s%s", x, eor) 224 maps.setClient(id, req{method: v.Method, start: tm}) 225 } else if v.ID != nil && v.Method == "" && v.Params == nil { 226 sc := maps.server(id, true) 227 elapsed := tm.Sub(sc.start) 228 fmt.Fprintf(&buf, "Sending response '%s - (%s)' took %dms.\n", 229 sc.method, id, elapsed/time.Millisecond) 230 if v.Result == nil { 231 fmt.Fprintf(&buf, "Result: {}%s", eor) 232 } else { 233 fmt.Fprintf(&buf, "Result: %s%s", string(*v.Result), eor) 234 } 235 } else if v.ID == nil && v.Method != "" { 236 p := "null" 237 if v.Params != nil { 238 p = string(*v.Params) 239 } 240 fmt.Fprintf(&buf, "Sending notification '%s'.\n", v.Method) 241 fmt.Fprintf(&buf, "Params: %s%s", p, eor) 242 } else { // for completeness, as it should never happen 243 buf = strings.Builder{} // undo common Trace 244 fmt.Fprintf(&buf, "[Error - %s] on read ID?%v method:%q Params:%v Result:%v Error:%v%s", 245 tmfmt, v.ID != nil, v.Method, v.Params != nil, 246 v.Result != nil, v.Error != nil, eor) 247 p := "null" 248 if v.Params != nil { 249 p = string(*v.Params) 250 } 251 r := "null" 252 if v.Result != nil { 253 r = string(*v.Result) 254 } 255 fmt.Fprintf(&buf, "%s\n%s\n%s%s", p, r, v.Error, eor) 256 } 257 outfd.Write([]byte(buf.String())) 258} 259