Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Allowed logging of errors to be quieted. #165

Merged
merged 3 commits into from
Nov 6, 2022

Conversation

scohen
Copy link
Contributor

@scohen scohen commented Oct 14, 2022

While using elixir-ls, frequently, the code that's sent to the LSP server (and then to elixir_sense) isn't always syntactically accurate, and sometimes elixir_sense will fail and spam the logs. After enough of these spammy logs, emacs throws the error into a mini-buffer to alert the user to some problem, which is not particularly helpful.

Emitting an error message in these circumstances is dubious, since there's nothing truly wrong, but I can understand that it might be helpful for other uses of elixir_ls. To that end, I consolidated the logging functions into a module and gated them with an application variable so that other apps can enable or disable logging at their discretion.

While using elixir-ls, frequently, the code that's sent to the LSP
server (and then to elixir_sense) isn't always syntactically accurate,
and sometimes elixir_sense will fail and spam the logs. After enough
of these spammy logs, emacs throws the error into a mini-buffer to
alert the user to some problem, which is not particularly helpful.

Emitting an error message in these circumstances is dubious, since
there's nothing truly wrong, but I can understand that it might be
helpful for other uses of elixir_ls. To that end, I consolidated the
logging functions into a module and gated them with an application
variable so that other apps can enable or disable logging at their
discretion.
@scohen
Copy link
Contributor Author

scohen commented Oct 14, 2022

I didn't integrate into logger because then it would be more difficult to quiet logging just for elixir_sense, while retaining it for other applications.

FYI, the following code

defmodule Foo do
  @spec^
  def stuff(a, b) do
  end
end

where ^ is the cursor
generates this logspam

warning: CaseClauseError during metadata build: no case clause matching: [{:stuff, [line: 4, column: 7], [{:a, [line: 4, column: 13], nil}, {:b, [line: 4, column: 16], nil}]}, [do: {:__block__, [], []}]]
  (elixir_sense 2.0.0) lib/elixir_sense/core/metadata_builder.ex:616: ElixirSense.Core.MetadataBuilder.pre/2
  (elixir_sense 2.0.0) lib/elixir_sense/core/metadata_builder.ex:56: anonymous fn/3 in ElixirSense.Core.MetadataBuilder.safe_call/1
  (elixir 1.13.4) lib/macro.ex:462: Macro.do_traverse/4
  (stdlib 4.0) lists.erl:1462: :lists.mapfoldl_1/3
  (elixir 1.13.4) lib/macro.ex:468: Macro.do_traverse/4
  (stdlib 4.0) lists.erl:1462: :lists.mapfoldl_1/3
  (stdlib 4.0) lists.erl:1463: :lists.mapfoldl_1/3
  (elixir 1.13.4) lib/macro.ex:448: Macro.do_traverse/4

Honestly, I think the right answer here is to not throw exceptions and ignore unhandled forms in both pre and post, but logging stuff to stdout doesn't feel right to me anyways.

scohen added a commit to scohen/elixir-ls that referenced this pull request Oct 14, 2022
Right now, this change is a no-op, but if and when this change
elixir-lsp/elixir_sense#165
lands, this will quiet elixir_sense's logging in the prod
environment, which will prevent logspam in lsp buffers when
elixir_sense encounters invalid code.
@lukaszsamson
Copy link
Collaborator

I'm tot convinced that this is the right way to go. Obviously we cannot expect the code to deal with every possible incorrect/incomplete AST but silently ignoring it is also not going to be helpful. Error logging here helps in finding gaps in coverage - there is some really weird elixir code out there.

After enough of these spammy logs, emacs throws the error into a mini-buffer to alert the user to some problem, which is not particularly helpful.

Isn't that something specific to emacs? vscode is happily logging errors to Output. Besides that, before logging as introduced here, elixir_sense would simply crash and let the language server emit error jsonrpc response.

My speculation is that the problem here is logging to stderr. stderr is translated to LSP Warning message in elixir-ls. How about trying using Logger here and info/debug log level? Maybe emacs language client has some rules on the amount of warnings emitted by language server.

@scohen
Copy link
Contributor Author

scohen commented Oct 17, 2022

@lukaszsamson let me try to convince you of this approach

