Intermittent `Request textDocument/completion failed` from R LSP

[juliasilge]

As I am working on various projects, I am noticing that occasionally I see this error:

I have no idea what I am doing that prompts this. Just now, I was typing in a .R file but I have also observed in while working in Quarto.

Here are the LSP logs, which were what that "Go to output" prompts me to go to:

lsp.log

[juliasilge]

I may feel like it happens more when I am typing really fast, maybe?

[DavisVaughan]

[Error - 8:38:54 AM] Request textDocument/completion failed.
  Message: Unexpected empty option value

Stack backtrace:
   0: std::backtrace::Backtrace::create
   1: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from
   2: ark::lsp::completions::sources::unique::custom::completions_from_custom_source
   3: ark::lsp::completions::sources::unique::completions_from_unique_sources
   4: core::ops::function::FnOnce::call_once{{vtable.shim}}
   5: harp::exec::r_top_level_exec::c_fn
   6: R_ToplevelExec
             at /Volumes/Builds/R4/R-4.4.0/src/main/context.c:804:2
   7: harp::exec::r_sandbox
   8: tracing::span::Span::in_scope
   9: ark::interface::RMain::handle_task
  10: ark::interface::RMain::handle_task_concurrent
  11: ark::interface::RMain::read_console
  12: harp::exec::r_top_level_exec::c_fn
  13: R_ToplevelExec
             at /Volumes/Builds/R4/R-4.4.0/src/main/context.c:804:2
  14: harp::exec::r_sandbox
  15: _r_read_console
  16: Rf_ReplIteration
             at /Volumes/Builds/R4/R-4.4.0/src/main/main.c:210:10
  17: R_ReplConsole
             at /Volumes/Builds/R4/R-4.4.0/src/main/main.c:314:11
  18: run_Rmainloop
             at /Volumes/Builds/R4/R-4.4.0/src/main/main.c:1216:5
  19: ark::interface::start_r
  20: ark::main
  21: std::sys_common::backtrace::__rust_begin_short_backtrace
  22: std::rt::lang_start::{{closure}}
  23: std::rt::lang_start_internal
  24: _main
  Code: -1 

not sure why yet but this is where it comes from

[DavisVaughan]

If you can reproduce, can you also capture and report the Console: R logs?

[DavisVaughan]

Okay, I have a decent idea about what is happening and can reproduce locally (though, nothing reliable).

In https://github.com/posit-dev/amalthea/pull/361 @lionel- introduced some more advanced logging of LSP errors, including sending LSP errors to the frontend, which we were not doing much before:

https://github.com/posit-dev/amalthea/blob/1ed00708871382510245288fd765b9a4ab4914d4/crates/ark/src/lsp/main_loop.rs#L367-L384

I have a feeling this error was happening before and was logging it to Console: R, but now the LSP middleware that we go through receives this error response and triggers a toast notification, rather than just logging the error to the Output channel for the LSP.

---

I managed to trigger locally in a debug build (which includes file locations)

[Error - 11:05:56 AM] Request textDocument/completion failed.
  Message: Unexpected empty option value

Stack backtrace:
   0: std::backtrace_rs::backtrace::libunwind::trace
             at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/../../backtrace/src/backtrace/libunwind.rs:104:5
   1: std::backtrace_rs::backtrace::trace_unsynchronized
             at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2: std::backtrace::Backtrace::create
             at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/std/src/backtrace.rs:331:13
   3: anyhow::error::<impl core::convert::From<E> for anyhow::Error>::from
             at /Users/davis/.cargo/registry/src/index.crates.io-6f17d22bba15001f/anyhow-1.0.80/src/error.rs:565:25
   4: <core::result::Result<T,F> as core::ops::try_trait::FromResidual<core::result::Result<core::convert::Infallible,E>>>::from_residual
             at /rustc/82e1608dfa6e0b5569232559e3d385fea5a93112/library/core/src/result.rs:1963:27
   5: ark::lsp::completions::sources::unique::custom::completions_from_custom_source_impl
             at /Users/davis/files/programming/positron/amalthea/crates/ark/src/lsp/completions/sources/unique/custom.rs:86:21
   6: ark::lsp::completions::sources::unique::custom::completions_from_custom_source
             at /Users/davis/files/programming/positron/amalthea/crates/ark/src/lsp/completions/sources/unique/custom.rs:66:5

This points at: https://github.com/posit-dev/amalthea/blob/1ed00708871382510245288fd765b9a4ab4914d4/crates/ark/src/lsp/completions/sources/unique/custom.rs#L86

And I have long thought that our signature-help method needs a rewrite, it has been the cause of quite a few issues over the past few months. I am not sure what the exact issue is yet though.

---

Here is the reverse engineered script, I managed to get it to fire sometimes while finishing out bathr -> bathroom in that first select() statement.

library(tidyverse)
library(arrow)
library(pins)

housing <- tibble::as_tibble(mlr3data::kc_housing) |>
  mutate(date = as.Date(date)) |>
  select(price, bedrooms, bathr)

summary(housing$date)

path1 <- here::here("data", "housing.parquet")
path2 <- here::here("data", "housing_monitoring.parquet")

