[PATCH] D44226: [clangd] Add -log-lsp-to-stderr option

[Ilya Biryukov via Phabricator via cfe-commits]

ilya-biryukov added inline comments.


================
Comment at: clangd/ClangdLSPServer.cpp:412
+    llvm::raw_string_ostream OS(Message);
+    OS << "method not found (" << Method << ")";
+    replyError(ErrorCode::MethodNotFound, OS.str());
----------------
simark wrote:
> ilya-biryukov wrote:
> > simark wrote:
> > > simark wrote:
> > > > ilya-biryukov wrote:
> > > > > malaperle wrote:
> > > > > > simark wrote:
> > > > > > > ilya-biryukov wrote:
> > > > > > > > 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.
> > > > > > > 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.
> > > > > > 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.
> > > > > 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").
> > > > > 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.
> > > 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.
> > 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?
> > 
> > 
> > 
> > 
> > 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.
> 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.


Repository:
  rCTE Clang Tools Extra

https://reviews.llvm.org/D44226