[clangd] Add -log=public to redact all request info from index server logs

[sammccall]

Summary

The index server has access to potentially-sensitive information, e.g. a
sequence of fuzzyFind requests reveals details about code completions in the
editor which in turn reveals details about the code being edited.
This information is necessary to provide the service, and our intention[1] is it
should never be retained beyond the scope of the request (e.g. not logged).

At the same time, some log messages should be exposed:

• server startup/index reloads etc that don't pertain to a user request
• basic request logs (method, latency, #results, error code) for monitoring
• errors while handling requests, without request-specific data

The -log=public design accommodates these by allowing three types of logs:

• those not associated with any user RPC request (via context-propagation)
• those explicitly tagged as [public] in the log line
• logging of format strings only, with no interpolated data (error level only)

[1] Specifically: Google is likely to run public instances of this server
for LLVM and potentially other projects, they will run in this configuration.
The details agreed in a Google-internal privacy review.
As clangd developers, we'd encourage others to use this configuration for public
instances too.

[sammccall]

Couple of notes on this patch.

There's no actual request logging here yet. My plan is something like [public] request v1/Relations => SUCCESS: 3 results in 3ms. Wanted to keep the patch a reasonable size.

There's also no testing, testing is definitely important here. I want to build something on top of Kirill's python tests once that lands. Probably in the patch that adds request logging.

The [public] thing is gross, but I think worse is better here.
I went through lots of iterations, including with explicit "Sensitivity" enum passed around, but it was pretty invasive.
Moreover explicitly supporting it in Logger.h made me feel like all the callsites in all our libraries should consider whether info is public or not. I think spreading that cognitive load around the whole project is a net negative.
With the request-context detection (which was a last-minute realization actually), maybe we could even get away without [public], but I didn't want to commit to contorting our code so that the request logging happens outside the request scope. Happy to drop this part if you think we can make it work.

Weird extension idea: we could have a completely synthetic request ID to stick on the request log lines and also the pattern-only elog()s to tie them together.

Changing the Logger API is a bit annoying, but has one side-benefit: error count grouped by format string is a nice thing to be able to monitor.

[kadircet]

Thanks for figuring this one out!

I think the final result looks pretty good, I especially loved only disabling when there's a request in question.
My only hesitation is around logging all severities when we are outside a request, I suppose it shouldn't cause too much trouble but we sometimes end up logging too much in verbose mode and I am afraid of this hindering the server performance at random intervals (e.g. when it loads a new index). But this is just speculation. I suppose we can think about this when it happens. Also maybe we should not be logging that much instead :D

In addition to that it could be nice to see how the public tagging will happen. Are you planning to have a custom endpoint for it, or should the user manually insert it into format string? Both are fine by me, the latter might even make it less error-prone for accidental logging at the cost of misspells and spreading the string across the codebase.

[sammccall]

In D90526#2367659, @kadircet wrote:

Thanks for figuring this one out!

I think the final result looks pretty good, I especially loved only disabling when there's a request in question.
My only hesitation is around logging all severities when we are outside a request, I suppose it shouldn't cause too much trouble but we sometimes end up logging too much in verbose mode and I am afraid of this hindering the server performance at random intervals (e.g. when it loads a new index). But this is just speculation. I suppose we can think about this when it happens. Also maybe we should not be logging that much instead :D

So I can't remember anymore why I put this as an enum -log=public rather than an independent switch -log-public or so that could combine with any log level.
Sounds like the latter would be better?

In addition to that it could be nice to see how the public tagging will happen. Are you planning to have a custom endpoint for it, or should the user manually insert it into format string? Both are fine by me, the latter might even make it less error-prone for accidental logging at the cost of misspells and spreading the string across the codebase.

Manually insert it into the format string. After thinking about it I came to the conclusion there just aren't that many places where we need to log things publicly. I expect to basically not have any visibility inside most requests except the error patterns.

[kadircet]

In D90526#2367782, @sammccall wrote:

So I can't remember anymore why I put this as an enum -log=public rather than an independent switch -log-public or so that could combine with any log level.
Sounds like the latter would be better?

Agreed.

Manually insert it into the format string. After thinking about it I came to the conclusion there just aren't that many places where we need to log things publicly. I expect to basically not have any visibility inside most requests except the error patterns.

SG.

[sammccall]

Use separate flag for log-public vs log level

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"
 #include "support/ThreadsafeFS.h"
 #include "support/Trace.h"
 #include "llvm/ADT/IntrusiveRefCntPtr.h"
 #include "llvm/ADT/None.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/Chrono.h"
 #include "llvm/Support/CommandLine.h"
 #include "llvm/Support/Error.h"
 #include "llvm/Support/FileSystem.h"
+#include "llvm/Support/FormatVariadic.h"
 #include "llvm/Support/Path.h"
 #include "llvm/Support/Signals.h"
 #include "llvm/Support/VirtualFileSystem.h"
 
 #include <chrono>
 #include <grpc++/grpc++.h>
 #include <grpc++/health_check_service_interface.h>
 #include <memory>
llvm::cl::opt<Logger::Level> LogLevel{
     "log",
     llvm::cl::desc("Verbosity of log messages written to stderr"),
     values(clEnumValN(Logger::Error, "error", "Error messages only"),
            clEnumValN(Logger::Info, "info", "High level execution tracing"),
            clEnumValN(Logger::Debug, "verbose", "Low level details")),
     llvm::cl::init(Logger::Info),
 };
 
+llvm::cl::opt<bool> LogPublic{
+    "log-public",
+    llvm::cl::desc("Avoid logging potentially-sensitive request details"),
+    llvm::cl::init(false),
+};
+
 llvm::cl::opt<std::string> TraceFile(
     "trace-file",
     llvm::cl::desc("Path to the file where tracer logs will be stored"));
 
 llvm::cl::opt<bool> PrettyPrint{
     "pretty",
     llvm::cl::desc("Pretty-print JSON output in the trace"),
     llvm::cl::init(false),
 };
 
 llvm::cl::opt<std::string> ServerAddress(
     "server-address", llvm::cl::init("0.0.0.0:50051"),
     llvm::cl::desc("Address of the invoked server. Defaults to 0.0.0.0:50051"));
 
+static Key<grpc::ServerContext *> CurrentRequest;
+
 class RemoteIndexServer final : public v1::SymbolIndex::Service {
 public:
   RemoteIndexServer(clangd::SymbolIndex &Index, llvm::StringRef IndexRoot)
       : Index(Index) {
     llvm::SmallString<256> NativePath = IndexRoot;
     llvm::sys::path::native(NativePath);
     ProtobufMarshaller = std::unique_ptr<Marshaller>(new Marshaller(
         /*RemoteIndexRoot=*/llvm::StringRef(NativePath),
         /*LocalIndexRoot=*/""));
   }
 
 private:
   grpc::Status Lookup(grpc::ServerContext *Context,
                       const LookupRequest *Request,
                       grpc::ServerWriter<LookupReply> *Reply) override {
+    WithContextValue(CurrentRequest, Context);
     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;
grpc::Status Lookup(grpc::ServerContext *Context,
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
     return grpc::Status::OK;
   }
 
   grpc::Status FuzzyFind(grpc::ServerContext *Context,
                          const FuzzyFindRequest *Request,
                          grpc::ServerWriter<FuzzyFindReply> *Reply) override {
+    WithContextValue(CurrentRequest, Context);
     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;
grpc::Status FuzzyFind(grpc::ServerContext *Context,
     Reply->Write(LastMessage);
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
     return grpc::Status::OK;
   }
 
   grpc::Status Refs(grpc::ServerContext *Context, const RefsRequest *Request,
                     grpc::ServerWriter<RefsReply> *Reply) override {
+    WithContextValue(CurrentRequest, Context);
     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;
grpc::Status Refs(grpc::ServerContext *Context, const RefsRequest *Request,
     SPAN_ATTACH(Tracer, "Sent", Sent);
     SPAN_ATTACH(Tracer, "Failed to send", FailedToSend);
     return grpc::Status::OK;
   }
 
   grpc::Status Relations(grpc::ServerContext *Context,
                          const RelationsRequest *Request,
                          grpc::ServerWriter<RelationsReply> *Reply) override {
+    WithContextValue(CurrentRequest, Context);
     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;
void hotReload(clangd::SwapIndex &Index, llvm::StringRef IndexPath,
                llvm::vfs::Status &LastStatus,
                llvm::IntrusiveRefCntPtr<llvm::vfs::FileSystem> &FS) {
   auto Status = FS->status(IndexPath);
   // Requested file is same as loaded index: no reload is needed.
   if (!Status || (Status->getLastModificationTime() ==
                       LastStatus.getLastModificationTime() &&
                   Status->getSize() == LastStatus.getSize()))
     return;
-  vlog("Found different index version: existing index was modified at {0}, new "
-       "index was modified at {1}. Attempting to reload.",
+  vlog("Found different index version: existing index was modified at "
+       "{0}, new index was modified at {1}. Attempting to reload.",
        LastStatus.getLastModificationTime(), Status->getLastModificationTime());
   LastStatus = *Status;
   std::unique_ptr<clang::clangd::SymbolIndex> NewIndex = loadIndex(IndexPath);
   if (!NewIndex) {
     elog("Failed to load new index. Old index will be served.");
     return;
   }
   Index.reset(std::move(NewIndex));
while (!clang::clangd::shutdownRequested())
       std::this_thread::sleep_for(WatcherFrequency);
     Server->Shutdown();
   });
 
   Server->Wait();
   ServerShutdownWatcher.join();
 }
 
+std::unique_ptr<Logger> makeLogger(llvm::raw_ostream &OS) {
+  if (!LogPublic)
+    return std::make_unique<StreamLogger>(OS, LogLevel);
+  // 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 {
+      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);
+}
+
 } // namespace
 } // namespace remote
 } // namespace clangd
 } // namespace clang
 
 using clang::clangd::elog;
 
 int main(int argc, char *argv[]) {
   using namespace clang::clangd::remote;
   llvm::cl::ParseCommandLineOptions(argc, argv, Overview);
   llvm::sys::PrintStackTraceOnErrorSignal(argv[0]);
   llvm::sys::SetInterruptFunction(&clang::clangd::requestShutdown);
 
   if (!llvm::sys::path::is_absolute(IndexRoot)) {
     llvm::errs() << "Index root should be an absolute path.\n";
     return -1;
   }
 
   llvm::errs().SetBuffered();
   // Don't flush stdout when logging for thread safety.
   llvm::errs().tie(nullptr);
-  clang::clangd::StreamLogger Logger(llvm::errs(), LogLevel);
-  clang::clangd::LoggingSession LoggingSession(Logger);
+  auto Logger = makeLogger(llvm::errs());
+  clang::clangd::LoggingSession LoggingSession(*Logger);
 
   llvm::Optional<llvm::raw_fd_ostream> TracerStream;
   std::unique_ptr<clang::clangd::trace::EventTracer> Tracer;
   if (!TraceFile.empty()) {
     std::error_code EC;
     TracerStream.emplace(TraceFile, EC,
                          llvm::sys::fs::FA_Read | llvm::sys::fs::FA_Write);
     if (EC) {

clang-tools-extra/clangd/support/Logger.h

 namespace clang {
 namespace clangd {
 
 /// Interface to allow custom logging in clangd.
 class Logger {
 public:
   virtual ~Logger() = default;
 
-  enum Level { Debug, Verbose, Info, Error };
+  /// The significance or severity of this message.
+  /// Typically used to filter the output to an interesting level.
+  enum Level : unsigned char { Debug, Verbose, Info, Error };
   static char indicator(Level L) { return "DVIE"[L]; }
 
   /// Implementations of this method must be thread-safe.
-  virtual void log(Level, const llvm::formatv_object_base &Message) = 0;
+  virtual void log(Level, const char *Fmt,
+                   const llvm::formatv_object_base &Message) = 0;
 };
 
 namespace detail {
 const char *debugType(const char *Filename);
-void log(Logger::Level, const llvm::formatv_object_base &);
+void logImpl(Logger::Level, const char *Fmt, const llvm::formatv_object_base &);
 
 // We often want to consume llvm::Errors by value when passing them to log().
 // We automatically wrap them in llvm::fmt_consume() as formatv requires.
 template <typename T> T &&wrap(T &&V) { return std::forward<T>(V); }
 inline decltype(fmt_consume(llvm::Error::success())) wrap(llvm::Error &&V) {
   return fmt_consume(std::move(V));
 }
 template <typename... Ts>
 void log(Logger::Level L, const char *Fmt, Ts &&... Vals) {
-  detail::log(L, llvm::formatv(Fmt, detail::wrap(std::forward<Ts>(Vals))...));
+  detail::logImpl(L, Fmt,
+                  llvm::formatv(Fmt, detail::wrap(std::forward<Ts>(Vals))...));
 }
 
 llvm::Error error(std::error_code, std::string &&);
 } // namespace detail
 
 // Clangd logging functions write to a global logger set by LoggingSession.
 // If no logger is registered, writes to llvm::errs().
 // All accept llvm::formatv()-style arguments, e.g. log("Text={0}", Text).

 
 // Logs to an output stream, such as stderr.
 class StreamLogger : public Logger {
 public:
   StreamLogger(llvm::raw_ostream &Logs, Logger::Level MinLevel)
       : MinLevel(MinLevel), Logs(Logs) {}
 
   /// Write a line to the logging stream.
-  void log(Level, const llvm::formatv_object_base &Message) override;
+  void log(Level, const char *Fmt,
+           const llvm::formatv_object_base &Message) override;
 
 private:
   Logger::Level MinLevel;
   llvm::raw_ostream &Logs;
 
   std::mutex StreamMutex;
 };
 
 } // namespace clangd
 } // namespace clang
 
 #endif

clang-tools-extra/clangd/support/Logger.cpp

 
 LoggingSession::LoggingSession(clangd::Logger &Instance) {
   assert(!L);
   L = &Instance;
 }
 
 LoggingSession::~LoggingSession() { L = nullptr; }
 
-void detail::log(Logger::Level Level,
+void detail::logImpl(Logger::Level Level, const char *Fmt,
                      const llvm::formatv_object_base &Message) {
   if (L)
-    L->log(Level, Message);
+    L->log(Level, Fmt, Message);
   else {
     static std::mutex Mu;
     std::lock_guard<std::mutex> Guard(Mu);
     llvm::errs() << Message << "\n";
   }
 }
 
 const char *detail::debugType(const char *Filename) {
   if (const char *Slash = strrchr(Filename, '/'))
     return Slash + 1;
   if (const char *Backslash = strrchr(Filename, '\\'))
     return Backslash + 1;
   return Filename;
 }
 
-void StreamLogger::log(Logger::Level Level,
+void StreamLogger::log(Logger::Level Level, const char *Fmt,
                        const llvm::formatv_object_base &Message) {
   if (Level < MinLevel)
     return;
   llvm::sys::TimePoint<> Timestamp = std::chrono::system_clock::now();
   trace::log(Message);
   std::lock_guard<std::mutex> Guard(StreamMutex);
   Logs << llvm::formatv("{0}[{1:%H:%M:%S.%L}] {2}\n", indicator(Level),
                         Timestamp, Message);

clang-tools-extra/clangd/unittests/ClangdLSPServerTests.cpp

if (Server)
       stop();
   }
 
   MockFS FS;
   ClangdLSPServer::Options Opts;
 
 private:
   // Color logs so we can distinguish them from test output.
-  void log(Level L, const llvm::formatv_object_base &Message) override {
+  void log(Level L, const char *Fmt,
+           const llvm::formatv_object_base &Message) override {
     raw_ostream::Colors Color;
     switch (L) {
     case Level::Verbose:
       Color = raw_ostream::BLUE;
       break;
     case Level::Error:
       Color = raw_ostream::RED;
       break;