housing |>
  filter(date < ymd("2015-01-01")) |>
  arrange(date) |>
  write_parquet(path1)

housing |>
  filter(date >= ymd("2015-01-01")) |>
  arrange(date) |>
  write_parquet(path2)

library(tidymodels)
set.seed(123)
housing_split <- housing |>
  filter(date < ymd("2015-01-01")) |>
  arrange(date) |>
  initial_split(prop = 0.8)

housing_train <- training(housing_split)
housing_test <- testing(housing_split)

housing_rec <-
  recipe(price ~ bedrooms + bathrooms + sqft_living + yr_built,
  data = housing_train)

housing_fit <-
  workflow(
    housing_rec,
    rand_forest(trees = 200, mode = "regression")
  ) |>
  fit(data = housing_train)

augment(housing_fit, new_data = slice_sample(housing_test, n = 10)) |>
  select(-aka_name)

library(vetiver)

v <- vetiver_model(inspect_fit, "julia.silge/chicago-inspections-rstats")
board <- board_connect()
board |> vetiver_pin_write(v)

vetiver_deploy_rsconnect(
  board = board,
  name = "julia.silge/chicago-inspections-rstats",
  predict_args = list(debug = TRUE),
  account = "julia.silge",
  appName = "chicago-inspections-rstats-model-api",
  forceUpdate = TRUE
)

hoursing_fit <-
  workflow(
    housing_rec,
    rand_forest(trees = 200, mode = "regression")
  ) |>
  fit(data = housing_train)

augment(housing_fit, new_data = slice_sample(housing_test, n = 10)) |>
  select(-aka_name)

[juliasilge]

Thank you for looking into all that detail! I believe you are exactly right about where the error is happening in this case, and I believe I have also seen it when selecting columns within a dplyr verb, in a Quarto chunk.

[lionel-]

I can consistently reproduce, it seems to happen when typing at the n + 1 position in an argument list of a function with n parameters. I get a textDocument/completion failed request.

Another issue occurs in functions taking ..., this time it's a completionItem/resolve failure.

https://github.com/posit-dev/positron/assets/4465050/a3800bf7-dfba-4cee-9cca-d73ea58f05c6

foo <- function() {}
foo2 <- function(x) {}

foo()
foo2()

bar <- function(...) {}

bar()

[yutannihilation]

Another issue occurs in functions taking ..., this time it's a completionItem/resolve failure.

Here's a stack trace and help.rs:142 is this line:

https://github.com/posit-dev/ark/blob/8d44a5bc325312ede6e86d28ca5a57d82394b6e0/crates/ark/src/lsp/help.rs#L142

[Error - 9:03:50 PM] Failure while handling event:
Error while handling request:
Unexpected empty option value

Stack backtrace:
   0: std::backtrace_rs::backtrace::dbghelp64::trace
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library\std\src\..\..\backtrace\src\backtrace\dbghelp64.rs:91
   1: std::backtrace_rs::backtrace::trace_unsynchronized
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library\std\src\..\..\backtrace\src\backtrace\mod.rs:66
   2: std::backtrace::Backtrace::create
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library\std\src\backtrace.rs:331
   3: std::backtrace::Backtrace::capture
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081/library\std\src\backtrace.rs:296
   4: anyhow::error::impl$1::from<stdext::unwrap::EmptyOptionError>
             at C:\Users\Yutani\.cargo\registry\src\index.crates.io-6f17d22bba15001f\anyhow-1.0.80\src\backtrace.rs:27
   5: core::result::impl$27::from_residual<tuple$<>,stdext::unwrap::EmptyOptionError,anyhow::Error>
             at /rustc/129f3b9964af4d4a709d1383930ade12dfe7c081\library\core\src\result.rs:1964
   6: ark::lsp::help::RHtmlHelp::parameters<ark::lsp::help::impl$0::parameter::closure_env$0>
             at C:\Users\Yutani\Documents\GitHub\ark\crates\ark\src\lsp\help.rs:142
   7: ark::lsp::help::RHtmlHelp::parameter
             at C:\Users\Yutani\Documents\GitHub\ark\crates\ark\src\lsp\help.rs:196
   8: ark::lsp::completions::resolve::resolve_parameter_completion_item
             at C:\Users\Yutani\Documents\GitHub\ark\crates\ark\src\lsp\completions\resolve.rs:103
   9: ark::lsp::completions::resolve::resolve_completion
             at C:\Users\Yutani\Documents\GitHub\ark\crates\ark\src\lsp\completions\resolve.rs:37
  10: ark::lsp::handlers::handle_completion_resolve::closure$0
             at C:\Users\Yutani\Documents\GitHub\ark\crates\ark\src\lsp\handlers.rs:194
  11: ark::r_task::r_task::closure$0<ark::lsp::handlers::handle_completion_resolve::closure_env$0,enum2$<core::result::Result<bool,anyhow::Error> > >
             at C:\Users\Yutani\Documents\GitHub\ark\crates\ark\src\r_task.rs:170

...snip...

This is a very tricky problem due to a coincidence that the function name bar is the same as the alisas to the help topic plotmath (you can confirm by executing ?bar in an R console). Since plotmath is not the type of help page that describes about function usages, it doesn't have Arguments section.