[clangd] Add index server request logging

[sammccall]

Summary

• 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...

[kbobyrev]

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

257

nit: everything is public by default since it's struct, right? did you mean to put &M behind private?

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

25

nit: PEP is against having <2 lines between functions :(

31

Why do we need wb here instead of w? I know that subprocess.Popen writes binary data but since we're writing actual text to file maybe we could convert to non-binary?

81

this was pipeline_helper.py intended for pipeline.test, maybe we'll use it more so makes sense to rename it to just helper.py or somethting.

[kadircet]

I wish there was an easy way to check redacted error logs too :/

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

335

feels like this one, and the one below are residues?

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

2

nit: use %/S to not mix forward and backslashes.

3

not sure if it is any easier, but it might make sense to just pass anything after -- to server, rather than explicitly mentioning --server-arg before each one. I suppose we can also rename the script to server_request_helper ?

This won't work if we decide to pass arbitrary client flags too though.

6

can you also add a check for TextProto printing ? I believe descriptor names should be enough.

[ArcsinX]

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

43

this breaks remote-index/pipeline.test test for me:

TypeError: can only concatenate list (not "NoneType") to list

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

5

Maybe we can use --input-file option of FileCheck instead of < (the same for the next line)

[sammccall]

Oops, took a while to get back to this.
Planning to land this with some style unaddressed (%/S, --input-file) but please do LMK if they're important and I'll fix.

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

31

we're just redirecting data from one stream to another, I don't think there's any reason to do character decoding+encoding on the way...

81

Agree - can do that as a followup.

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

2

Why do we want to avoid mixing them?
(This is copied from the other test which uses %S)

3

Yeah, there aren't a lot of these so i'd like it to be super-explicit for now. Happy to change this if we end up with lots of tests passing various server args (and few client args)

5

Why would this be preferred? (< is roughly 5x more common in llvm/test and clang/test - neither is used significantly in clang-tools-extra)

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

 //===--- Server.cpp - gRPC-based Remote Index Server  ---------------------===//
 //
 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
 // See https://llvm.org/LICENSE.txt for license information.
 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 //===----------------------------------------------------------------------===//
 
 #include "Index.pb.h"
 #include "Service.grpc.pb.h"
 #include "index/Index.h"
 #include "index/Serialization.h"
 #include "index/Symbol.h"
 #include "index/remote/marshalling/Marshalling.h"
 #include "support/Context.h"
 #include "support/Logger.h"
 #include "support/Shutdown.h"
RemoteIndexServer(clangd::SymbolIndex &Index, llvm::StringRef IndexRoot)
     llvm::SmallString<256> NativePath = IndexRoot;
     llvm::sys::path::native(NativePath);
     ProtobufMarshaller = std::unique_ptr<Marshaller>(new Marshaller(
         /*RemoteIndexRoot=*/llvm::StringRef(NativePath),
         /*LocalIndexRoot=*/""));
   }
 
 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) {
       elog("Can not parse LookupRequest from protobuf: {0}", Req.takeError());
       return grpc::Status::CANCELLED;
     }
     unsigned Sent = 0;
     unsigned FailedToSend = 0;
     Index.lookup(*Req, [&](const clangd::Symbol &Item) {
       auto SerializedItem = ProtobufMarshaller->toProtobuf(Item);
       if (!SerializedItem) {
         elog("Unable to convert Symbol to protobuf: {0}",
              SerializedItem.takeError());
         ++FailedToSend;
         return;
       }
       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) {
       elog("Can not parse FuzzyFindRequest from protobuf: {0}",
            Req.takeError());
       return grpc::Status::CANCELLED;
     }
     unsigned Sent = 0;
     unsigned FailedToSend = 0;
     bool HasMore = Index.fuzzyFind(*Req, [&](const clangd::Symbol &Item) {
       auto SerializedItem = ProtobufMarshaller->toProtobuf(Item);
       if (!SerializedItem) {
         elog("Unable to convert Symbol to protobuf: {0}",
              SerializedItem.takeError());
         ++FailedToSend;
         return;
       }
       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) {
       elog("Can not parse RefsRequest from protobuf: {0}", Req.takeError());
       return grpc::Status::CANCELLED;
     }
     unsigned Sent = 0;
     unsigned FailedToSend = 0;
     bool HasMore = Index.refs(*Req, [&](const clangd::Ref &Item) {
       auto SerializedItem = ProtobufMarshaller->toProtobuf(Item);
       if (!SerializedItem) {
         elog("Unable to convert Ref to protobuf: {0}",
              SerializedItem.takeError());
         ++FailedToSend;
         return;
       }
       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) {
       elog("Can not parse RelationsRequest from protobuf: {0}",
            Req.takeError());
       return grpc::Status::CANCELLED;
     }
     unsigned Sent = 0;
     unsigned FailedToSend = 0;
     Index.relations(
         *Req, [&](const SymbolID &Subject, const clangd::Symbol &Object) {
           auto SerializedItem = ProtobufMarshaller->toProtobuf(Subject, Object);
           if (!SerializedItem) {
             elog("Unable to convert Relation to protobuf: {0}",
                  SerializedItem.takeError());
             ++FailedToSend;
             return;
           }
           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;
+
+  public:
+    TextProto(const google::protobuf::Message &M) : M(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;
 };
 
 // Detect changes in \p IndexPath file and load new versions of the index
 // whenever they become available.
 void hotReload(clangd::SwapIndex &Index, llvm::StringRef IndexPath,
                llvm::vfs::Status &LastStatus,
std::thread ServerShutdownWatcher([&]() {
     Server->Shutdown();
   });
 
   Server->Wait();
   ServerShutdownWatcher.join();
 }
 
 std::unique_ptr<Logger> makeLogger(llvm::raw_ostream &OS) {
-  if (!LogPublic)
+  if (!LogPublic) {
     return std::make_unique<StreamLogger>(OS, LogLevel);
+    llvm::errs() << "non redacted logger\n";
+  }
   // Redacted mode:
   //  - messages outside the scope of a request: log fully
   //  - messages tagged [public]: log fully
   //  - errors: log the format string
   //  - others: drop
   class RedactedLogger : public StreamLogger {
   public:
     using StreamLogger::StreamLogger;
     void log(Level L, const char *Fmt,
              const llvm::formatv_object_base &Message) override {
+      llvm::errs() << "redactedlogger! "
+                   << Context::current().get(CurrentRequest) << "\n";
       if (Context::current().get(CurrentRequest) == nullptr ||
           llvm::StringRef(Fmt).startswith("[public]"))
         return StreamLogger::log(L, Fmt, Message);
       if (L >= Error)
         return StreamLogger::log(L, Fmt, llvm::formatv("[redacted] {0}", Fmt));
     }
   };
   return std::make_unique<RedactedLogger>(OS, LogLevel);

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

 import threading
 
 
 def kill_server_after_delay(server_process):
   time.sleep(10)
   if server_process.poll() is None:
     server_process.kill()
 
-
 def main():
   parser = argparse.ArgumentParser()
   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')
+  parser.add_argument('--server-log', nargs='?', type=argparse.FileType('wb'), default=os.devnull)
 
   args = parser.parse_args()
 
   # Grab an available port.
   with socket() as s:
     s.bind(('localhost', 0))
     server_address = 'localhost:' + str(s.getsockname()[1])
 
   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
   # message.
   shutdown_thread = threading.Thread(
       target=kill_server_after_delay, args=(index_server_process,))
   shutdown_thread.daemon = True
   shutdown_thread.start()
 
   # 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:
       found_init_message = True
       break
 
   if not found_init_message:
     sys.exit(1)
 
   in_file = open(args.input_file_name)
 
   clangd_process = subprocess.Popen([
       'clangd', '--remote-index-address=' + server_address,
       '--project-root=' + args.project_root, '--lit-test', '--sync'
   ],
                                     stdin=in_file)
-
   clangd_process.wait()
   index_server_process.kill()
+  for line in index_server_process.stderr:
+    args.server_log.write(line)
+    args.server_log.flush()
 
 
 if __name__ == '__main__':
   main()

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

+# 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: gFoo
+# LOG-ALL: 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"}