diff --git a/CHANGELOG.md b/CHANGELOG.md index 1cdff528..c639d151 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,14 @@ Status of the `main` branch. Changes prior to the next official version change will appear here. +* Language Servers: + - Fix: Scala cross-file queries waited a fixed 5s after the first file was opened, which on a cold + Metals is long before its build import, indexing and compilation have finished; the first + `find_referencing_symbols` of a session could return a fraction of the references with nothing to + indicate it was incomplete. Serena now declares work-done progress support and waits for the work + Metals reports, bounded by the new `indexing_timeout`, `indexing_start_grace` and + `indexing_quiet_period` settings + # v1.7.0 (2026-08-09) * General: diff --git a/docs/02-usage/050_configuration.md b/docs/02-usage/050_configuration.md index 0c611eb0..cc558e41 100644 --- a/docs/02-usage/050_configuration.md +++ b/docs/02-usage/050_configuration.md @@ -1112,6 +1112,13 @@ build below the repository root — it is the build roots, not the repository ro given. Serena detects them automatically; `project_roots` overrides that detection where it guesses wrong, and `project_root_scan_depth` bounds how far it looks. +Metals reports its build import, indexing and compilation as LSP work-done progress, and Serena waits +for all of it before the first cross-file query of a session. This matters most for references, which +Metals serves from SemanticDB — a file the build server only writes once it has compiled the sources, +well after indexing ends — so a query made too early returns a fraction of the true result with +nothing to say it is partial. The wait is bounded by `indexing_timeout`, after which the query +proceeds against whatever Metals has so far and a warning is logged. + Supported settings: | Setting | Default | Description | @@ -1123,6 +1130,9 @@ Supported settings: | `auto_import_build` | `true` | Answer Metals' build-import prompts affirmatively, which lets it run the project's build tool (e.g. `sbt bloopInstall`). Set to `false` to leave the build un-imported; Metals then has no build server, and every cross-file query is served by the fallback presentation compiler. | | `project_roots` | auto-detected | The build roots to serve, as paths relative to the repository root. A path that does not exist is skipped with a warning; if none of them exists, the build roots are detected instead. | | `project_root_scan_depth` | `3` | How many directory levels below the repository root the detection searches. Applies whenever the roots are detected — that is, when `project_roots` is unset, or when it names nothing that exists. | +| `indexing_timeout` | `180` | How long to wait, in seconds, for Metals to finish importing, indexing and compiling before the first cross-file query. On expiry the query proceeds and a warning names what was still outstanding. | +| `indexing_start_grace` | `15` | How long to wait, in seconds, for Metals to report any work at all. A server that reports none within this window is taken to have nothing to do. | +| `indexing_quiet_period` | `3` | How long, in seconds, Metals must report nothing for its work to count as finished. Metals hands off between its phases rather than overlapping them, so it reports nothing for a moment in between; a shorter period risks mistaking that gap for completion. | #### SCSS / Sass / CSS diff --git a/docs/03-special-guides/scala_setup_guide_for_serena.md b/docs/03-special-guides/scala_setup_guide_for_serena.md index e682827c..ef1e653e 100644 --- a/docs/03-special-guides/scala_setup_guide_for_serena.md +++ b/docs/03-special-guides/scala_setup_guide_for_serena.md @@ -87,6 +87,26 @@ ls_specific_settings: project_root_scan_depth: 3 # only applies when project_roots is unset ``` +--- +## Waiting for Metals to be ready + +Metals needs its build imported, its index built and the project compiled before it can answer a +cross-file question completely — references in particular come from SemanticDB, which the build +server writes only as it compiles. Serena waits for all of that, tracking the work-done progress +Metals reports, before the first such query of a session; a query made earlier would return a +fraction of the true result and look no different from a complete one. + +The first `find_referencing_symbols` of a session therefore takes as long as the project takes to +compile. Subsequent queries do not wait. Where the default bound is wrong for a large build: + +```yaml +ls_specific_settings: + scala: + indexing_timeout: 180 # seconds to wait before giving up and answering anyway + indexing_start_grace: 15 # seconds to wait for Metals to report anything at all + indexing_quiet_period: 3 # seconds of silence that count as "finished" +``` + --- ## Running Multiple Metals Instances diff --git a/src/solidlsp/language_servers/scala_language_server.py b/src/solidlsp/language_servers/scala_language_server.py index 450627dd..dabe2284 100644 --- a/src/solidlsp/language_servers/scala_language_server.py +++ b/src/solidlsp/language_servers/scala_language_server.py @@ -6,6 +6,8 @@ import logging import os import shutil import subprocess +import threading +import time from enum import Enum from overrides import override @@ -31,6 +33,9 @@ DEFAULT_ON_STALE_LOCK = "auto-clean" DEFAULT_LOG_MULTI_INSTANCE_NOTICE = True DEFAULT_AUTO_IMPORT_BUILD = True DEFAULT_PROJECT_ROOT_SCAN_DEPTH = 3 +DEFAULT_INDEXING_TIMEOUT = 180.0 +DEFAULT_INDEXING_START_GRACE = 15.0 +DEFAULT_INDEXING_QUIET_PERIOD = 3.0 # The `window/showMessageRequest` actions Serena answers affirmatively: the ones standing between # an un-imported workspace and a build server. Everything else is dismissed, since a prompt we do @@ -81,6 +86,139 @@ BUILD_ROOT_MARKER_JSON_DIRS = (".bloop", ".bsp") BUILD_ROOT_SCAN_SKIP_DIRS = frozenset({"node_modules", "out", "project", "src", "target", "venv"}) +class IndexingOutcome(Enum): + """How a wait for Metals' outstanding work ended.""" + + NO_WORK = "no-work" + """Metals reported nothing at all within the start grace — it may not report progress.""" + + IDLE = "idle" + """Every task Metals reported has finished.""" + + TIMEOUT = "timeout" + """Work was still outstanding when the timeout expired.""" + + +class MetalsProgressTracker: + """ + Tracks the work-done progress Metals reports, so that a cross-file query can wait for its + import, indexing and compilation rather than for a fixed period. References in particular + are served from SemanticDB, which only exists once the build server has compiled the + sources, and that finishes well after indexing does. + + Metals keeps reporting progress for the rest of the session — it loads a presentation + compiler for essentially every file it is asked about — so the tracker answers "is anything + outstanding right now", never "has the server finished for good". + """ + + def __init__(self) -> None: + self._lock = threading.Lock() + self._active: dict[str, str] = {} + self._seen_work = False + self._idle = threading.Event() + self._idle.set() + + def expect_work(self) -> None: + """ + Mark the tracker busy ahead of an action that is expected to make Metals do something, + so that a wait started before the first token arrives blocks rather than returning at once. + """ + self._idle.clear() + + def on_create(self, params: dict) -> dict: + """ + Handle `window/workDoneProgress/create`, which precedes the token's first notification. + + Tracking from creation rather than from `begin` means work announced just before a query + is waited for even if it has not started yet. + + :param params: the request's `WorkDoneProgressCreateParams` + :return: the empty result the request expects + """ + with self._lock: + self._active.setdefault(str(params.get("token", "")), "") + self._seen_work = True + self._idle.clear() + return {} + + def on_progress(self, params: dict) -> None: + """ + Handle a `$/progress` notification, tracking the token's title for diagnostics. + + :param params: the notification's `ProgressParams` + """ + token = str(params.get("token", "")) + value = params.get("value") or {} + kind = value.get("kind") + if kind == "begin": + title = str(value.get("title", "")) + with self._lock: + self._active[token] = title + self._seen_work = True + self._idle.clear() + log.info(f"Metals progress [{token}] started: {title}") + elif kind == "end": + with self._lock: + title = self._active.pop(token, "") + if not self._active: + self._idle.set() + log.info(f"Metals progress [{token}] ended: {title}") + + def wait_until_idle(self, timeout: float, start_grace: float, quiet_period: float) -> IndexingOutcome: + """ + Wait for everything Metals is doing to finish. + + Metals hands off between its phases rather than overlapping them — the import ends, then + indexing begins, then a compilation per module — so its set of tokens empties for a + second or so in between. Readiness is therefore "nothing outstanding for `quiet_period`", + not "nothing outstanding", which would return in the first such gap. + + :param timeout: how long to wait, in seconds, once work is known to be outstanding + :param start_grace: how long to wait, in seconds, for work to appear at all + :param quiet_period: how long, in seconds, Metals must report nothing to count as finished + :return: how the wait ended + """ + grace_deadline = time.monotonic() + start_grace + while time.monotonic() < grace_deadline: + with self._lock: + if self._active or self._seen_work: + break + time.sleep(0.05) + + with self._lock: + if not self._active and not self._seen_work: + self._idle.set() + return IndexingOutcome.NO_WORK + + deadline = time.monotonic() + timeout + while True: + remaining = deadline - time.monotonic() + if remaining <= 0 or not self._idle.wait(timeout=remaining): + return IndexingOutcome.TIMEOUT + if self._stays_idle(quiet_period, deadline): + return IndexingOutcome.IDLE + + def _stays_idle(self, quiet_period: float, deadline: float) -> bool: + """ + :param quiet_period: how long, in seconds, nothing new must be reported + :param deadline: the monotonic time at which to give up regardless + :return: whether the tracker stayed idle for the whole quiet period + """ + quiet_end = time.monotonic() + quiet_period + while time.monotonic() < min(quiet_end, deadline): + if not self._idle.is_set(): + return False + time.sleep(0.05) + return self._idle.is_set() + + def describe(self) -> str: + """:return: compact diagnostic state of Metals' outstanding work.""" + with self._lock: + titles = sorted(title for title in self._active.values() if title) + idle = self._idle.is_set() + return f"idle={idle}, active={', '.join(titles) or ''}" + + class StaleLockMode(Enum): """Mode for handling stale Metals H2 database locks.""" @@ -238,6 +376,18 @@ def _parse_project_root_scan_depth(value: object) -> int: return value +def _parse_positive_float(value: object, name: str, default: float) -> float: + """ + Validate a positive-number setting, falling back to the default if it is unusable. + """ + if value is None: + return default + if isinstance(value, bool) or not isinstance(value, int | float) or value <= 0: + log.warning(f"Invalid {name} value {value!r}, expected a positive number; using {default}") + return default + return float(value) + + def _get_scala_settings(solidlsp_settings: SolidLSPSettings) -> dict[str, object]: """ Extract Scala-specific settings with defaults applied. @@ -250,6 +400,9 @@ def _get_scala_settings(solidlsp_settings: SolidLSPSettings) -> dict[str, object - auto_import_build: bool - project_roots: list[str] | None - project_root_scan_depth: int + - indexing_timeout: float + - indexing_start_grace: float + - indexing_quiet_period: float """ from solidlsp.ls_config import LanguageServerId @@ -261,6 +414,9 @@ def _get_scala_settings(solidlsp_settings: SolidLSPSettings) -> dict[str, object "auto_import_build": DEFAULT_AUTO_IMPORT_BUILD, "project_roots": None, "project_root_scan_depth": DEFAULT_PROJECT_ROOT_SCAN_DEPTH, + "indexing_timeout": DEFAULT_INDEXING_TIMEOUT, + "indexing_start_grace": DEFAULT_INDEXING_START_GRACE, + "indexing_quiet_period": DEFAULT_INDEXING_QUIET_PERIOD, } if not solidlsp_settings.ls_specific_settings: @@ -284,6 +440,13 @@ def _get_scala_settings(solidlsp_settings: SolidLSPSettings) -> dict[str, object "auto_import_build": scala_settings.get("auto_import_build", DEFAULT_AUTO_IMPORT_BUILD), "project_roots": _parse_project_roots(scala_settings.get("project_roots")), "project_root_scan_depth": _parse_project_root_scan_depth(scala_settings.get("project_root_scan_depth")), + "indexing_timeout": _parse_positive_float(scala_settings.get("indexing_timeout"), "indexing_timeout", DEFAULT_INDEXING_TIMEOUT), + "indexing_start_grace": _parse_positive_float( + scala_settings.get("indexing_start_grace"), "indexing_start_grace", DEFAULT_INDEXING_START_GRACE + ), + "indexing_quiet_period": _parse_positive_float( + scala_settings.get("indexing_quiet_period"), "indexing_quiet_period", DEFAULT_INDEXING_QUIET_PERIOD + ), } @@ -312,6 +475,20 @@ class ScalaLanguageServer(SolidLanguageServer): project_roots: ['backend', 'tooling/plugin'] # How many levels below the repository root auto-detection searches project_root_scan_depth: 3 + # How long to wait, in seconds, for Metals to finish indexing and compiling + # before the first cross-file query (see "Indexing") + indexing_timeout: 180 + # How long to wait for that work to *begin* before concluding there is none + indexing_start_grace: 15 + # How long Metals must report nothing for its work to count as finished + indexing_quiet_period: 3 + + Indexing: + Metals reports its import, indexing and compilation as LSP work-done progress, and + references are only complete once the build server has compiled the sources that + produce SemanticDB. The first cross-file query of a session therefore waits for that + work rather than for a fixed period; `indexing_timeout` bounds the wait, after which + the query proceeds against whatever Metals has so far. Build import: Metals asks, via `window/showMessageRequest`, whether to import a workspace it has not @@ -342,7 +519,13 @@ class ScalaLanguageServer(SolidLanguageServer): for build_root in self._build_roots: self._check_metals_db_status(build_root, solidlsp_settings) - self._auto_import_build: bool = _get_scala_settings(solidlsp_settings)["auto_import_build"] # type: ignore[assignment] + settings = _get_scala_settings(solidlsp_settings) + self._auto_import_build: bool = settings["auto_import_build"] # type: ignore[assignment] + self._indexing_timeout: float = settings["indexing_timeout"] # type: ignore[assignment] + self._indexing_start_grace: float = settings["indexing_start_grace"] # type: ignore[assignment] + self._indexing_quiet_period: float = settings["indexing_quiet_period"] # type: ignore[assignment] + + self._progress = MetalsProgressTracker() scala_lsp_executable_path = self._setup_runtime_dependencies(config, solidlsp_settings) super().__init__( @@ -552,18 +735,54 @@ class ScalaLanguageServer(SolidLanguageServer): "copyWorksheetOutputProvider": False, "doctorVisibilityProvider": False, }, - "capabilities": {"textDocument": {"documentSymbol": {"hierarchicalDocumentSymbolSupport": True}}}, + "capabilities": { + "textDocument": {"documentSymbol": {"hierarchicalDocumentSymbolSupport": True}}, + # without this Metals never reports what it is doing, so there is nothing to + # wait on before the first cross-file query + "window": {"workDoneProgress": True}, + }, } return initialize_params def _answer_show_message_request(self, params: dict) -> dict | None: return choose_show_message_request_action(params, auto_import_build=self._auto_import_build) + @override + def _pre_open_for_cross_file_references(self) -> None: + if not self._has_waited_for_cross_file_references: + self._progress.expect_work() + + @override + def _wait_for_cross_file_references_if_needed(self) -> None: + if self._has_waited_for_cross_file_references: + return + + # Opening a file is what makes Metals connect to its build server, so the work only + # begins after the didOpen that precedes this call. + outcome = self._progress.wait_until_idle( + timeout=self._indexing_timeout, + start_grace=self._indexing_start_grace, + quiet_period=self._indexing_quiet_period, + ) + if outcome == IndexingOutcome.NO_WORK: + log.info(f"Metals reported no work within {self._indexing_start_grace:.0f}s; proceeding") + elif outcome == IndexingOutcome.IDLE: + log.info("Metals indexing complete") + else: + log.warning( + "Metals was still working after %.0fs; proceeding, so cross-file results may be incomplete (%s)", + self._indexing_timeout, + self._progress.describe(), + ) + self._has_waited_for_cross_file_references = True + def _start_server(self) -> None: """ Starts the Scala Language Server """ self.server.on_request("window/showMessageRequest", self._answer_show_message_request) + self.server.on_request("window/workDoneProgress/create", self._progress.on_create) + self.server.on_notification("$/progress", self._progress.on_progress) log.info("Starting Scala server process") self.server.start() @@ -573,7 +792,3 @@ class ScalaLanguageServer(SolidLanguageServer): initialize_params = self._create_initialize_params() self.server.send.initialize(initialize_params) self.server.notify.initialized({}) - - @override - def _get_wait_time_for_cross_file_referencing(self) -> float: - return 5 diff --git a/test/solidlsp/scala/test_scala_indexing_progress.py b/test/solidlsp/scala/test_scala_indexing_progress.py new file mode 100644 index 00000000..85cc0e49 --- /dev/null +++ b/test/solidlsp/scala/test_scala_indexing_progress.py @@ -0,0 +1,145 @@ +""" +Unit tests for the tracking of the work-done progress Metals reports. +""" + +import threading +import time + +import pytest + +from solidlsp.language_servers.scala_language_server import ( + DEFAULT_INDEXING_QUIET_PERIOD, + DEFAULT_INDEXING_START_GRACE, + DEFAULT_INDEXING_TIMEOUT, + IndexingOutcome, + MetalsProgressTracker, + _get_scala_settings, +) +from solidlsp.ls_config import LanguageServerId +from solidlsp.settings import SolidLSPSettings + +# `$/progress` as Metals sends it (scala/meta/internal/metals/WorkDoneProgress.scala), whose +# titles are the ones that matter to a cross-file query: the build import, the index, and the +# compilation that produces the SemanticDB references are read from. +IMPORTING = "Importing build" +INDEXING = "Indexing" +COMPILING = "Compiling core" + + +def begin(token: str, title: str) -> dict: + return {"token": token, "value": {"kind": "begin", "title": title}} + + +def report(token: str, message: str = "1s") -> dict: + return {"token": token, "value": {"kind": "report", "message": message}} + + +def end(token: str) -> dict: + return {"token": token, "value": {"kind": "end"}} + + +@pytest.fixture +def tracker() -> MetalsProgressTracker: + return MetalsProgressTracker() + + +def test_no_work_reported(tracker: MetalsProgressTracker) -> None: + """A server that reports nothing must not hold a query for the whole timeout.""" + tracker.expect_work() + started = time.monotonic() + assert tracker.wait_until_idle(timeout=30, start_grace=0.2, quiet_period=0.1) == IndexingOutcome.NO_WORK + assert time.monotonic() - started < 5 + + +def test_waits_for_work_that_starts_within_the_grace(tracker: MetalsProgressTracker) -> None: + tracker.expect_work() + + def work() -> None: + time.sleep(0.1) + tracker.on_progress(begin("t1", INDEXING)) + time.sleep(0.2) + tracker.on_progress(end("t1")) + + threading.Thread(target=work, daemon=True).start() + assert tracker.wait_until_idle(timeout=10, start_grace=2, quiet_period=0.1) == IndexingOutcome.IDLE + + +def test_waits_for_every_outstanding_token(tracker: MetalsProgressTracker) -> None: + """Indexing ending is not readiness: the compilations that follow it must be waited for too.""" + tracker.on_progress(begin("index", INDEXING)) + tracker.on_progress(begin("compile", COMPILING)) + tracker.on_progress(report("index")) + tracker.on_progress(end("index")) + + assert tracker.wait_until_idle(timeout=0.2, start_grace=0.2, quiet_period=0.1) == IndexingOutcome.TIMEOUT + assert COMPILING in tracker.describe() + + tracker.on_progress(end("compile")) + assert tracker.wait_until_idle(timeout=1, start_grace=0.2, quiet_period=0.1) == IndexingOutcome.IDLE + + +def test_token_created_before_it_begins_is_awaited(tracker: MetalsProgressTracker) -> None: + """`window/workDoneProgress/create` arrives first, and work announced that way still counts.""" + assert tracker.on_create({"token": "t1"}) == {} + assert tracker.wait_until_idle(timeout=0.2, start_grace=0.2, quiet_period=0.1) == IndexingOutcome.TIMEOUT + + tracker.on_progress(begin("t1", IMPORTING)) + tracker.on_progress(end("t1")) + assert tracker.wait_until_idle(timeout=1, start_grace=0.2, quiet_period=0.1) == IndexingOutcome.IDLE + + +def test_unknown_and_repeated_ends_do_not_unbalance_the_count(tracker: MetalsProgressTracker) -> None: + tracker.on_progress(begin("t1", INDEXING)) + tracker.on_progress(end("unknown")) + assert tracker.wait_until_idle(timeout=0.2, start_grace=0.2, quiet_period=0.1) == IndexingOutcome.TIMEOUT + + tracker.on_progress(end("t1")) + tracker.on_progress(end("t1")) + assert tracker.wait_until_idle(timeout=1, start_grace=0.2, quiet_period=0.1) == IndexingOutcome.IDLE + + +def test_describe_reports_outstanding_titles(tracker: MetalsProgressTracker) -> None: + assert "" in tracker.describe() + tracker.on_progress(begin("t1", COMPILING)) + described = tracker.describe() + assert COMPILING in described + assert "idle=False" in described + + +def test_indexing_settings_defaults() -> None: + settings = _get_scala_settings(SolidLSPSettings()) + assert settings["indexing_timeout"] == DEFAULT_INDEXING_TIMEOUT + assert settings["indexing_start_grace"] == DEFAULT_INDEXING_START_GRACE + + +@pytest.mark.parametrize("value", [45, 45.0]) +def test_indexing_settings_are_read(value: object) -> None: + settings = _get_scala_settings(SolidLSPSettings(ls_specific_settings={LanguageServerId.SCALA: {"indexing_timeout": value}})) + assert settings["indexing_timeout"] == 45.0 + + +@pytest.mark.parametrize("value", [0, -1, "soon", True, None]) +def test_invalid_indexing_settings_fall_back_to_the_default(value: object) -> None: + settings = _get_scala_settings(SolidLSPSettings(ls_specific_settings={LanguageServerId.SCALA: {"indexing_start_grace": value}})) + assert settings["indexing_start_grace"] == DEFAULT_INDEXING_START_GRACE + + +def test_a_gap_between_phases_does_not_end_the_wait(tracker: MetalsProgressTracker) -> None: + """Metals' token set empties between its phases; the wait must not return in that gap.""" + tracker.on_progress(begin("import", IMPORTING)) + + def work() -> None: + tracker.on_progress(end("import")) + time.sleep(0.4) # the handover, during which nothing is outstanding + tracker.on_progress(begin("index", INDEXING)) + time.sleep(0.2) + tracker.on_progress(end("index")) + + threading.Thread(target=work, daemon=True).start() + started = time.monotonic() + assert tracker.wait_until_idle(timeout=10, start_grace=1, quiet_period=0.6) == IndexingOutcome.IDLE + assert time.monotonic() - started >= 0.6, "returned during the gap, before indexing began" + + +def test_quiet_period_default_is_read() -> None: + assert _get_scala_settings(SolidLSPSettings())["indexing_quiet_period"] == DEFAULT_INDEXING_QUIET_PERIOD