[clangd] Add -log-lsp-to-stderr option

[simark]

Summary

Currently, clangd prints all the LSP communication on stderr. While
this is good for developping, I don't think it's good as a general
default. For example, we are integrating clangd (and other language
servers) in an IDE, and we print everything the language servers send on
their stderr on our own stderr. Printing the whole LSP communication
adds a lot of noise. If there are actual error messages to be printed,
then it makes sense to output them on stderr.

Also, an IDE or tool that integrates many language servers will likely
have its own way of logging LSP communication in a consistent way, so
it's better to leave it to that tool to log the LSP communication if it
wants to.

An alternative would be to introduce log levels (debug, info, warning,
error), and output LSP communications only at the debug log level.

Signed-off-by: Simon Marchi <[e-mail]>

[simark]

Changed -log-to-stderr to -log-lsp-to-stderr

The first version disabled a bit too much, this version removes the LSP
communication logging in a more fine grained way.

[ilya-biryukov]

I would vouch for adding a log level instead. It's a very well understood concept that certainly covers this use-case and can be useful in other places.
WDYT?

[simark]

In D44226#1030625, @ilya-biryukov wrote:

I would vouch for adding a log level instead. It's a very well understood concept that certainly covers this use-case and can be useful in other places.
WDYT?

I agree. How would you prefer the flags to look like?

• --log-level {debug,info,warning,error} (warning being the default if not specified)
• Use -v multiple times to be more verbose: "-v" to show info, "-v -v" to show debug. Without -v, we show warnings and errors.
• something else?

[ilya-biryukov]

In D44226#1030639, @simark wrote:

In D44226#1030625, @ilya-biryukov wrote:

I would vouch for adding a log level instead. It's a very well understood concept that certainly covers this use-case and can be useful in other places.
WDYT?

I agree. How would you prefer the flags to look like?

• Use -v multiple times to be more verbose: "-v" to show info, "-v -v" to show debug. Without -v, we show warnings and errors.

Let's go with two levels (info and verbose) and a single -v flag to enable the verbose level.
Keeping consistent the way people use many logging levels across the whole project is hard (i.e. different people might have different ideas about to distinguishing warning from info). A distinction between verbose and non-verbose messages should be easier to agree on.

As for the changes in the code, let's make the current log function emit info messages and add a vlog function that emits "verbose" messages. Verbose message are only output when -v is passed.

clangd/JSONRPCDispatcher.cpp

315

Since we're replacing log with vlog here, could we add a normal info log that captures the name of the LSP method?
And log with LSP method name should probably go before vlog with message contents, that's easy to achieve by moving the logging code into the body of Dispatcher.call

[simark]

Update

• Change switch to -verbose
• Add vlog function, do the filtering there

[simark]

Now, if the client calls a method that we do not support (e.g. the initialized notification), clangd just outputs:

C/C++: [10:55:16.033] Error -32601: method not found

It would be useful to at least print in this error message the name of the method. Because the "unknown method" handler shares the type signature of regular handlers, I would have to add a parameter with the method name to all existing handlers. I'll try that.

[ilya-biryukov]

clangd/Logger.cpp

19 ↗

