[clangd] Add index server request logging

- Add verbose logging of payloads
- Add public logging of request summaries
- fix non-logging of messages in request scopes (oops!)
- add test for public/non-public logging, extending pipeline_helper a bit.

We've accumulated quite a lot of duplication in the request handlers by now.
I should factor that out, but not in this patch...

Differential Revision: https://reviews.llvm.org/D90654

Author: sam-mccall

clang-tools-extra/clangd/index/remote/server/Server.cpp

@@ -94,10 +94,14 @@ class RemoteIndexServer final : public v1::SymbolIndex::Service {
   }
 
 private:
+  using stopwatch = std::chrono::steady_clock;
+
   grpc::Status Lookup(grpc::ServerContext *Context,
                       const LookupRequest *Request,
                       grpc::ServerWriter<LookupReply> *Reply) override {
-    WithContextValue(CurrentRequest, Context);
+    auto StartTime = stopwatch::now();
+    WithContextValue WithRequestContext(CurrentRequest, Context);
+    logRequest(*Request);
     trace::Span Tracer("LookupRequest");
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
@@ -116,21 +120,26 @@ class RemoteIndexServer final : public v1::SymbolIndex::Service {
       }
       LookupReply NextMessage;
       *NextMessage.mutable_stream_result() = *SerializedItem;
+      logResponse(NextMessage);
       Reply->Write(NextMessage);
       ++Sent;
     });
     LookupReply LastMessage;
     LastMessage.mutable_final_result()->set_has_more(true);
+    logResponse(LastMessage);
     Reply->Write(LastMessage);
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+    logRequestSummary("v1/Lookup", Sent, StartTime);
     return grpc::Status::OK;
   }
 
   grpc::Status FuzzyFind(grpc::ServerContext *Context,
                          const FuzzyFindRequest *Request,
                          grpc::ServerWriter<FuzzyFindReply> *Reply) override {
-    WithContextValue(CurrentRequest, Context);
+    auto StartTime = stopwatch::now();
+    WithContextValue WithRequestContext(CurrentRequest, Context);
+    logRequest(*Request);
     trace::Span Tracer("FuzzyFindRequest");
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
@@ -150,20 +159,25 @@ class RemoteIndexServer final : public v1::SymbolIndex::Service {
       }
       FuzzyFindReply NextMessage;
       *NextMessage.mutable_stream_result() = *SerializedItem;
+      logResponse(NextMessage);
       Reply->Write(NextMessage);
       ++Sent;
     });
     FuzzyFindReply LastMessage;
     LastMessage.mutable_final_result()->set_has_more(HasMore);
+    logResponse(LastMessage);
     Reply->Write(LastMessage);
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+    logRequestSummary("v1/FuzzyFind", Sent, StartTime);
     return grpc::Status::OK;
   }
 
   grpc::Status Refs(grpc::ServerContext *Context, const RefsRequest *Request,
                     grpc::ServerWriter<RefsReply> *Reply) override {
-    WithContextValue(CurrentRequest, Context);
+    auto StartTime = stopwatch::now();
+    WithContextValue WithRequestContext(CurrentRequest, Context);
+    logRequest(*Request);
     trace::Span Tracer("RefsRequest");
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
@@ -182,21 +196,26 @@ class RemoteIndexServer final : public v1::SymbolIndex::Service {
       }
       RefsReply NextMessage;
       *NextMessage.mutable_stream_result() = *SerializedItem;
+      logResponse(NextMessage);
       Reply->Write(NextMessage);
       ++Sent;
     });
     RefsReply LastMessage;
     LastMessage.mutable_final_result()->set_has_more(HasMore);
+    logResponse(LastMessage);
     Reply->Write(LastMessage);
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+    logRequestSummary("v1/Refs", Sent, StartTime);
     return grpc::Status::OK;
   }
 
   grpc::Status Relations(grpc::ServerContext *Context,
                          const RelationsRequest *Request,
                          grpc::ServerWriter<RelationsReply> *Reply) override {
-    WithContextValue(CurrentRequest, Context);
+    auto StartTime = stopwatch::now();
+    WithContextValue WithRequestContext(CurrentRequest, Context);
+    logRequest(*Request);
     trace::Span Tracer("RelationsRequest");
     auto Req = ProtobufMarshaller->fromProtobuf(Request);
     if (!Req) {
@@ -217,17 +236,44 @@ class RemoteIndexServer final : public v1::SymbolIndex::Service {
           }
           RelationsReply NextMessage;
           *NextMessage.mutable_stream_result() = *SerializedItem;
+          logResponse(NextMessage);
           Reply->Write(NextMessage);
           ++Sent;
         });
     RelationsReply LastMessage;
     LastMessage.mutable_final_result()->set_has_more(true);
+    logResponse(LastMessage);
     Reply->Write(LastMessage);
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
+    logRequestSummary("v1/Relations", Sent, StartTime);
     return grpc::Status::OK;
   }
 