I see four types of users.

  1. I'm a user of elixir-ls, and of elixir-sense, and I'm going about my day
  2. I'm a user of elixir-ls and I need to debug an issue that I'm having with it
  3. I'm a developer of elixir-ls
  4. I'm using elixir_sense in my own project

The first thing to agree upon is that this type of error happens all the time while editing code. It is not an error, but an expected state where the code is syntactically incomplete for a short time. For me, it often happens two or three times every second until elixir_sense matches a case.

Now let's talk about the users.

The first user is representative of the vast majority of the people who consume elixir-sense. They're simply typing in code, and then having it loudly complain to them all the time. There's no reason at all for them to care about the messages and they're never going to check them. To sum up, the messages are wasteful to them. Disabling wasteful frequent messages is good for both UX and performance. As it stands right now, the server has to handle an exception, build an error, marshal it to JsonRPC and write it to stdout, while the client has to read the message from stdin, decode the JsonRPC and then display or buffer that message somewhere. All that work can be eliminated.

The second user, needs to debug something in elixir_ls, and to do so they, as I have done, download the source and compile it. Alternately, I could make it possible for them to pass an envar to the elixir-ls language server that enables debug logs. Their needs are met easily here, as long as we document how to enable debug logging.

The third user, the elixir-ls developer, almost certainly has an in-progress copy of the code that's been compiled in dev mode, their logs will show, since logging is only enabled in production (elixir-lsp/elixir-ls#748).

Finally, the fourth user is the one who's using elixir-sense somewhere else. Their project has logger integrated and they don't want to see elixir_sense errors in their logging.

In short, it's a big win for users 1 and 4, and no change for 2 and 3.

I don't think switching to logger messages would work as well, since you've recently added a backend for JsonRPC, and then there's no way to silence elixir_ls warnings specifically. I'm willing to try it out just to get things quiet, though that approach might cause problems in the future, and again, this carries the annoyance for user 4 that they'll see elixir_sense logs mixed with their logs.

Isn't that something specific to emacs? vscode is happily logging errors to Output.

Yes, this is specific to emacs (and more specifically, to lsp-mode), and I can understand the decision from the perspective of the lsp-mode authors, these are errors after all. Elixirls is presumably a language server for all editors, and not just for vscode. As I've said before, I use a lot of language servers (rust, yaml, python, tailwind, js, ts), and this is the only one with this level of output. The rest are extremely quiet and produce no output.

Besides that, before logging as introduced here, elixir_sense would simply crash and let the language server emit error jsonrpc response.

Well, yes, that's also bad. I'm not suggesting we go back to do that.

I do, however, think that this file needs to handle all forms, even if most of them are a no-op. I'm not a fan of crashing and then picking up the pieces by using try/rescue, that doesn't feel very idiomatic to me. A good subsequent change to this file would be to add a catch-all function head for both pre and post that handles unknown forms and logs a debug message. This change would also involve auditing all case statements in the pre and post functions to ensure that all cases are covered. I'd be more than happy to do this for you.

@lukaszsamson
Copy link
Collaborator

Thanks for detailed answer @scohen. You are probably right. I tend to look at the problem from my perspective. Even when not working on elixir-ls when I look for bugs in the tool to put them on my todo list. From the perspective of other users those are most likely irrelevant.

A good subsequent change to this file would be to add a catch-all function ... that handles unknown forms

That would not work here. Most crashes happen in known forms with broken/incomplete AST

@scohen
Copy link
Contributor Author

scohen commented Oct 24, 2022

@lukaszsamson Everyone looks at things from their perspective, it's a very human thing to do ;)
I'd like to land one more commit here; Now that you've made Logger work in elixir-ls, I think using IO.write directly here doesn't make much sense. I'll forward everything to Logger.log and we should be good to go, correct?

I was thinking about the prior implementation, and I think it would
mess up the line and files due to it calling a function in the Log
module. Making pass through macros surrounded by an if simplifies
things greatly.
@lukaszsamson lukaszsamson merged commit 0af177b into elixir-lsp:master Nov 6, 2022
lukaszsamson pushed a commit to elixir-lsp/elixir-ls that referenced this pull request Nov 6, 2022
Right now, this change is a no-op, but if and when this change
elixir-lsp/elixir_sense#165
lands, this will quiet elixir_sense's logging in the prod
environment, which will prevent logspam in lsp buffers when
elixir_sense encounters invalid code.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants