[clangd] log request/response messages with method/ID/error at INFO level

[sammccall]

Summary

Bodies are logged at VERBOSE level (since r336785), tweak the formatting.

[hokein]

LGTM.

clangd/JSONRPCDispatcher.cpp

138

nit I'd suggest putting this statement immediately after the above FIXME, it took me a while to understand why it is 1.

clangd/JSONRPCDispatcher.cpp

else
     OS << Message;
   OS.flush();
 
   {
     std::lock_guard<std::mutex> Guard(StreamMutex);
     Outs << "Content-Length: " << S.size() << "\r\n\r\n" << S;
     Outs.flush();
   }
-  vlog("--> {0}\n", S);
+  vlog(">>> {0}\n", S);
 }
 
 void JSONOutput::log(Logger::Level Level,
                      const llvm::formatv_object_base &Message) {
   if (Level < MinLevel)
     return;
   llvm::sys::TimePoint<> Timestamp = std::chrono::system_clock::now();
   trace::log(Message);

 
 void clangd::reply(json::Value &&Result) {
   auto ID = Context::current().get(RequestID);
   if (!ID) {
     elog("Attempted to reply to a notification!");
     return;
   }
   RequestSpan::attach([&](json::Object &Args) { Args["Reply"] = Result; });
+  log("--> reply({0})", *ID);
   Context::current()
       .getExisting(RequestOut)
       ->writeMessage(json::Object{
           {"jsonrpc", "2.0"},
           {"id", *ID},
           {"result", std::move(Result)},
       });
 }
 
 void clangd::replyError(ErrorCode code, const llvm::StringRef &Message) {
   elog("Error {0}: {1}", static_cast<int>(code), Message);
   RequestSpan::attach([&](json::Object &Args) {
     Args["Error"] = json::Object{{"code", static_cast<int>(code)},
                                  {"message", Message.str()}};
   });
 
   if (auto ID = Context::current().get(RequestID)) {
+    log("--> reply({0}) error: {1}", *ID, Message);
     Context::current()
         .getExisting(RequestOut)
         ->writeMessage(json::Object{
             {"jsonrpc", "2.0"},
             {"id", *ID},
             {"error", json::Object{{"code", static_cast<int>(code)},
                                    {"message", Message}}},
         });
   }
 }
 
 void clangd::call(StringRef Method, json::Value &&Params) {
   // FIXME: Generate/Increment IDs for every request so that we can get proper
   // replies once we need to.
   RequestSpan::attach([&](json::Object &Args) {
     Args["Call"] = json::Object{{"method", Method.str()}, {"params", Params}};
   });
+  auto ID = 1;
+  log("--> {0}({1})", Method, ID);
   Context::current()
       .getExisting(RequestOut)
       ->writeMessage(json::Object{
           {"jsonrpc", "2.0"},
-          {"id", 1},
+          {"id", ID},
           {"method", Method},
           {"params", std::move(Params)},
       });
 }
 
 void JSONRPCDispatcher::registerHandler(StringRef Method, Handler H) {
   assert(!Handlers.count(Method) && "Handler already registered!");
   Handlers[Method] = std::move(H);
 }
 
+static void logIncomingMessage(const llvm::Optional<json::Value> &ID,
+                               llvm::Optional<StringRef> Method,
+                               const json::Object *Error) {
+  if (Method) { // incoming request
+    if (ID)     // call
+      log("<-- {0}({1})", *Method, *ID);
+    else // notification
+      log("<-- {0}", *Method);
+  } else if (ID) { // response, ID must be provided
+    if (Error)
+      log("<-- reply({0}) error: {1}", *ID,
+          Error->getString("message").getValueOr("<no message>"));
+    else
+      log("<-- reply({0})", *ID);
+  }
+}
+
 bool JSONRPCDispatcher::call(const json::Value &Message,
                              JSONOutput &Out) const {
   // Message must be an object with "jsonrpc":"2.0".
   auto *Object = Message.getAsObject();
   if (!Object || Object->getString("jsonrpc") != Optional<StringRef>("2.0"))
     return false;
   // ID may be any JSON value. If absent, this is a notification.
   llvm::Optional<json::Value> ID;
   if (auto *I = Object->get("id"))
     ID = std::move(*I);
-  // Method must be given.
   auto Method = Object->getString("method");
-  if (!Method)
+  logIncomingMessage(ID, Method, Object->getObject("error"));
+  if (!Method) // We only handle incoming requests, and ignore responses.
     return false;
   // Params should be given, use null if not.
   json::Value Params = nullptr;
   if (auto *P = Object->get("params"))
     Params = std::move(*P);
 
   auto I = Handlers.find(*Method);
   auto &Handler = I != Handlers.end() ? I->second : UnknownHandler;
void clangd::runLanguageServerLoop(std::FILE *In, JSONOutput &Out,
   while (!IsDone && !feof(In)) {
     if (ferror(In)) {
       elog("IO error: {0}", llvm::sys::StrError());
       return;
     }
     if (auto JSON = ReadMessage(In, Out)) {
       if (auto Doc = json::parse(*JSON)) {
         // Log the formatted message.
-        vlog(Out.Pretty ? "<-- {0:2}\n" : "<-- {0}\n", *Doc);
+        vlog(Out.Pretty ? "<<< {0:2}\n" : "<<< {0}\n", *Doc);
         // Finally, execute the action for this JSON message.
         if (!Dispatcher.call(*Doc, Out))
           elog("JSON dispatch failed!");
       } else {
         // Parse error. Log the raw message.
-        vlog("<-- {0}\n", *JSON);
+        vlog("<<< {0}\n", *JSON);
         elog("JSON parse error: {0}", llvm::toString(Doc.takeError()));
       }
     }
   }
 }