+  // Proxy object to allow proto messages to be lazily serialized as text.
+  struct TextProto {
+    const google::protobuf::Message &M;
+    friend llvm::raw_ostream &operator<<(llvm::raw_ostream &OS,
+                                         const TextProto &P) {
+      return OS << P.M.DebugString();
+    }
+  };
+
+  void logRequest(const google::protobuf::Message &M) {
+    vlog("<<< {0}\n{1}", M.GetDescriptor()->name(), TextProto{M});
+  }
+  void logResponse(const google::protobuf::Message &M) {
+    vlog(">>> {0}\n{1}", M.GetDescriptor()->name(), TextProto{M});
+  }
+  void logRequestSummary(llvm::StringLiteral RequestName, unsigned Sent,
+                         stopwatch::time_point StartTime) {
+    auto Duration = stopwatch::now() - StartTime;
+    auto Millis =
+        std::chrono::duration_cast<std::chrono::milliseconds>(Duration).count();
+    log("[public] request {0} => OK: {1} results in {2}ms", RequestName, Sent,
+        Millis);
+  }
+
   std::unique_ptr<Marshaller> ProtobufMarshaller;
   clangd::SymbolIndex &Index;
 };

clang-tools-extra/clangd/test/remote-index/pipeline_helper.py

@@ -28,6 +28,8 @@ def main():
   parser.add_argument('--input-file-name', required=True)
   parser.add_argument('--project-root', required=True)
   parser.add_argument('--index-file', required=True)
+  parser.add_argument('--server-arg', action='append', default=[])
+  parser.add_argument('--server-log', nargs='?', type=argparse.FileType('wb'), default=os.devnull)
 
   args = parser.parse_args()
 
@@ -40,7 +42,7 @@ def main():
   index_server_process = subprocess.Popen([
       'clangd-index-server', '--server-address=' + server_address,
       args.index_file, args.project_root
-  ],
+  ] + args.server_arg,
                                           stderr=subprocess.PIPE)
 
   # This will kill index_server_process if it hangs without printing init
@@ -53,7 +55,10 @@ def main():
   # Wait for the server to warm-up.
   found_init_message = False
   while index_server_process.poll() is None:
-    if b'Server listening' in index_server_process.stderr.readline():
+    line = index_server_process.stderr.readline()
+    args.server_log.write(line)
+    args.server_log.flush()
+    if b'Server listening' in line:
       print('Server initialization complete.', file=sys.stderr)
       found_init_message = True
       break
@@ -70,12 +75,14 @@ def main():
       '--project-root=' + args.project_root, '--lit-test', '--sync'
   ],
                                     stdin=in_file)
-
   clangd_process.wait()
   print(
       'Clangd executed successfully, shutting down child processes.',
       file=sys.stderr)
   index_server_process.kill()
+  for line in index_server_process.stderr:
+    args.server_log.write(line)
+    args.server_log.flush()
 
 
 if __name__ == '__main__':

clang-tools-extra/clangd/test/remote-index/public-log.test

@@ -0,0 +1,26 @@
+# RUN: rm -rf %t
+# RUN: clangd-indexer %S/Inputs/Source.cpp > %t.idx
+# RUN: %python %S/pipeline_helper.py --input-file-name=%s --server-arg=--log=verbose --server-arg=-log-public --server-log=%t.public.log --project-root=%S --index-file=%t.idx > /dev/null
+# RUN: %python %S/pipeline_helper.py --input-file-name=%s --server-arg=--log=verbose --server-log=%t.log --project-root=%S --index-file=%t.idx > /dev/null
+# RUN: FileCheck --check-prefixes=LOG,LOG-PUBLIC %s < %t.public.log
+# RUN: FileCheck --check-prefixes=LOG,LOG-ALL %s < %t.log
+# REQUIRES: clangd-remote-index
+
+# LOG: Server listening on
+{"jsonrpc":"2.0","id":0,"method":"initialize","params":{"processId":123,"rootPath":"clangd","capabilities":{},"trace":"off"}}
+---
+# Verify that request and response bodies are included in the verbose logs,
+# but not when --log-public is on.
+# The request summary should be included in either case.
+{"jsonrpc":"2.0","id":1,"method":"workspace/symbol","params":{"query":"gFoo"}}
+# LOG-ALL: <<< FuzzyFindRequest
+# LOG-ALL: query: "gFoo"
+# LOG-ALL: >>> FuzzyFindReply
+# LOG-ALL: name: "getFoo"
+# LOG-PUBLIC-NOT: gFoo
+# LOG-PUBLIC-NOT: getFoo
+# LOG: request v1/FuzzyFind => OK: 1 results in {{.*}}ms
+---
+{"jsonrpc":"2.0","id":4,"method":"shutdown"}
+---
+{"jsonrpc":"2.0","method":"exit"}