It seems we don't implement doctor-run as a client command. We should, tell Chris to fix this.

LyndonArmitage commented 5 months ago

Describe the bug

I've been trying to get my neovim working as a replacement for IntelliJ (especially given their support for Scala 3 is so-so), and to that end I've enabled the nvim-dap plugin.

I've been able to debug tests using nvim-metals but every log line produced from those tests pauses the debugger and displays the following message:

[pool-1-thread-1-ScalaTest-running-MainTest] INFO hbi.indexing.Main$ - Generating Index events
There is a doctor-run command attatched to this, would you like to execute it?
1: yes
2: no
Type number and <Enter> or click with the mouse (q or empty cancels): 1[nvim-metals] It seems we don't implement doctor-run as a client command. We should, tell Chris to fix this.
Press ENTER or type command to continue

The first line is the log line from a test. In this example I have selected 1, and am met with the doctor-run client command message.

These lines also produce bloop report files in .metals/.reports/bloop/. An example file called .metals/.reports/bloop/2024-01-22/r_\[pool-1-thread-1-Sca..._21-37-56-482.md

error id: 2t7Pf/ytXqxQha6LXgcnxg==
### Bloop error:

[pool-1-thread-1-ScalaTest-running-MainTest] INFO hbi.indexing.Main$ - Generating Index events
#### Short summary: 

[pool-1-thread-1-ScalaTest-running-MainTest] INFO hbi.indexing.Main$ - Generating Index events

Some useful extracts from the MetalsRunDoctor command:

Metals Server version: 1.2.0
Metals Java: 1.8.0_392 from Oracle Corporation located at /usr/lib/jvm/java-8-openjdk/jre
Build definition is coming from sbt.
Build server currently being used is Bloop v1.5.13.

I am using sbt 1.9.8 and targeting Scala 3.2.2.

My nvim-metals config looks as followed:

local nvim_metals_group = vim.api.nvim_create_augroup("nvim-metals", { clear = false })
vim.api.nvim_create_autocmd("FileType", {
  pattern = { "scala", "sbt", "java" },
  callback = function()
    local metals_config = require("metals").bare_config()
    metals_config.settings.testUserInterface = "Test Explorer"
    metals_config.init_options.statusBarProvider = "on"
    metals_config.init_options.testExplorerProvider = true

    metals_config.on_attach = function(client, bufnr)
      require("metals").setup_dap()
      vim.keymap.set("n", "[d", function() vim.diagnostic.goto_next() end)
      vim.keymap.set("n", "]d", function() vim.diagnostic.goto_prev() end)
      vim.keymap.set("n", "K", vim.lsp.buf.hover)
      vim.keymap.set("n", "<leader>t", function() require("telescope").extensions.metals.commands() end)
    end
    require("metals").initialize_or_attach(metals_config)
  end,
  group = nvim_metals_group,
})

The dap configuration is located in another file and looks like this (without the keybindings):

local dap = require("dap")

dap.configurations.scala = {
  {
    type = "scala",
    request = "launch",
    name = "Run or Test Target",
    metals = {
      runType = "runOrTestFile",
    },
  },
  {
    type = "scala",
    request = "launch",
    name = "Test Target",
    metals = {
      runType = "testTarget",
    },
  },
}

Expected behavior

As a naive user, I'd expect there to be no interactive output unless I have specified a breakpoint with nvim-dap (which does work). The log messages are present in the REPL which can be toggled open.

Operating system

Linux

Version of Metals

1.2.0

Commit of nvim-metals

d47287324d1e2efdb7aabde73fad5fd5b2b438bf

ckipp01 commented 5 months ago

Hey @LyndonArmitage, there was an issue related to this on the Metals side since the last release that has been fixed already. Could you try the latest snapshot and see if that fixes your issue? You can just set serverVersion in your metals config settings to latest.snapshot and then trigger a :MetalsUpdate and you'll pull in the latest.

LyndonArmitage commented 5 months ago

Thanks for the quick response!

Okay. I altered my configuration and added this line:

    metals_config.settings.serverVersion = "latest.snapshot"

Then ran :MetalsUpdate

The logs say it is using Metals version 1.2.0+77-ecb7dcfd-SNAPSHOT

I tried creating a dummy test in Scala

class MainTest extends AnyFlatSpec with Matchers {
  "dummy test" should "work" in {
    val logger = LoggerFactory.getLogger(getClass)
    logger.info("Foo")
    logger.info("Bar")
    println("foobar now")
  }
}

I still get a message every time a log message appears:

[pool-1-thread-1-ScalaTest-running-MainTest] INFO MainTest - Foo
There is a metals-doctor-run command attatched to this, would you like to execute it?
1: yes
2: no
Type number and <Enter> or click with the mouse (q or empty cancels):

But I no longer get the: It seems we don't implement doctor-run as a client command. We should, tell Chris to fix this. message, which is progress. If I select 1 the Metals Doctor display appears after the test is run.

Interestingly, the REPL logs look like this:

MainTest:
dummy test
foobar now
[pool-1-thread-1-ScalaTest-running-MainTest] INFO MainTest - Foo
[pool-1-thread-1-ScalaTest-running-MainTest] INFO MainTest - Bar
- should work
Main
Execution took 51ms
1 tests, 1 passed
All tests in MainTest passed

===============================================
Total duration: 51ms
All 1 test suites passed.
===============================================

Which puts the log messages after the println() but that might just be the logging framework.

What's interesting is that the message There is a metals-doctor-run command attatched to this, would you like to execute it? doesn't seem to actually pause the tests at all, which is good, but it pops up for every message from the logger.

So a test like:

  "dummy test" should "work" in {
    val logger = LoggerFactory.getLogger(getClass)
    (0 to 5).foreach {i =>
      logger.info(s"Foo $i")
      logger.info(s"Bar $i")
      println(s"foobar now $i")
    }
    println("foobar end")
  }

Has it pop up 10 times (5 times each for the Foo and Bar log lines).

Since this seems related to the log lines, it might help if I share the logging library used: "org.slf4j" % "slf4j-simple" % "2.0.9",.

slf4j-simple logs all log levels to System.err which is probably the issue I am seeing here!

If I replace the logging framework with "org.slf4j" % "slf4j-nop" % "2.0.9", the issue goes away (no logs), likewise if I use a better logging implementation like logback (I am compiling on Java 8 right now :frowning_face:):

"org.slf4j" % "slf4j-api" % "2.0.9",
"ch.qos.logback" % "logback-core" % "1.3.14",
"ch.qos.logback" % "logback-classic" % "1.3.14",

The issue goes away too! So this is probably a case of wrong expectations on my part.

To summarise:

Any output to System.err gets flagged by Metals and trigger the There is a metals-doctor-run command attatched to this, would you like to execute it? message when running code using nvim-dap.
In Metals 1.2.0 the feature to handle these messages is not implemented so you get an error message when selecting yes: [nvim-metals] It seems we don't implement doctor-run as a client command. We should, tell Chris to fix this.
The above error message is solved in the latest snapshot (at least 1.2.0+77-ecb7dcfd-SNAPSHOT)

The remaining questions I have are as follows:

Is this default behaviour desirable? Given that if something (like slf4j-simple) logs a lot of message to stderr/System.err it will render nvim unusable until you clear all the messages.
Should there be some kind of configuration option to disable the warning on every write to stderr/System.err, and just pop up once?

I am not 100% sure if the potential changes highlighted in the questions above would be done in nvim-metals or nvim-dap.

ckipp01 commented 5 months ago

Thanks a lot for the detailed investigation @LyndonArmitage!

Is this default behaviour desirable? Given that if something (like slf4j-simple) logs a lot of message to stderr/System.err it will render nvim unusable until you clear all the messages.

I'm not actually sure. I'm a bit surprised by this behavior. Maybe @tgodzik or @adpi2 will have more information here, but is this expected to report errors in Metals when any stderr or System.err is detected? @LyndonArmitage when you look in the Doctor when you get this message, do you see any actual actionable errors or messages in there about something wrong`?

Should there be some kind of configuration option to disable the warning on every write to stderr/System.err, and just pop up once?

There isn't, but i'm reconsidering the implementation I have here where there is an action attached to the status to show a pop up. In VS Code for example this isn't blocked and doesn't steal the users' input where it does in nvim. What you're experiencing is partly due to how I've implemented this, but ideally if we're sending an action like this that isn't useful, then we should also address that.

tgodzik commented 5 months ago

I'm not actually sure. I'm a bit surprised by this behavior. Maybe @tgodzik or @adpi2 will have more information here, but is this expected to report errors in Metals when any stderr or System.err is detected?

Not really expected, we only send that if Bloop send something via error, but not when using DAP, so this is highly unexpected. What is the command being send actually?

LyndonArmitage commented 5 months ago

I get errors like this in my MetalsDoctor run:

### Test suite aborted
- timestamp: 1706006228395
- uri: file:///home/lyndon/repos/data-platform/indexing/.metals/.reports/bloop/2024-01-23/r_Test%20suite%20aborted_10-37-08-395.md
- error type: bloop

#### Summary
Test suite aborted

This is how I was originally able to find the reports section of the .metals folder.

I'm sorry, but once I figured this was to do with the logging framework and the treatment of error logging I switched to something that didn't send all logs to error in order to work with less issues.

If it helps, I am running these tests through metals Select Test Case or Select Test Suite commands.

LyndonArmitage commented 5 months ago

Bloop just released a new version that might address some of the issues I saw in my logs.

https://github.com/scalacenter/bloop/releases/tag/v1.5.14

They mention in one of the merged PRs about changing something from Error to Warn to reduce how prominent Metals displays it: https://github.com/scalacenter/bloop/pull/2214

tgodzik commented 5 months ago

We started at some point to show errors more prominent for the users, but that wasn't neccessarily useful in all the cases, so I am reducing the ones that don't help or happen consistently in a workspace.

LyndonArmitage commented 5 months ago

Thanks for the context @tgodzik.

Not sure how to proceed on this issue, happy to close it if you guys feel it isn't helpful to keep it around anymore :smiley: as I have worked around the issue by avoiding logging to stderr/System.err for now.

scalameta / nvim-metals