(On Diff #137573)

Could we move the flag to implementation of Logger?
I.e.:

class Logger {
  virtual log(const llvm::Twine &Message, bool Verbose);
};

// Implementation of top-level log
void clangd::log(const llvm::Twine &Message) {
   L->log(Message, /*Verbose=*/false);
   // should also handle missing Logger by logging into llvm::errs()
}

// Implementation of top-level vlog.
void clangd::vlog(const llvm::Twine &Message) {
   L->log(Message, /*Verbose=*/true);
   // should also handle missing Logger by logging into llvm::errs()
}

An implementation of the interface would decide whether to log or not, based on command-line argument.

clangd/tool/ClangdMain.cpp

79

Maybe just call it -v?

[simark]

clangd/Logger.cpp

19 ↗

(On Diff #137573)

That's what I thought of doing first. The issue is that if we don't set a logger with LoggingSession, the log function prints to stderr itself. So if we don't check the Verbose flag there, the -v flag will have no effect when LoggingSession has not been called (I don't know if it's really a problem or not, since in practice we call it).

[simark]

clangd/tool/ClangdMain.cpp

79

I would have like to add both "-v" and "-verbose", but it doesn't seem possible to have two flags for the same option. "-v" it is then, it is quite standard.

[ilya-biryukov]

clangd/Logger.cpp

19 ↗

(On Diff #137573)

It shouldn't be a problem.
We're only missing LoggingSession in tests, so let's just print messages from vlog into stderr in the same way we do it with log now.

clangd/tool/ClangdMain.cpp

79

I would go with having just -v with no aliases.

But this should do the trick if you prefer to have -verbose as an option:

llvm::cl::opt<bool> Verbose("v", llvm::cl::alias("verbose") , //....

[simark]

Update

• Add vlog method to Logger interface
• Add method name to "method not found" error message

[simark]

clangd/tool/ClangdMain.cpp

79

Ah ok thanks for the info. I'll leave it with just -v here, but knowing this could be handy in the future.

[ilya-biryukov]

Sorry for the delay, just a few more comments.

clangd/ClangdLSPServer.cpp

412 ↗

(On Diff #137582)

Could we also log (i.e. not vlog) names of the methods that were handled successfully? To have some context when something crashes and we only have non-verbose logs.

413 ↗

(On Diff #137582)

Maybe use llvm::formatv to generate message? Having a string and a stream for something as simple is too verbose.

clangd/Logger.cpp

19 ↗

(On Diff #137582)

We don't need Verbose variable here and Verbose flag from LoggingSession anymore.

[simark]

Address review comments

[malaperle]

Gentle ping! It would be nice to have this so make Clangd less "verbose".

clangd/ClangdLSPServer.cpp

412 ↗

(On Diff #137582)

Wouldn't that mean pretty much logging everything coming in? The idea of this patch it to make it that by default Clangd is not talkative unless there is an error and optionally make it verbose, for troubleshooting.

[ilya-biryukov]

clangd/ClangdLSPServer.cpp

412 ↗

(On Diff #137582)

Logs are also useful to diagnose problems in case something crashes or works incorrectly.
Clang will probably log something when processing any request anyway, logging the method name first will merely give some more context on which request other log messages correspond to.

The idea of this patch it to make it that by default Clangd is not talkative unless there is an error.

I don't think we use logging this way in clangd. Logs give us a way to make sense of what's happening inside clangd even when there's no error. vlog lets us turn off some extremely noisy output that is not useful most of the time.
We have a whole bunch of log statements that don't correspond to errors (e.g. "reusing preamble", "building file with compile command").

clangd/JSONRPCDispatcher.h

56

This flag should be private.

[simark]

clangd/ClangdLSPServer.cpp

412 ↗

(On Diff #137582)

That would be against the purpose of this patch, which is to output nothing if everything goes right (so it's easier to notice when something goes wrong). Just outputting the names of the methods that are handled successfully would still be very verbose I think.

412 ↗

(On Diff #137582)

Logs are also useful to diagnose problems in case something crashes or works incorrectly.

Clang will probably log something when processing any request anyway, logging the method name first will merely give some more context on which request other log messages correspond to.

I think it's fine if clangd logs warning/errors by default, that a user might want to look at and address. But logging things that happen recurrently and are part of clangd's normal operation just flood the terminal (and makes it harder to spot actual errors).

I agree that having some context helps to make sense of an error. A reasonnable way would be to include the method name only when printing an error. For example, While handling method 'workspace/symbol': Could not open file foo.. That would require us to carry around some more context information, but I think it would be better than printing all the handled methods.

I don't think we use logging this way in clangd. Logs give us a way to make sense of what's happening inside clangd even when there's no error.

In that case you turn on a more verbose log level.

vlog lets us turn off some extremely noisy output that is not useful most of the time. We have a whole bunch of log statements that don't correspond to errors (e.g. "reusing preamble", "building file with compile command").

I would consider everything that happens at each json-rpc request to be "noisy". When using clangd from an IDE, there's quite a lot of requests being done. I was also thinking of modyfing the patch to also use vlog for the "reusing preamble" and "building file with compile command" messages.

[simark]

clangd/ClangdLSPServer.cpp

412 ↗

(On Diff #137582)

One more thing: when using multiple workers and the asynchronous model, the error may not be related to the last printed method name:

Handling json-rpc method A
Handling json-rpc method B
Some error related to the handling of request A

If you just see the error like this, you would think it's cause by request B, even though it's when handling request A. Passing some context to the callback would allow us to print the request which is really at the origin of the error, avoiding any confusion. And it would allow us to not print it if everything goes fine.

[ilya-biryukov]

clangd/ClangdLSPServer.cpp

412 ↗

(On Diff #137582)

clangd logs were never designed to fire only on errors. I probably misread the patch initially, are you trying to change log into something used only for logging errors?
Could you give a bit more context for your use-case in order to understand it better?

• How do you use the log output? Is it shown to the end user?
• What information do you want to extract from the logs apart from the fact that an error happened?
• Why are JSON RPC error responses not enough to indicate errors? What benefits do logs provide over them?

[simark]

clangd/ClangdLSPServer.cpp

412 ↗

(On Diff #137582)

clangd logs were never designed to fire only on errors. I probably misread the patch initially, are you trying to change log into something used only for logging errors?

Because we only have two log level (log and vlog) as part of this patch, that's pretty much what I ended up doing. But perhaps we should rather have the standard error, warning, info and debug log levels.

Of course, clangd should log more than just errors, since it helps developers know what is happening inside. But we should think about what is useful to show to the regular end user, and what should be the default log level. For the end user, if clangd spits out text constantly and there is one error somewhere in the middle, they will likely not catch it. However, if clangd is mostly silent during its regular operation, the user will be more likely to notice when it outputs an error, which will allow them to either report the error or address it.

If you are a clangd developer (or a user reporting a bug) and want to see everything happening in clangd, then you can use the switch to increase the log level.

Could you give a bit more context for your use-case in order to understand it better?

• How do you use the log output? Is it shown to the end user?

Currently, our application (the Theia IDE) prints on the console (not sure if it's on its stdout or stderr) everything that the language servers, mixed with its own output. Eventually, we'd like to show it to the user if there is an error in the language server, the same way as if there is an error in the rest of the IDE, because the language server is part of the complete IDE.

Also, since we send whole files (at least when opening them) through json-rpc, they end up printed on the console. Printing thousands of lines worth of text to the console does not help performance and just makes the log less readable.

• What information do you want to extract from the logs apart from the fact that an error happened?

That would depend on the user. A regular end user would probably just be interested in errors, but they don't care about single json-rpc requests, or the fact that a preamble was reused or not. A a clangd developer would be interested in all of that.

• Why are JSON RPC error responses not enough to indicate errors? What benefits do logs provide over them?

We can't reply an error to json-rpc notifications. It's also possible that we do things that are not triggered by json-rpc requests, for example we might watch some files for changes in the future, which can trigger errors.

[ilya-biryukov]

clangd/ClangdLSPServer.cpp

412 ↗

(On Diff #137582)

Of course, clangd should log more than just errors, since it helps developers know what is happening inside. But we should think about what is useful to show to the regular end user, and what should be the default log level. For the end user, if clangd spits out text constantly and there is one error somewhere in the middle, they will likely not catch it. However, if clangd is mostly silent during its regular operation, the user will be more likely to notice when it outputs an error, which will allow them to either report the error or address it.

Currently, our application (the Theia IDE) prints on the console (not sure if it's on its stdout or stderr) everything that the language servers, mixed with its own output. Eventually, we'd like to show it to the user if there is an error in the language server, the same way as if there is an error in the rest of the IDE, because the language server is part of the complete IDE.

That would depend on the user. A regular end user would probably just be interested in errors, but they don't care about single json-rpc requests, or the fact that a preamble was reused or not. A a clangd developer would be interested in all of that.

Even if we have multiple log levels, I don't think we should aim to make clangd logs of any level readable by the end user. We use json rpc for communicating information to the user. stderr is internal output, only relevant to clangd developers.

Do you surface json error replies in the same console? Is it possible to move the clangd logs to a separate file or tab and keep only the json error replies there?

We can't reply an error to json-rpc notifications. It's also possible that we do things that are not triggered by json-rpc requests, for example we might watch some files for changes in the future, which can trigger errors.

Json rpc notifications are a limitation, yes. But they will probably cause errors in the subsequent request and users will report the error based on that.
LSP has window/logMessage method that seems to be a much better medium for reporting these errors to the user. We need to do some plumbing to make sure we send it when errors happen, but that's doable.

[sammccall]

Hey Simon,

Sorry this patch got stalled. I hope you're still interested!
I agree there's space for providing some high-signal information about error conditions to power users/potential developers/administrators, even if it's not "polished" for end-users.

What are the semantics we want for these log levels? My guess is we need a third one:

1. it seems clear we want a level that indicates likely problems, with minimal noise. You want this, and this is useful for monitoring production/cloud issues too.
2. it may be useful to add context like LSP method names and "rebuilding preamble" to understand the context of errors and crashes. I think this is what Ilya was pushing for.
3. we also want to log details that allow you to see what's going on with only the log to go on. This is stuff like full LSP messages. I think it's important that we can do this with a production build.
4. finer-grained debugging things can probably be done in a targeted way using LLVM_DEBUG (CodeComplete has some of this for debugging scoring signals)

What do you think about 1=elog() (e for Error), 2=log(), 3=vlog() (v for Verbose), and using LLVM_DEBUG for 4?

I don't have a strong opinion of what the default should be long term, but either 1 with -v and -vv to change, or 2 with -q and -v, seem reasonable...

(Internally at google we use something like glog which calls these levels ERROR, INFO, VLOG(1) and VLOG(2), with INFO as default - this convention explains some of our confusion over the semantics of vlog!)

If you don't think we need a third level, or don't have time for it now, I'm pretty happy with this patch as it is but would suggest rename of log,vlog --> elog,log to make it clearer that the former is for problems only.

clangd/JSONRPCDispatcher.h

 
 /// Encapsulates output and logs streams and provides thread-safe access to
 /// them.
 class JSONOutput : public Logger {
   // FIXME(ibiryukov): figure out if we can shrink the public interface of
   // JSONOutput now that we pass Context everywhere.
 public:
   JSONOutput(llvm::raw_ostream &Outs, llvm::raw_ostream &Logs,
-             llvm::raw_ostream *InputMirror = nullptr, bool Pretty = false)
-      : Pretty(Pretty), Outs(Outs), Logs(Logs), InputMirror(InputMirror) {}
+             llvm::raw_ostream *InputMirror = nullptr, bool LogToStderr = false,
+             bool Pretty = false)
+      : LogToStderr(LogToStderr), Pretty(Pretty), Outs(Outs), Logs(Logs),
+        InputMirror(InputMirror) {}
 
   /// Emit a JSONRPC message.
   void writeMessage(const json::Expr &Result);
 
   /// Write a line to the logging stream.
   void log(const Twine &Message) override;
 
   /// Mirror \p Message into InputMirror stream. Does nothing if InputMirror is
   /// null.
   /// Unlike other methods of JSONOutput, mirrorInput is not thread-safe.
   void mirrorInput(const Twine &Message);
 
+  // Whether to output all LSP communication to stderr.
+  const bool LogToStderr;
+
   // Whether output should be pretty-printed.
   const bool Pretty;
 
 private:
   llvm::raw_ostream &Outs;
   llvm::raw_ostream &Logs;
   llvm::raw_ostream *InputMirror;
 
   std::mutex StreamMutex;
 };
 
 /// Sends a successful reply.
 /// Current context must derive from JSONRPCDispatcher::Handler.

clangd/JSONRPCDispatcher.cpp

OS.flush();
     std::lock_guard<std::mutex> Guard(StreamMutex);
     Outs << "Content-Length: " << S.size() << "\r\n\r\n" << S;
     Outs.flush();
   }
   log(llvm::Twine("--> ") + S);
 }
 
 void JSONOutput::log(const Twine &Message) {
-  llvm::sys::TimePoint<> Timestamp = std::chrono::system_clock::now();
   trace::log(Message);
+
+  if (!LogToStderr)
+    return;
+
+  llvm::sys::TimePoint<> Timestamp = std::chrono::system_clock::now();
   std::lock_guard<std::mutex> Guard(StreamMutex);
   Logs << llvm::formatv("[{0:%H:%M:%S.%L}] {1}\n", Timestamp, Message);
   Logs.flush();
 }
 
 void JSONOutput::mirrorInput(const Twine &Message) {
   if (!InputMirror)
     return;
void clangd::runLanguageServerLoop(std::istream &In, JSONOutput &Out,
   auto &ReadMessage =
       (InputStyle == Delimited) ? readDelimitedMessage : readStandardMessage;
   while (In.good()) {
     if (auto JSON = ReadMessage(In, Out)) {
       if (auto Doc = json::parse(*JSON)) {
         // Log the formatted message.
         log(llvm::formatv(Out.Pretty ? "<-- {0:2}\n" : "<-- {0}\n", *Doc));
         // Finally, execute the action for this JSON message.
         if (!Dispatcher.call(*Doc, Out))
           log("JSON dispatch failed!\n");
       } else {
         // Parse error. Log the raw message.
         log(llvm::formatv("<-- {0}\n" , *JSON));
         log(llvm::Twine("JSON parse error: ") +
             llvm::toString(Doc.takeError()) + "\n");
       }
     }
     // If we're done, exit the loop.
     if (IsDone)
       break;
   }
 }

clangd/tool/ClangdMain.cpp

 static llvm::cl::opt<JSONStreamStyle> InputStyle(
     "input-style", llvm::cl::desc("Input JSON stream encoding"),
     llvm::cl::values(
         clEnumValN(JSONStreamStyle::Standard, "standard", "usual LSP protocol"),
         clEnumValN(JSONStreamStyle::Delimited, "delimited",
                    "messages delimited by --- lines, with # comment support")),
     llvm::cl::init(JSONStreamStyle::Standard));
 
 static llvm::cl::opt<bool>
+    LogToStderr("log-to-stderr",
+                llvm::cl::desc("Output LSP communication on stderr"),
+                llvm::cl::init(false));
+
+static llvm::cl::opt<bool>
     PrettyPrint("pretty", llvm::cl::desc("Pretty-print JSON output"),
                 llvm::cl::init(false));
 
-static llvm::cl::opt<bool> Test(
-    "lit-test",
+static llvm::cl::opt<bool>
+    Test("lit-test",
          llvm::cl::desc(
-        "Abbreviation for -input-style=delimited -pretty -run-synchronously. "
-        "Intended to simplify lit tests."),
+             "Abbreviation for -input-style=delimited -pretty -log-to-stderr "
+             "-run-synchronously. Intended to simplify lit tests."),
          llvm::cl::init(false), llvm::cl::Hidden);
 
 static llvm::cl::opt<PCHStorageFlag> PCHStorage(
     "pch-storage",
     llvm::cl::desc("Storing PCHs in memory increases memory usages, but may "
                    "improve performance"),
     llvm::cl::values(
         clEnumValN(PCHStorageFlag::Disk, "disk", "store PCHs on disk"),
         clEnumValN(PCHStorageFlag::Memory, "memory", "store PCHs in memory")),
static llvm::cl::opt<Path> YamlSymbolFile(
     llvm::cl::init(""), llvm::cl::Hidden);
 
 int main(int argc, char *argv[]) {
   llvm::sys::PrintStackTraceOnErrorSignal(argv[0]);
   llvm::cl::ParseCommandLineOptions(argc, argv, "clangd");
   if (Test) {
     RunSynchronously = true;
     InputStyle = JSONStreamStyle::Delimited;
+    LogToStderr = true;
     PrettyPrint = true;
   }
 
   if (!RunSynchronously && WorkerThreadsCount == 0) {
     llvm::errs() << "A number of worker threads cannot be 0. Did you mean to "
                     "specify -run-synchronously?";
     return 1;
   }
int main(int argc, char *argv[]) {
   }
 
   llvm::Optional<trace::Session> TracingSession;
   if (Tracer)
     TracingSession.emplace(*Tracer);
 
   JSONOutput Out(llvm::outs(), llvm::errs(),
                  InputMirrorStream ? InputMirrorStream.getPointer() : nullptr,
-                 PrettyPrint);
+                 LogToStderr, PrettyPrint);
 
   clangd::LoggingSession LoggingSession(Out);
 
   // If --compile-commands-dir arg was invoked, check value and override default
   // path.
   llvm::Optional<Path> CompileCommandsDirPath;
   if (CompileCommandsDir.empty()) {
     CompileCommandsDirPath = llvm::None;

test/clangd/protocol.test

-# RUN: not clangd -pretty -run-synchronously < %s | FileCheck -strict-whitespace %s
-# RUN: not clangd -pretty -run-synchronously < %s 2>&1 | FileCheck -check-prefix=STDERR %s
+# RUN: not clangd -pretty -log-to-stderr -run-synchronously < %s | FileCheck -strict-whitespace %s
+# RUN: not clangd -pretty -log-to-stderr -run-synchronously < %s 2>&1 | FileCheck -check-prefix=STDERR %s
 # vim: fileformat=dos
 # It is absolutely vital that this file has CRLF line endings.
 #
 # Note that we invert the test because we intent to let clangd exit prematurely.
 #
 # Test protocol parsing
 Content-Length: 125
 Content-Type: application/vscode-jsonrpc; charset-utf-8

test/clangd/too_large.test

-# RUN: not clangd -run-synchronously < %s 2>&1 | FileCheck -check-prefix=STDERR %s
+# RUN: not clangd -run-synchronously -log-to-stderr < %s 2>&1 | FileCheck -check-prefix=STDERR %s
 # vim: fileformat=dos
 # It is absolutely vital that this file has CRLF line endings.
 #
 Content-Length: 2147483648
 
 # STDERR: Skipped overly large message