diff --git a/.memory/unprocessed/daemon-logger-lock-scope.md b/.memory/unprocessed/daemon-logger-lock-scope.md new file mode 100644 index 0000000..4a63534 --- /dev/null +++ b/.memory/unprocessed/daemon-logger-lock-scope.md @@ -0,0 +1,7 @@ +# Daemon logger isolation does not cover the `run` wrapper before exec + +The daemon starts its configured server through a child `lsp-cli run` process. That wrapper writes +startup records through the global synchronous system logger before it replaces itself with the +actual LSP server. Consequently, holding the global log lock before initial daemon startup can still +delay server startup even after daemon-owned logging is isolated. The latency playground must acquire +the lock after the daemon reports `READY` when testing coordinator responsiveness. diff --git a/.memory/unprocessed/references-lua-performance.md b/.memory/unprocessed/references-lua-performance.md deleted file mode 100644 index 54a4a50..0000000 --- a/.memory/unprocessed/references-lua-performance.md +++ /dev/null @@ -1,32 +0,0 @@ -# References query performance investigation (2026-09-05) - -User requested investigation of a 17.715-second detached references query for -`normalize_timestamp` in `/home/segoon/projects/parley.nvim`. - -Installed `/home/segoon/.cargo/bin/lsp-cli` reproduced the same result in 19.744 and -22.107 seconds without debug logging. A timestamped debug run took 20.303 seconds: -initialize 0.076 s, workspace/symbol 0.040 s, 188 sequential documentSymbol requests -17.368 s combined, references 0.063 s, shutdown 0.024 s. Debug logging adds overhead, -so these are phase measurements, not a controlled estimate of every source of latency. - -`select_named_anchors` always scans all matching documents when document symbols are -supported. It is not merely a fallback for empty workspace-symbol results. Here -workspace/symbol returned null, so preferring workspace results alone would not help. -The scanned files were 100 under lua/, 86 under tests/, one plugin and one script. -Only lua/parley/timestamp.lua contains the literal query (checked with rg). - -Daemon::serve sleeps 25 ms after each iteration, draining upstream before downstream. -This adds latency to sequential exchanges, independently of server computation. ---limit truncates final output and does not bound discovery work. - -Direct runs used an isolated XDG_RUNTIME_DIR because connect_lsp_client reuses existing -sockets even with --no-detach. They took 45.521 s with debug and 44.738 s without: -query work finished, but server exit timed out after another 30 seconds. This is a -separate unresolved behavior, documented in GOTCHAS.md, not a successful workaround. - -Potential changes: event-driven daemon wakeups preserve discovery semantics but need -transport work; literal source prefiltering greatly reduces candidates here but could -miss server-provided names absent literally from source. No runtime code was changed. -Future regressions should exercise delayed/local-symbol discovery and verify protocol -request counts; daemon latency checks should use a fake immediate-response server. -Timestamped traces and result files are in /tmp/lsp-cli-{detached,direct}* for this session. diff --git a/.memory/unprocessed/release-reference-profile.md b/.memory/unprocessed/release-reference-profile.md deleted file mode 100644 index 18345f6..0000000 --- a/.memory/unprocessed/release-reference-profile.md +++ /dev/null @@ -1,117 +0,0 @@ -# Release references benchmark and remaining latency (2026-09-05) - -## User correction - -The user asked to investigate remaining latency and explicitly corrected the use of -**debug** benchmarks: use **release**. Future performance comparisons must build with -`cargo build --release` and invoke `target/release/lsp-cli`. No new product preference -or architectural decision was requested in this investigation. - -## Measurements - -Built the current uncommitted implementation in release. Ran without --debug against -/home/segoon/projects/parley.nvim, using isolated config/runtime directories and the -installed LuaLS executable. All six reference outputs were identical: - -| Request window | Run 1 | Run 2 | Run 3 | Median | -|---|---:|---:|---:|---:| -| 1 | 19.207 s | 21.177 s | 20.266 s | 20.266 s | -| 20 | 12.982 s | 13.438 s | 13.003 s | 13.003 s | - -These are repeated runs, not guaranteed warm-server runs. The project currently has -193 Lua files, compared with 188 in the earlier debug investigation, so the old and -new series are not a controlled comparison of compiler profiles alone. - -## Remaining time - -A temporary Python pass-through wrapper recorded message timestamps, payload sizes, -and Linux /proc CPU counters for LuaLS without verbose JSON logging. Two release -queries with a window of 20 took 12.809/13.211 seconds: - -- 193 documentSymbol requests: span 12.425/12.774 seconds at the server boundary. -- LuaLS CPU consumed across that span: 12.16/12.61 seconds. -- Foreground CLI user+system CPU: 0.574/0.626 seconds (excludes daemon CPU). -- Each run returned 5.509 MB of document-symbol JSON and about 300 diagnostic notifications. -- Actual references request at the server boundary: 0.0034/0.0030 seconds. -- Maximum observed outstanding documentSymbol requests: 20. - -Request latencies overlap and must not be summed as elapsed time. Server CPU and -foreground CPU also overlap; the figures are not additive phase timings. Wrapper -measurements have instrumentation overhead; the uninstrumented series above is the -baseline. - -## Controlled diagnostics comparison - -Used LuaLS --configpath pointing to a temporary copy of the project's .luarc.json, -with an explicit diagnostics.enable value. The real project configuration was not -edited. Both controls used the same wrapper, release binary, and request window 20. - -| diagnostics.enable | Run 1 wall | Run 2 wall | LuaLS CPU during symbol span | -|---|---:|---:|---:| -| true | 12.573 s | 12.375 s | 11.90 / 11.71 s | -| false | 4.502 s | 2.837 s | 3.62 / 2.45 s | - -All reference matches were identical to baseline. Disabled runs emitted no diagnostic -notifications and reused the same daemon/server PID. Thus file-open-triggered -background diagnostics explain much of the remaining cost; symbol generation, parsing, -and transport still remain. This experiment does not establish that disabling -server diagnostics is a generally acceptable behavior change. - -Installed source confirms the trigger: -- libexec/script/provider/provider.lua:271 handles didOpen, files.open, and compileState. -- libexec/script/provider/diagnostic.lua:678 watches file events; the open branch calls - doDiagnostic when the workspace is ready. -- libexec/script/provider/provider.lua:825 handles documentSymbol and converts all - returned symbols; requests still require file-wide symbol generation. - -## Daemon reuse defect - -The trace initially showed a new daemon and server on each command. Capturing daemon -stderr in a separate foreground-managed experiment reproduced: - - failed to write daemon client message: failed to write JSON-RPC message: Broken pipe (os error 32) - -The query itself succeeded. The daemon exited with status 1 and left a stale socket. -The coordinator drains upstream traffic before client events, and downstream write -errors propagate out of serve. Notifications racing with client disconnect can thus -terminate the daemon. This is intermittent: a manually managed daemon also survived -queries that still took 12.9/12.7 seconds, so lost reuse is a separate contributor, -not a complete explanation of the 13-second latency. For a fix, use a fake-server -regression that sends a notification after downstream disconnect and then verifies -that another client can use the same upstream server. - -## Implications and tradeoffs - -- Fixing disconnect handling should preserve reuse without changing query semantics, - but does not remove diagnostics triggered by opening every file again. -- Reducing file opens or caching discovery could avoid more work, but requires an - explicit completeness/invalidation design and server compatibility checks. -- Explicit user-selected LuaLS diagnostic settings give a concrete speed tradeoff: - faster query-only sessions at the cost of diagnostic availability in that session. - Do not hardcode Lua-specific configuration into generic lsp-cli logic. -- Runtime code and normal project/user configuration were not changed here. - -## Artifacts from this session - -- /tmp/lsp-release-bench-0z8zssym/results.json: uninstrumented release baseline. -- /tmp/lsp-release-trace-ab66lhav/{wire.jsonl,runs.json}: normal-config profile. - The wire log also has later foreground-daemon observations; filter by run timestamps. -- /tmp/lsp-diag-control-g7gfa7nw/{wire.jsonl,runs.json}: diagnostics enabled. -- /tmp/lsp-diag-control-h7mzmx60/{wire.jsonl,runs.json}: diagnostics disabled. -- /tmp/lsp-proxy-daemon-exit-v2jzda7x/daemon.stderr: captured broken-pipe failure. -- Benchmark and reproducer scripts: /tmp/lsp-cli-release-benchmark.py, - /tmp/lsp-cli-release-trace.py, /tmp/lsp-lua-trace-proxy.py, - /tmp/lsp-cli-diagnostics-control.py, /tmp/lsp-cli-proxy-daemon-exit-check.py. - -# Encountered difficulties - -## What confused me - -Repeated commands were initially assumed to be warm. PID traces and captured stderr -showed intermittent daemon termination. The live project also gained five Lua files -since the earlier measurements; release/debug cross-series comparisons need that caveat. - -## Where to report - -If you're sure the reported difficulties above are related to techplatform (e.g. userver, c35), -please report to [aisuite](https://nda.ya.ru/t/EcUMOwSH7eudWX). diff --git a/.memory/unprocessed/request-window-implementation.md b/.memory/unprocessed/request-window-implementation.md deleted file mode 100644 index 7baebdd..0000000 --- a/.memory/unprocessed/request-window-implementation.md +++ /dev/null @@ -1,27 +0,0 @@ -# Request-window implementation decisions and validation (2026-09-05) - -The user requested a default of 20 concurrent per-file requests, configurable as -`max-requests-in-flight` in lsp-cli.yaml. During planning the user selected: -- Named queries only (references, definition, declaration, callers, callees). -- Fail on document-symbol timeout instead of silently skipping it. - -The implementation uses bounded document-symbol scheduling in the client, matches -response IDs, decodes immediately, and preserves scan order. Synchronous request -transmission is shared. Do not invoke the unbounded notification-drain helper inside -window scheduling: continuous traffic could prevent deadline checks. Regression tests -exercise continuous notifications, refill with an older outstanding request, reversed -responses, server requests, cancellation, and deterministic named-query results. - -Debug-build benchmark, without verbose logging, with separate temporary configuration -and daemon runtime directories for each limit: -- parley.nvim, limit 1: 20.012 s cold / 22.382 s warm. -- parley.nvim, limit 20: 13.519 s cold / 13.200 s warm. -- Lua playground, limit 1: 1.139 s cold / 0.503 s warm. -- Lua playground, limit 20: 1.148 s cold / 0.352 s warm. -All four outputs for each workspace were identical. These are two measurements per -limit, not a statistical performance guarantee. Artifacts are in -/tmp/lsp-window-bench-7mvr24xb/results.json for this session. - -A direct-process fake server also verified the default window, 23 file requests, -reversed responses, all 23 anchors, and clean shutdown. Its temporary script and -fixture are /tmp/lsp-cli-window-stdio-check.py and /tmp/lsp-window-stdio-msmp85nt. diff --git a/.memory/unprocessed/request-window-validation-difficulties.md b/.memory/unprocessed/request-window-validation-difficulties.md deleted file mode 100644 index cb6237a..0000000 --- a/.memory/unprocessed/request-window-validation-difficulties.md +++ /dev/null @@ -1,27 +0,0 @@ -# Encountered difficulties - -## What confused me - -- The environment contains `/tmp/.git`. Three existing workspace-root tests then - discover `/tmp` as their project root. Running `TMPDIR=/dev/shm make test` isolates - fixture ancestry and passes those tests without changing unrelated code. -- Tests change PATH while other tests run. The new daemon echo-helper test must use - `/bin/cat`, not a PATH lookup. This avoids introducing another environment race. -- Unix socket creation is blocked in the sandbox; socket regression tests needed - execution outside it. -- The rust-analyzer command is a rustup proxy with no installed component. LuaLS was - available, so a small Lua playground was added for real-server validation. -- One isolated benchmark daemon returned an unexpected stop-response ID. Retrying - cleanup removed its stale socket; this is recorded in GOTCHAS.md and remains - separate from request-window scheduling. - -# Missing tools - -`make test` reaches `cargo deny check`, but cargo-deny is not installed. Formatting, -270 active tests (one ignored subprocess helper), Clippy, and README generation -consistency checks pass. No new dependency or tool was installed. - -## Where to report - -If you're sure the reported difficulties above are related to techplatform (e.g. userver, c35), -please report to [aisuite](https://nda.ya.ru/t/EcUMOwSH7eudWX). diff --git a/GOTCHAS.md b/GOTCHAS.md index 651c1c4..fc00580 100644 --- a/GOTCHAS.md +++ b/GOTCHAS.md @@ -4,9 +4,10 @@ - Some servers send client requests such as `client/registerCapability` immediately after the `initialize` response and expect those requests to be answered before later client traffic. - lsp-cli therefore drains and replies to queued server requests right after `initialized` and - before sending later requests, instead of assuming request-response traffic is strictly - one-directional. + lsp-cli therefore drains and replies to requests already queued after `initialized` and before + later outgoing operations. Requests that race with the next client request are answered while + that request is outstanding, instead of assuming request-response traffic is strictly + one-directional or waiting for a fixed post-initialization quiet period. ## Diagnostics @@ -31,6 +32,10 @@ # Daemon gotchas +- Daemon initialization compares workspace URIs literally. Directory URIs produced by + `path_to_file_uri` end with `/`; raw socket clients and fixtures must use the same trailing + slash in `rootUri` and workspace folder URIs, or initialization is rejected. + - LSP 3.17 assumes one server serves one tool. `lsp-cli daemon` therefore implements a conservative proxy policy instead of transparent multi-client sharing: only one client may be connected at a time, downstream `shutdown`/`exit` are handled locally, and a later client with diff --git a/README.md b/README.md index ac6e63b..5c25241 100644 --- a/README.md +++ b/README.md @@ -168,6 +168,11 @@ lsp-cli stop-all The same background daemon is spawned and left idle after `lsp-cli --detach` is finished. +A new connection has two seconds to send its first complete message. Silent or +incomplete connections are closed without interrupting the active client. Up to +16 connections can wait to start a session; additional connections are closed, +including `stop` connections while all 16 slots are occupied. + ## Configuration Files @@ -246,6 +251,8 @@ detect: daemon: # Shut down an idle daemon after this much time. idle-timeout: "60" + # Disconnect an output peer that remains backlogged for this long. Default: 2 seconds. + write-stall-timeout: "2" lsp: # Example server preference list for C++. @@ -259,6 +266,20 @@ lsp: - jedi-language-server ``` +Each daemon output uses an ordered writer queue. A queue is marked stalled at 64 +messages or 8 MiB of framed data and unmarked after both values fall below those +limits. The daemon continues accepting messages during the grace period, so memory +can grow if traffic continues; it disconnects a slow client or stops an unresponsive +server if the queue stays marked for `write-stall-timeout`. A message larger than +8 MiB is allowed and begins writing after earlier messages on that output. +Server restart and shutdown also advance through daemon events. The daemon keeps +accepting control traffic while a process starts or exits; an unresponsive server +is force-stopped after the existing two-second shutdown and exit deadlines. +Daemon traffic, lifecycle, error, and captured-server-stderr logs use a 64-record +worker queue, so formatting, stderr, and the global log file do not block forwarding. +New records are dropped when this queue is full, and the daemon reports the count +after logging resumes. Normal shutdown waits at most 100 milliseconds for logs. + ## Language Configs: filetypes/*.yaml Files in `filetypes/` define how `lsp-cli` recognizes a language. diff --git a/playground/README.md b/playground/README.md index df5662a..b9dba32 100644 --- a/playground/README.md +++ b/playground/README.md @@ -39,6 +39,40 @@ Server selection follows the configured preferences and server availability. The projects reuse a similar domain across languages so symbol names are easy to remember while trying different LSP servers. +To measure daemon forwarding overhead with a deterministic immediate-reply server: + +```sh +cargo build +python3 scripts/daemon_latency.py --binary target/debug/lsp-cli --samples 100 --pipeline 16 +``` + +Run this from the repository root. Add another `--binary /path/to/baseline/lsp-cli` +to compare builds; use `--skip-handshake-checks` for binaries predating independent +handshakes. The script uses `playground/rust` with temporary server +configuration and sockets; it requires Python 3 but no installed language server. +It reports direct and warm-daemon p50/p95/p99 request latency in milliseconds, +with sample counts for sequential requests and batches of 16 pipelined requests. +Initialization is outside the measured interval. It also checks busy rejection, +warm reuse, restart after capability changes or dynamic registration, +initialization-failure recovery, silent/trickling handshake expiration while active +requests continue, and stop behind a silent connection. + +The daemon uses one outstanding event per reader or accept worker, keeping event +backlog bounded without a forwarding-loop polling delay. Individual message sizes +are not capped. First-message reads run independently with a two-second absolute +deadline and at most 16 pending handshakes. Excess connections are closed, including +stop connections when all slots are occupied. Writes, logging, and upstream +shutdown use per-output writer workers, so a peer that stops reading does not block +the coordinator. An output is flagged at 64 queued messages or 8 MiB of framed data; +it is unflagged after both values fall below their limits, or disconnected after the +configured `daemon.write-stall-timeout` (two seconds by default). Messages continue +to queue during that grace period, so memory use can temporarily exceed both limits. +Process start, shutdown, exit monitoring, and reaping run through a lifecycle worker; +daemon logging uses a bounded worker and a 100-millisecond shutdown flush budget. +The check holds the global log lock while forwarding and while stopping, and verifies +that overflow is reported after the lock is released. These measurements describe an immediate-reply fixture, not a +latency guarantee for real language servers or stalled peers. + The Lua playground exercises discovery of the local `normalize_timestamp` function, which may be absent from LuaLS workspace-symbol results: diff --git a/scripts/daemon_latency.py b/scripts/daemon_latency.py new file mode 100644 index 0000000..73019f3 --- /dev/null +++ b/scripts/daemon_latency.py @@ -0,0 +1,325 @@ +#!/usr/bin/env python3 +"""Repeatable immediate-reply latency measurement; also supplies the test LSP server. + +Example: python3 scripts/daemon_latency.py --binary target/debug/lsp-cli \ + --binary /tmp/lsp-cli-baseline --samples 100 --pipeline 16 +Uses isolated temporary configuration and sockets, with playground/rust as workspace. +""" + +import argparse +import contextlib +import fcntl +import json +import math +import os +from pathlib import Path +import shlex +import socket +import subprocess +import sys +import tempfile +import time + + +def read_message(reader): + length = None + while line := reader.readline(): + if line in (b"\r\n", b"\n"): + break + name, value = line.split(b":", 1) + if name.lower() == b"content-length": + length = int(value) + if length is None: + return None + return json.loads(reader.read(length)) + + +def write_message(writer, message): + body = json.dumps(message, separators=(",", ":")).encode() + writer.write(f"Content-Length: {len(body)}\r\n\r\n".encode() + body) + writer.flush() + + +def serve(): + hang_shutdown = False + while message := read_message(sys.stdin.buffer): + method = message.get("method") + if method == "exit": + return + if "id" not in message or method is None: + continue + result = message.get("params") + response = {"jsonrpc": "2.0", "id": message["id"]} + if method == "initialize": + if (message.get("params", {}).get("initializationOptions") or {}).get("fail"): + response["error"] = {"code": -32603, "message": "test initialization failure"} + else: + result = {"capabilities": {}, "serverInfo": {"name": "latency-fixture", "version": str(os.getpid())}} + elif method == "shutdown": + if hang_shutdown: + continue + result = None + elif method == "latency/hangShutdown": + hang_shutdown = True + result = None + elif method == "latency/logBurst": + for index in range(256): + print(f"latency log line {index}: {'x' * 256}", file=sys.stderr) + sys.stderr.flush() + result = None + elif method == "latency/register": + write_message(sys.stdout.buffer, {"jsonrpc": "2.0", "id": "registration", "method": "client/registerCapability", "params": {"registrations": []}}) + if "error" not in response: + response["result"] = result + write_message(sys.stdout.buffer, response) + + +class Peer: + def __init__(self, reader, writer): + self.reader = reader + self.writer = writer + self.sequence = 0 + + def send(self, method, params=None): + self.sequence += 1 + write_message(self.writer, {"jsonrpc": "2.0", "id": self.sequence, "method": method, "params": params}) + return self.sequence + + def notify(self, method): + write_message(self.writer, {"jsonrpc": "2.0", "method": method, "params": {}}) + + def receive(self, request_id): + while message := read_message(self.reader): + if message.get("method") and "id" in message: + write_message(self.writer, {"jsonrpc": "2.0", "id": message["id"], "result": None}) + continue + if message.get("id") == request_id: + return message + raise AssertionError(f"unexpected response: {message}") + raise AssertionError("peer closed before replying") + + def request(self, method, params=None): + return self.receive(self.send(method, params)) + + def initialize(self, workspace, capabilities=None, fail=False): + response = self.request("initialize", { + "rootUri": workspace.as_uri().rstrip("/") + "/", "capabilities": capabilities or {}, + "initializationOptions": {"fail": fail}, + }) + if not fail: + assert "result" in response, response + self.notify("initialized") + return response["result"]["serverInfo"]["version"] + assert "error" in response, response + + def finish(self): + assert self.request("shutdown")["result"] is None + self.notify("exit") + + +@contextlib.contextmanager +def connect(path): + with socket.socket(socket.AF_UNIX) as stream: + stream.settimeout(10) + stream.connect(str(path)) + with stream.makefile("rb") as reader, stream.makefile("wb") as writer: + yield Peer(reader, writer) + + +@contextlib.contextmanager +def raw_connection(path): + with socket.socket(socket.AF_UNIX) as stream: + stream.settimeout(5) + stream.connect(str(path)) + yield stream + + +def handshake_smoke(path, peer): + """Exercise the independent handshake readers outside the latency sample interval.""" + import threading + + with raw_connection(path) as silent, raw_connection(path) as trickling: + trickling.sendall(b"Content-Length: 10000\r\n\r\n") + stopped = threading.Event() + + def trickle(): + while not stopped.wait(.01): + try: + trickling.sendall(b" ") + except OSError: + return + + writer = threading.Thread(target=trickle) + writer.start() + try: + for index in range(20): + assert peer.request("latency/echo", index)["result"] == index + # Receiving EOF verifies absolute expiry despite bytes arriving on every read. + assert trickling.recv(1) == b"", "trickling peer did not expire" + assert silent.recv(1) == b"", "silent peer did not expire" + assert peer.request("latency/echo", "after-expiry")["result"] == "after-expiry" + finally: + stopped.set() + writer.join(timeout=5) + assert not writer.is_alive(), "trickle writer did not finish" + + +def report(peer, samples, pipeline): + def percentile(values, fraction): + return round(sorted(values)[max(0, math.ceil(len(values) * fraction) - 1)], 3) + + results = {} + for width in (1, pipeline): + elapsed = [] + for _ in range(samples): + pending = [] + for index in range(width): + started = time.perf_counter_ns() + pending.append((peer.send("latency/echo", index), index, started)) + for request_id, expected, started in pending: + assert peer.receive(request_id)["result"] == expected + elapsed.append((time.perf_counter_ns() - started) / 1_000_000) + results[f"pipeline_{width}"] = { + "samples": len(elapsed), "p50_ms": percentile(elapsed, .5), + "p95_ms": percentile(elapsed, .95), "p99_ms": percentile(elapsed, .99), + } + return results + + +def benchmark(binary, workspace, samples, pipeline, check_handshakes): + with tempfile.TemporaryDirectory(prefix="lsp-latency-") as temporary: + root = Path(temporary) + home = root / "home" + log_path = home / ".local" / "share" / "lsp-cli" / "lsp-cli.log" + log_path.parent.mkdir(parents=True) + log_path.touch() + data = root / "data" + (data / "filetypes").mkdir(parents=True) + (data / "lsp").mkdir() + (data / "filetypes" / "rust.yaml").write_text('extensions: ["rs"]\n') + command = shlex.join([sys.executable, str(Path(__file__).resolve()), "--server"]) + (data / "lsp" / "latency.yaml").write_text( + 'filetypes: ["rust"]\nroot_markers: ["Cargo.toml"]\nname: latency-fixture\n' + f'cmdline: {json.dumps(command)}\nwait-for-index: false\n' + ) + (data / "lsp-cli.yaml").write_text("download: false\ndetach: false\n") + env = {**os.environ, "HOME": str(home), "LSP_DATA": str(data), "XDG_CONFIG_HOME": str(root / "config"), + "XDG_RUNTIME_DIR": str(root / "run")} + args = [str(binary), "daemon", str(workspace), "--lsp", "latency-fixture", "--debug", "--idle-timeout", "30"] + stderr = (root / "daemon.stderr").open("w+") + daemon = subprocess.Popen(args, env={**env, "LSP_CLI_DAEMON_BACKGROUND": "1"}, + stdin=subprocess.DEVNULL, stdout=subprocess.PIPE, stderr=stderr, text=True) + status = daemon.stdout.readline().strip() + payload = daemon.stdout.readline().strip() + if status != "READY": + daemon.wait(timeout=5) + stderr.seek(0) + raise RuntimeError(f"{status}: {payload}\n{stderr.read()}") + path = Path(payload) + try: + with connect(path) as peer: + pid = peer.initialize(workspace) + with connect(path) as busy: + assert "error" in busy.request("initialize", {"capabilities": {}}) + peer.finish() + # Session cleanup is asynchronous; keep it outside the measured request interval. + time.sleep(.1) + with connect(path) as peer: + assert peer.initialize(workspace) == pid, "warm upstream was not reused" + measurements = report(peer, samples, pipeline) + with log_path.open("a+") as locked_log: + fcntl.flock(locked_log, fcntl.LOCK_EX) + peer.request("latency/logBurst") + assert peer.request("latency/echo", "logging-stalled")["result"] == "logging-stalled" + fcntl.flock(locked_log, fcntl.LOCK_UN) + deadline = time.monotonic() + 2 + while "daemon logger dropped" not in log_path.read_text() and time.monotonic() < deadline: + time.sleep(.01) + assert "daemon logger dropped" in log_path.read_text(), "lost log records were not reported" + if check_handshakes: + handshake_smoke(path, peer) + peer.request("latency/register") + peer.finish() + time.sleep(.1) + with connect(path) as peer: + assert peer.initialize(workspace) != pid, "dynamic registration did not restart upstream" + peer.finish() + time.sleep(.1) + with connect(path) as peer: + pid = peer.initialize(workspace, {"window": {"workDoneProgress": True}}) + peer.finish() + time.sleep(.1) + with connect(path) as peer: + assert peer.initialize(workspace) != pid, "capability mismatch did not restart upstream" + peer.finish() + time.sleep(.1) + with connect(path) as peer: + peer.initialize(workspace, fail=True) + peer.notify("exit") + time.sleep(.1) + with connect(path) as peer: + peer.initialize(workspace) + peer.request("latency/echo", "recovered") + peer.finish() + time.sleep(.1) + for _ in range(2): + query = subprocess.run([str(binary), "server-capabilities", str(workspace), + "--lsp", "latency-fixture", "--detach"], + env=env, capture_output=True, text=True, timeout=15, check=True) + assert "latency-fixture" in query.stdout, "capability command returned no server information" + time.sleep(.1) + with connect(path) as peer: + peer.initialize(workspace) + peer.request("latency/hangShutdown") + # A silent connection must not delay a later stop control connection. + with raw_connection(path): + with log_path.open("a+") as locked_log: + fcntl.flock(locked_log, fcntl.LOCK_EX) + started = time.monotonic() + subprocess.run([str(binary), "stop", str(workspace), "--lsp", "latency-fixture"], + env=env, capture_output=True, timeout=15, check=True) + assert time.monotonic() - started < 5, "daemon stop exceeded lifecycle deadline" + assert not path.exists(), "daemon socket survived stop" + return measurements + except Exception: + stderr.seek(0) + print(stderr.read(), file=sys.stderr) + raise + finally: + if path.exists(): + subprocess.run([str(binary), "stop", str(workspace), "--lsp", "latency-fixture"], + env=env, capture_output=True, timeout=15, check=True) + daemon.wait(timeout=10) + daemon.stdout.close() + stderr.close() + + +def main(): + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("--server", action="store_true", help="Run the immediate-reply test LSP server on stdio") + parser.add_argument("--binary", type=Path, action="append", help="Binary to measure (repeat to compare builds)") + parser.add_argument("--skip-handshake-checks", action="store_true", + help="Skip absolute handshake deadline checks when comparing binaries predating this feature") + parser.add_argument("--workspace", type=Path, default=Path(__file__).resolve().parents[1] / "playground/rust") + parser.add_argument("--samples", type=int, default=100, help="Number of batches at each pipeline width") + parser.add_argument("--pipeline", type=int, default=16, help="Requests per pipelined batch") + args = parser.parse_args() + if args.server: + serve() + return + if args.samples < 1 or args.pipeline < 2: + parser.error("samples must be positive and pipeline must be at least 2") + workspace = args.workspace.resolve() + with subprocess.Popen([sys.executable, str(Path(__file__).resolve()), "--server"], + stdin=subprocess.PIPE, stdout=subprocess.PIPE) as server: + direct = Peer(server.stdout, server.stdin) + direct.initialize(workspace) + print(json.dumps({"direct": report(direct, args.samples, args.pipeline)}), flush=True) + direct.finish() + server.wait(timeout=5) + for binary in args.binary or [Path("target/debug/lsp-cli")]: + print(json.dumps({str(binary): benchmark(binary.resolve(), workspace, args.samples, args.pipeline, not args.skip_handshake_checks)}), flush=True) + + +if __name__ == "__main__": + main() diff --git a/src/cli.rs b/src/cli.rs index 1e61eaa..8364151 100644 --- a/src/cli.rs +++ b/src/cli.rs @@ -21,6 +21,7 @@ pub(crate) use resolve::parse_args; pub(crate) const DEFAULT_TIMEOUT: Duration = Duration::from_secs(10); pub(crate) const DEFAULT_LIMIT: usize = 100; pub(crate) const DEFAULT_IDLE_TIMEOUT: Duration = Duration::from_mins(1); +pub(crate) const DEFAULT_WRITE_STALL_TIMEOUT: Duration = Duration::from_secs(2); #[derive(Debug, Eq, PartialEq)] pub enum Command { @@ -208,6 +209,7 @@ pub struct DaemonArgs { pub path: PathBuf, pub server: InstallDebugArgs, pub idle_timeout: Duration, + pub write_stall_timeout: Duration, } #[derive(Debug, Eq, PartialEq)] diff --git a/src/cli/resolve.rs b/src/cli/resolve.rs index e047ea1..ab6541d 100644 --- a/src/cli/resolve.rs +++ b/src/cli/resolve.rs @@ -1,9 +1,10 @@ use crate::cli::{ BuildIndexArgs, Command, CommandsArgs, DEFAULT_IDLE_TIMEOUT, DEFAULT_LIMIT, DEFAULT_TIMEOUT, - DaemonArgs, DeclarationArgs, DefinitionArgs, DetectArgs, DiagnosticsArgs, FormatArgs, GrepArgs, - InstallDebugArgs, LanguagesArgs, ListFilesArgs, ListFunctionsArgs, ListSymbolsArgs, - LspWorkspaceQueryArgs, RunArgs, SelectionArgs, ServerCapabilitiesArgs, ServersArgs, - StopAllArgs, StopArgs, SymbolQueryArgs, UpdateArgs, WorkspaceQueryArgs, + DEFAULT_WRITE_STALL_TIMEOUT, DaemonArgs, DeclarationArgs, DefinitionArgs, DetectArgs, + DiagnosticsArgs, FormatArgs, GrepArgs, InstallDebugArgs, LanguagesArgs, ListFilesArgs, + ListFunctionsArgs, ListSymbolsArgs, LspWorkspaceQueryArgs, RunArgs, SelectionArgs, + ServerCapabilitiesArgs, ServersArgs, StopAllArgs, StopArgs, SymbolQueryArgs, UpdateArgs, + WorkspaceQueryArgs, }; use crate::cli::{ RawBuildIndexArgs, RawCommand, RawCommandsArgs, RawDaemonArgs, RawDeclarationArgs, @@ -279,6 +280,10 @@ impl RawDaemonArgs { idle_timeout: self .idle_timeout .unwrap_or(defaults.daemon.idle_timeout.unwrap_or(DEFAULT_IDLE_TIMEOUT)), + write_stall_timeout: defaults + .daemon + .write_stall_timeout + .unwrap_or(DEFAULT_WRITE_STALL_TIMEOUT), } } } diff --git a/src/cli/tests/misc_commands.rs b/src/cli/tests/misc_commands.rs index 53f729f..4a1758c 100644 --- a/src/cli/tests/misc_commands.rs +++ b/src/cli/tests/misc_commands.rs @@ -56,12 +56,14 @@ fn parses_daemon_arguments_and_config_idle_timeout() { path: PathBuf::from("workspace"), server: install_debug(Some("rust"), Some("rust-analyzer"), true, true), idle_timeout: Duration::from_millis(1500), + write_stall_timeout: Duration::from_secs(2), }) ); let config = CliConfig { daemon: DaemonCliConfig { idle_timeout: Some(Duration::from_secs(5)), + write_stall_timeout: Some(Duration::from_secs(7)), }, ..CliConfig::default() }; @@ -72,6 +74,7 @@ fn parses_daemon_arguments_and_config_idle_timeout() { path: PathBuf::from("workspace"), server: install_debug(None, None, false, false), idle_timeout: Duration::from_secs(5), + write_stall_timeout: Duration::from_secs(7), }) ); } diff --git a/src/commands/daemon.rs b/src/commands/daemon.rs index e203b7e..f03d851 100644 --- a/src/commands/daemon.rs +++ b/src/commands/daemon.rs @@ -2,42 +2,52 @@ use crate::cli::DaemonArgs; use crate::config::ConfigStore; use crate::error::{Error, Result, error_fn}; use crate::lsp::transport::{log_debug_message, write_message}; -use crate::lsp::{STOP_METHOD, jsonrpc, parse_lsp_uri}; +use crate::lsp::{jsonrpc, parse_lsp_uri}; use crate::server_stderr::CapturedStderr; -use crate::system_log::{log_lsp_server_exit, log_unexpected_error}; use lsp_types::notification::{Cancel, DidCloseTextDocument, Notification}; -use lsp_types::request::{Initialize, Request}; use lsp_types::{CancelParams, DidCloseTextDocumentParams, NumberOrString, TextDocumentIdentifier}; use serde_json::Value; use std::collections::{BTreeMap, BTreeSet}; use std::fs; use std::io::ErrorKind; -use std::os::unix::net::{UnixListener, UnixStream}; +use std::os::unix::net::UnixStream; use std::path::Path; use std::path::PathBuf; -use std::process::{Child, ChildStdin}; -use std::sync::mpsc::{Receiver, TryRecvError}; +use std::sync::Arc; +use std::sync::mpsc::RecvTimeoutError; use std::thread; use std::time::{Duration, Instant}; +mod connections; +mod events; +mod forwarding; +mod lifecycle; +mod logger; +mod outputs; mod process; +mod process_worker; mod protocol; +mod socket_reader; +mod writer; +#[cfg(test)] +mod session_tests; #[cfg(test)] mod tests; +use connections::PendingConnection; +use events::{AcceptWorker, Event, EventQueue, ReaderWorker, Source}; +use logger::{LOG_SHUTDOWN_TIMEOUT, Logger, LoggerWorker}; use process::{bind_listener, launch_background, resolve_target, run_background}; +use process_worker::ProcessWorker; use protocol::{ - BackgroundWorkTracker, ReaderEvent, error_response, fingerprint_value, handle_busy_connection, - id_key, local_server_request_response, message_method, normalize_initialize_params, - read_control_message, request_id, request_id_from_key, respond_to_stop_request, response_id, - stop_request, stop_request_id, success_response, update_background_work_tracker, - wants_background_work, + BackgroundWorkTracker, ReaderEvent, error_response, read_control_message, request_id_from_key, + response_id, stop_request, stop_request_id, }; +use writer::{WriteId, WriterWorker}; const BACKGROUND_ENV: &str = "LSP_CLI_DAEMON_BACKGROUND"; const POLL_INTERVAL: Duration = Duration::from_millis(25); -const BUSY_CLIENT_TIMEOUT: Duration = Duration::from_millis(250); const CONTROL_TIMEOUT: Duration = Duration::from_secs(2); const DETACHED_IDLE_TIMEOUT: Duration = Duration::from_mins(1); const STOP_COMPLETION_TIMEOUT: Duration = Duration::from_secs(5); @@ -45,6 +55,7 @@ const UPSTREAM_SHUTDOWN_TIMEOUT: Duration = Duration::from_secs(2); const SERVER_NOT_INITIALIZED: i64 = -32002; const INVALID_REQUEST: i64 = -32600; const REQUEST_CANCELLED: i64 = -32800; +const INTERNAL_ERROR: i64 = -32603; pub(super) fn run(args: &DaemonArgs, config: &ConfigStore) -> Result { let target = resolve_target(args, config)?; @@ -169,22 +180,31 @@ struct DaemonTarget { } struct Daemon { - listener: UnixListener, + accept_worker: Option, + events: EventQueue, + socket_owned: bool, target: DaemonTarget, debug: bool, + logger: Logger, + logger_worker: LoggerWorker, idle_timeout: Duration, + write_stall_timeout: Duration, upstream: Option, + process: Option, + lifecycle: LifecycleState, + pending_initialize: Option, active_client: Option, + pending_connections: BTreeMap, orphaned_client_requests: BTreeSet, idle_since: Instant, stop_requested: bool, } struct UpstreamServer { - child: Child, - stdin: ChildStdin, + writer: WriterWorker, stderr: CapturedStderr, - messages: Receiver, + generation: u64, + _reader: ReaderWorker, initialize_fingerprint: Option, initialize_result: Option, restart_required: bool, @@ -192,435 +212,220 @@ struct UpstreamServer { } struct ClientSession { - writer: UnixStream, - messages: Receiver, + writer: WriterWorker, + generation: u64, + reader: ReaderWorker, phase: ClientPhase, wants_background_work: bool, forwarded_client_requests: BTreeSet, pending_server_requests: BTreeMap, open_documents: BTreeSet, + stop_after_write: Option, + disconnect_after_write: Option, } #[derive(Clone, Copy)] enum ClientPhase { WaitingForInitialize, + WaitingForUpstream, WaitingForInitialized { forward_to_upstream: bool }, Ready, WaitingForExit, } +struct PendingInitialize { + request_id: Value, + normalized: Value, + fingerprint: String, + wants_background_work: bool, +} + +#[derive(Clone, Copy, Debug, Eq, PartialEq)] +enum AfterExit { + Restart, + Stop, + Absent, +} + +#[derive(Clone, Copy, Debug, Eq, PartialEq)] +enum LifecycleState { + Starting { + generation: u64, + initial: bool, + }, + Running, + AwaitingShutdownReply { + generation: u64, + deadline: Instant, + after: AfterExit, + }, + AwaitingExitWrite { + generation: u64, + write_id: WriteId, + deadline: Instant, + after: AfterExit, + }, + AwaitingExit { + generation: u64, + deadline: Instant, + after: AfterExit, + }, + Killing { + generation: u64, + after: AfterExit, + }, + Absent, + Stopped, +} + impl Daemon { - fn new(target: DaemonTarget, debug: bool, idle_timeout: Duration) -> Result { + fn new( + target: DaemonTarget, + debug: bool, + idle_timeout: Duration, + write_stall_timeout: Duration, + ) -> Result { + let logger_worker = LoggerWorker::spawn(debug)?; + let logger = logger_worker.logger(); let listener = bind_listener(&target.socket_path)?; - listener.set_nonblocking(true).map_err(|error| { - Error::unexpected(format!( - "failed to set {} nonblocking: {error}", - target.socket_path.display() - )) - })?; - let upstream = UpstreamServer::spawn(&target, debug)?; - - Ok(Self { - listener, + let mut daemon = Self { + accept_worker: None, + events: EventQueue::new(), + socket_owned: true, target, debug, + logger, + logger_worker, idle_timeout, - upstream: Some(upstream), + write_stall_timeout, + upstream: None, + process: None, + lifecycle: LifecycleState::Absent, + pending_initialize: None, active_client: None, + pending_connections: BTreeMap::new(), orphaned_client_requests: BTreeSet::new(), idle_since: Instant::now(), stop_requested: false, - }) + }; + daemon.start_upstream(true)?; + daemon.wait_for_initial_upstream()?; + daemon.accept_worker = Some(AcceptWorker::spawn( + listener, + &daemon.target.socket_path, + &daemon.events, + )?); + Ok(daemon) } fn serve(&mut self) -> Result<()> { loop { - self.accept_connections()?; - self.drain_upstream_messages()?; - self.drain_client_messages()?; - - if self.stop_requested { - return self.stop(); + let now = Instant::now(); + self.expire_pending_connections(now); + self.expire_stalled_outputs(now)?; + self.advance_lifecycle_deadline(now); + if (self.stop_requested && !self.lifecycle.is_stopping()) || self.idle_stop_due() { + self.begin_stop()?; } - - if self.active_client.is_none() && self.idle_since.elapsed() >= self.idle_timeout { - return self.stop(); + if self.lifecycle == LifecycleState::Stopped { + return self.finish_stop(); } - - thread::sleep(POLL_INTERVAL); - } - } - - fn accept_connections(&mut self) -> Result<()> { - loop { - match self.listener.accept() { - Ok((stream, _)) => { - if self.active_client.is_some() { - if handle_busy_connection(stream, self.debug)? { - self.stop_requested = true; - } + let timeout = self.next_event_timeout(Instant::now()); + match self.events.receive(timeout) { + Ok(event) => { + if self.idle_stop_due() { + // A received event may coincide with the deadline. Release its producer + // before shutdown starts consuming upstream events from the same queue. + let _ = event.acknowledge.send(()); + self.begin_stop()?; continue; } - - self.active_client = Some(ClientSession::new(stream)?); + let result = self.dispatch(event.event); + // Release admission even when dispatch fails; cancellation handles retired readers. + let _ = event.acknowledge.send(()); + result?; } - Err(error) if error.kind() == std::io::ErrorKind::WouldBlock => return Ok(()), - Err(error) => { - return Err(Error::unexpected(format!( - "failed to accept client on {}: {error}", - self.target.socket_path.display() - ))); + Err(RecvTimeoutError::Timeout) => {} + Err(RecvTimeoutError::Disconnected) => { + return Err(Error::unexpected( + "daemon event workers stopped unexpectedly", + )); } } } } - fn drain_upstream_messages(&mut self) -> Result<()> { - loop { - let event = match self.upstream.as_ref() { - Some(upstream) => match upstream.messages.try_recv() { - Ok(event) => event, - Err(TryRecvError::Empty) => return Ok(()), - Err(TryRecvError::Disconnected) => { - self.upstream_died(); - return Ok(()); - } - }, - None => return Ok(()), - }; - - match event { - ReaderEvent::Message(message) => self.handle_upstream_message(&message)?, - ReaderEvent::EndOfStream => { - self.upstream_died(); - return Ok(()); - } - ReaderEvent::Error(error) => { - self.upstream_died(); - let error = format!("failed to read LSP server message: {error}"); - log_unexpected_error(&error); - return Err(Error::unexpected(error)); - } - } - } + fn idle_expired(&self) -> bool { + self.active_client.is_none() && self.idle_since.elapsed() >= self.idle_timeout } - fn drain_client_messages(&mut self) -> Result<()> { - loop { - let event = match self.active_client.as_ref() { - Some(client) => match client.messages.try_recv() { - Ok(event) => event, - Err(TryRecvError::Empty) => return Ok(()), - Err(TryRecvError::Disconnected) => { - self.disconnect_client()?; - return Ok(()); - } - }, - None => return Ok(()), - }; - - match event { - ReaderEvent::Message(message) => self.handle_client_message(&message)?, - ReaderEvent::EndOfStream => { - self.disconnect_client()?; - return Ok(()); - } - ReaderEvent::Error(error) => { - self.disconnect_client()?; - return Err(Error::lsp(format!( - "failed to read daemon client message: {error}" - ))); - } - } - } + fn idle_stop_due(&self) -> bool { + self.idle_expired() && !self.lifecycle.is_stopping() } - fn handle_client_message(&mut self, message: &Value) -> Result<()> { - log_debug_message(self.debug, "daemon client <- ", message); - let method = message_method(message); - let request_id = request_id(message); - let response_id = response_id(message); - - if let Some(response_id) = response_id { - let Some(client) = self.active_client.as_mut() else { - return Ok(()); - }; - let key = id_key(&response_id); - if client.pending_server_requests.remove(&key).is_some() { - self.write_upstream_message(message)?; + fn dispatch(&mut self, event: Event) -> Result<()> { + // Deadline expiry wins over a queued first message, including during sustained traffic. + self.expire_pending_connections(Instant::now()); + match event { + Event::Accepted { + stream, + accepted_at, + } => self.accept_pending_connection(stream, accepted_at)?, + Event::Reader(Source::Client(generation), event) + if self.pending_connections.contains_key(&generation) => + { + self.handle_pending_message(generation, event)?; } - return Ok(()); - } - - match self.active_client.as_ref().map(|client| client.phase) { - Some(ClientPhase::WaitingForInitialize) => { - if stop_request_id(message).is_some() { - return self.handle_stop_request(message); - } - - if method == Some("initialize") && request_id.is_some() { - return self.handle_initialize_request(message); - } - - if method == Some("exit") { - self.disconnect_client()?; - return Ok(()); - } - - if let Some(request_id) = request_id { - return self.write_client_response(&error_response( - &request_id, - SERVER_NOT_INITIALIZED, - "daemon client must initialize before sending requests", - )); - } - - return Ok(()); + Event::AcceptError(error) => { + return Err(Error::unexpected(format!( + "failed to accept client on {}: {error}", + self.target.socket_path.display() + ))); } - Some(ClientPhase::WaitingForInitialized { - forward_to_upstream, - }) => { - if method == Some("initialized") { - if forward_to_upstream { - self.write_upstream_message(message)?; + Event::Reader(Source::Upstream(generation), event) + if self + .upstream + .as_ref() + .is_some_and(|upstream| upstream.generation == generation) => + { + match event { + ReaderEvent::Message(message) => { + if !self.handle_lifecycle_message(&message)? { + self.handle_upstream_message(&message)?; + } } - if let Some(client) = self.active_client.as_mut() { - client.phase = ClientPhase::Ready; + ReaderEvent::EndOfStream => self.upstream_failed(), + ReaderEvent::Error(error) => { + self.upstream_failed(); + let error = format!("failed to read LSP server message: {error}"); + self.logger.unexpected(&error); + return Err(Error::unexpected(error)); } - self.notify_client_if_background_ready(!forward_to_upstream)?; - return Ok(()); - } - - if let Some(request_id) = request_id { - return self.write_client_response(&error_response( - &request_id, - INVALID_REQUEST, - "daemon client must send initialized before other requests", - )); - } - - return Ok(()); - } - Some(ClientPhase::WaitingForExit) => { - if method == Some("exit") { - self.disconnect_client()?; - } - return Ok(()); - } - Some(ClientPhase::Ready) | None => {} - } - - if method == Some("shutdown") { - let Some(request_id) = request_id else { - return Ok(()); - }; - if let Some(client) = self.active_client.as_mut() { - client.phase = ClientPhase::WaitingForExit; - } - return self.write_client_response(&success_response(&request_id, &Value::Null)); - } - - if method == Some("exit") { - self.disconnect_client()?; - return Ok(()); - } - - if method == Some(STOP_METHOD) { - return self.handle_stop_request(message); - } - - self.track_client_document_state(method, message.get("params")); - - if let Some(request_id) = request_id { - let Some(client) = self.active_client.as_mut() else { - return Ok(()); - }; - client.forwarded_client_requests.insert(id_key(&request_id)); - } - - self.write_upstream_message(message) - } - - fn handle_initialize_request(&mut self, message: &Value) -> Result<()> { - let Some(request_id) = request_id(message) else { - return Ok(()); - }; - let Some(params) = message.get("params").cloned() else { - return Err(Error::lsp("initialize request is missing params")); - }; - let normalized = normalize_initialize_params(¶ms, &self.target)?; - let fingerprint = fingerprint_value(&normalized); - let wants_background_work = wants_background_work(&normalized); - - let should_restart = match self.upstream.as_ref() { - Some(upstream) => { - upstream.restart_required - || upstream - .initialize_fingerprint - .as_ref() - .is_some_and(|value| value != &fingerprint) - } - None => true, - }; - - if should_restart { - self.restart_upstream()?; - } - - if self - .upstream - .as_ref() - .and_then(|upstream| upstream.initialize_fingerprint.as_ref()) - .is_some() - { - let Some(result) = self - .upstream - .as_ref() - .and_then(|upstream| upstream.initialize_result.clone()) - else { - return Err(Error::unexpected("daemon lost cached initialize result")); - }; - self.write_client_response(&success_response(&request_id, &result))?; - if let Some(client) = self.active_client.as_mut() { - client.wants_background_work = wants_background_work; - client.phase = ClientPhase::WaitingForInitialized { - forward_to_upstream: false, - }; - } - return Ok(()); - } - - let Some(upstream) = self.upstream.as_mut() else { - return Err(Error::unexpected("daemon failed to start LSP server")); - }; - upstream.initialize_fingerprint = Some(fingerprint); - - let forwarded = jsonrpc(Some(request_id.clone()), Initialize::METHOD, &normalized)?; - self.write_upstream_message(&forwarded)?; - if let Some(client) = self.active_client.as_mut() { - client.wants_background_work = wants_background_work; - client.phase = ClientPhase::WaitingForInitialized { - forward_to_upstream: true, - }; - client.forwarded_client_requests.insert(id_key(&request_id)); - } - Ok(()) - } - - fn handle_stop_request(&mut self, message: &Value) -> Result<()> { - let Some(client) = self.active_client.as_mut() else { - return Ok(()); - }; - - respond_to_stop_request(&mut client.writer, message, self.debug)?; - self.stop_requested = true; - Ok(()) - } - - fn handle_upstream_message(&mut self, message: &Value) -> Result<()> { - log_debug_message(self.debug, "daemon upstream -> ", message); - - if let Some(upstream) = self.upstream.as_mut() { - update_background_work_tracker(message, &mut upstream.background_work)?; - } - - if let Some(response_id) = response_id(message) { - let response_key = id_key(&response_id); - - if self.orphaned_client_requests.remove(&response_key) { - return Ok(()); - } - - let mut forwarded_client_request = false; - let mut initialize_response = false; - if let Some(client) = self.active_client.as_mut() { - forwarded_client_request = client.forwarded_client_requests.remove(&response_key); - initialize_response = forwarded_client_request - && matches!( - client.phase, - ClientPhase::WaitingForInitialized { - forward_to_upstream: true, - } - ); - if initialize_response && message.get("error").is_some() { - client.phase = ClientPhase::WaitingForExit; - } - } - - if initialize_response && let Some(upstream) = self.upstream.as_mut() { - if message.get("error").is_some() { - upstream.initialize_fingerprint = None; - upstream.initialize_result = None; - upstream.restart_required = true; - } else { - upstream.initialize_result = message.get("result").cloned(); } } - - if forwarded_client_request { - return self.write_client_response(message); - } - - return Ok(()); - } - - if let Some(request_id) = request_id(message) { - let Some(method) = message_method(message) else { - return Err(Error::lsp("server request missing method")); - }; - - if matches!( - method, - "client/registerCapability" | "client/unregisterCapability" - ) && let Some(upstream) = self.upstream.as_mut() + Event::Reader(Source::Client(generation), event) + if self + .active_client + .as_ref() + .is_some_and(|client| client.generation == generation) => { - upstream.restart_required = true; - } - - if let Some(client) = self.active_client.as_mut() { - client - .pending_server_requests - .insert(id_key(&request_id), request_id.clone()); - return self.write_client_response(message); - } - - let response = local_server_request_response(&request_id, method); - return self.write_upstream_message(&response); - } - - if self.active_client.is_some() { - return self.write_client_response(message); - } - - Ok(()) - } - - fn track_client_document_state(&mut self, method: Option<&str>, params: Option<&Value>) { - let Some(client) = self.active_client.as_mut() else { - return; - }; - - match method { - Some("textDocument/didOpen") => { - if let Some(uri) = params - .and_then(|value| value.get("textDocument")) - .and_then(|value| value.get("uri")) - .and_then(Value::as_str) - { - client.open_documents.insert(uri.to_string()); - } - } - Some("textDocument/didClose") => { - if let Some(uri) = params - .and_then(|value| value.get("textDocument")) - .and_then(|value| value.get("uri")) - .and_then(Value::as_str) - { - client.open_documents.remove(uri); + match event { + ReaderEvent::Message(message) => self.handle_client_message(&message)?, + ReaderEvent::EndOfStream => self.disconnect_client()?, + ReaderEvent::Error(error) => { + self.disconnect_client()?; + return Err(Error::lsp(format!( + "failed to read daemon client message: {error}" + ))); + } } } - _ => {} + Event::Writer(source, event) => self.handle_writer_event(source, event)?, + Event::Process(generation, event) => self.handle_process_event(generation, event)?, + // Retired workers can still publish a final event while cancellation races with I/O. + Event::Reader(_, _) => {} } + Ok(()) } fn disconnect_client(&mut self) -> Result<()> { @@ -628,6 +433,8 @@ impl Daemon { return Ok(()); }; + client.reader.cancel(); + for uri in client.open_documents { let params = DidCloseTextDocumentParams { text_document: TextDocumentIdentifier::new(parse_lsp_uri(&uri, "document")?), @@ -660,8 +467,7 @@ impl Daemon { .as_ref() .is_some_and(|upstream| upstream.restart_required) { - self.shutdown_upstream()?; - self.upstream = Some(UpstreamServer::spawn(&self.target, self.debug)?); + self.begin_restart()?; } self.idle_since = Instant::now(); @@ -669,13 +475,28 @@ impl Daemon { } fn write_client_response(&mut self, message: &Value) -> Result<()> { - log_debug_message(self.debug, "daemon client -> ", message); + self.enqueue_client_response(message).map(|_| ()) + } + + fn enqueue_client_response(&mut self, message: &Value) -> Result> { + self.logger.debug_value("daemon client -> ", message); let Some(client) = self.active_client.as_mut() else { - return Ok(()); + return Ok(None); }; - write_message(&mut client.writer, message).map_err(error_fn!( + client.writer.enqueue(message).map(Some).map_err(error_fn!( Error::lsp, - "failed to write daemon client message" + "failed to queue daemon client message" + )) + } + + fn enqueue_client_message(&mut self, message: &Arc) -> Result> { + self.logger.debug("daemon client -> ", Arc::clone(message)); + let Some(client) = self.active_client.as_mut() else { + return Ok(None); + }; + client.writer.enqueue(message).map(Some).map_err(error_fn!( + Error::lsp, + "failed to queue daemon client message" )) } @@ -683,52 +504,52 @@ impl Daemon { let Some(upstream) = self.upstream.as_mut() else { return Err(Error::unexpected("LSP server is not running")); }; - log_debug_message(self.debug, "daemon upstream <- ", message); - write_message(&mut upstream.stdin, message) - .map_err(error_fn!(Error::lsp, "failed to write LSP server message")) + self.logger.debug_value("daemon upstream <- ", message); + upstream + .writer + .enqueue(message) + .map(|_| ()) + .map_err(error_fn!(Error::lsp, "failed to queue LSP server message")) } - fn shutdown_upstream(&mut self) -> Result<()> { - if let Some(mut upstream) = self.upstream.take() { - upstream.shutdown(self.debug)?; - } - self.orphaned_client_requests.clear(); - Ok(()) + fn write_upstream_shared(&mut self, message: &Arc) -> Result<()> { + let Some(upstream) = self.upstream.as_mut() else { + return Err(Error::unexpected("LSP server is not running")); + }; + self.logger + .debug("daemon upstream <- ", Arc::clone(message)); + upstream + .writer + .enqueue(message) + .map(|_| ()) + .map_err(error_fn!(Error::lsp, "failed to queue LSP server message")) } - fn stop(&mut self) -> Result<()> { - self.disconnect_client()?; - self.shutdown_upstream()?; + fn finish_stop(&mut self) -> Result<()> { match fs::remove_file(&self.target.socket_path) { - Ok(()) => Ok(()), - Err(error) if error.kind() == ErrorKind::NotFound => Ok(()), + Ok(()) => self.socket_owned = false, + Err(error) if error.kind() == ErrorKind::NotFound => self.socket_owned = false, Err(error) => Err(Error::unexpected(format!( "failed to remove daemon socket {}: {error}", self.target.socket_path.display() - ))), + )))?, } - } - - fn restart_upstream(&mut self) -> Result<()> { - self.shutdown_upstream()?; - self.upstream = Some(UpstreamServer::spawn(&self.target, self.debug)?); + self.logger_worker.finish(LOG_SHUTDOWN_TIMEOUT); Ok(()) } +} - fn upstream_died(&mut self) { - if let Some(mut upstream) = self.upstream.take() { - let _ = upstream.stderr.summary(); - match upstream.child.try_wait() { - Ok(Some(status)) => log_lsp_server_exit(status), - Ok(None) => {} - Err(error) => { - log_unexpected_error(&format!("failed to inspect LSP server process: {error}")); - } - } +impl Drop for Daemon { + fn drop(&mut self) { + // Error exits must also wake acceptance before removing its socket path. + self.accept_worker.take(); + self.pending_connections.clear(); + self.active_client.take(); + self.upstream.take(); + self.process.take(); + // Normal stop already unlinked our socket; a replacement daemon may own that path now. + if self.socket_owned { + let _ = fs::remove_file(&self.target.socket_path); } - self.upstream = None; - self.active_client = None; - self.orphaned_client_requests.clear(); - self.idle_since = Instant::now(); } } diff --git a/src/commands/daemon/connections.rs b/src/commands/daemon/connections.rs new file mode 100644 index 0000000..e110b5b --- /dev/null +++ b/src/commands/daemon/connections.rs @@ -0,0 +1,179 @@ +use super::protocol::{ + ReaderEvent, error_response, message_method, normalize_initialize_params, request_id, + stop_request_id, success_response, +}; +use super::writer::WriteId; +use super::{ClientSession, Daemon, INVALID_REQUEST, REQUEST_CANCELLED, SERVER_NOT_INITIALIZED}; +use crate::error::Result; +use serde_json::Value; +use std::os::unix::net::UnixStream; +use std::sync::Arc; +use std::time::{Duration, Instant}; + +pub(super) const HANDSHAKE_TIMEOUT: Duration = Duration::from_secs(2); +pub(super) const MAX_PENDING_CONNECTIONS: usize = 16; + +pub(super) struct PendingConnection { + pub(super) client: ClientSession, + pub(super) deadline: Instant, + pub(super) close_after_write: Option, + pub(super) stop_after_write: bool, +} + +impl PendingConnection { + fn reject(&mut self, id: &Value, code: i64, reason: &str) -> Result<(WriteId, Value)> { + let response = error_response(id, code, reason); + self.client + .writer + .enqueue(&response) + .map(|write_id| (write_id, response)) + } +} + +impl Daemon { + pub(super) fn accept_pending_connection( + &mut self, + stream: UnixStream, + accepted_at: Instant, + ) -> Result<()> { + let deadline = accepted_at + HANDSHAKE_TIMEOUT; + if deadline <= Instant::now() || self.pending_connections.len() >= MAX_PENDING_CONNECTIONS { + // Do not read a rejected newcomer: no request ID is known, and existing pending + // clients retain their slots. This policy applies to control connections too. + return Ok(()); + } + let client = ClientSession::new(stream, &mut self.events, Some(deadline))?; + self.pending_connections.insert( + client.generation, + PendingConnection { + client, + deadline, + close_after_write: None, + stop_after_write: false, + }, + ); + Ok(()) + } + + pub(super) fn expire_pending_connections(&mut self, now: Instant) { + self.pending_connections + .retain(|_, pending| pending.close_after_write.is_some() || pending.deadline > now); + } + + pub(super) fn next_event_timeout(&mut self, now: Instant) -> Option { + let idle = if self.active_client.is_none() { + Some( + self.idle_timeout + .saturating_sub(now.saturating_duration_since(self.idle_since)), + ) + } else { + None + }; + for pending in self.pending_connections.values_mut() { + pending.client.writer.refresh_flag(now); + } + if let Some(client) = self.active_client.as_mut() { + client.writer.refresh_flag(now); + } + if let Some(upstream) = self.upstream.as_mut() { + upstream.writer.refresh_flag(now); + } + let output_deadlines = self + .pending_connections + .values() + .filter_map(|pending| pending.client.writer.deadline(self.write_stall_timeout)) + .chain( + self.active_client + .as_ref() + .and_then(|client| client.writer.deadline(self.write_stall_timeout)), + ) + .chain( + self.upstream + .as_ref() + .and_then(|upstream| upstream.writer.deadline(self.write_stall_timeout)), + ); + self.pending_connections + .values() + .filter(|pending| pending.close_after_write.is_none()) + .map(|pending| pending.deadline.saturating_duration_since(now)) + .chain(idle) + .chain(output_deadlines.map(|deadline| deadline.saturating_duration_since(now))) + .chain(self.lifecycle_timeout(now)) + .min() + } + + pub(super) fn handle_pending_message( + &mut self, + generation: u64, + event: ReaderEvent, + ) -> Result<()> { + let Some(mut pending) = self.pending_connections.remove(&generation) else { + return Ok(()); + }; + let ReaderEvent::Message(message) = event else { + // Malformed frames and EOF belong to this unadmitted connection only. + return Ok(()); + }; + self.logger + .debug("daemon pending client <- ", Arc::clone(&message)); + if let Some(id) = stop_request_id(&message) { + let response = success_response(&id, &Value::Null); + self.logger + .debug_value("daemon pending client -> ", &response); + if let Ok(write_id) = pending.client.writer.enqueue(&response) { + pending.close_after_write = Some(write_id); + pending.stop_after_write = true; + self.pending_connections.insert(generation, pending); + } + return Ok(()); + } + let Some(id) = request_id(&message) else { + return Ok(()); + }; + if message_method(&message) != Some("initialize") { + if let Ok((write_id, response)) = pending.reject( + &id, + SERVER_NOT_INITIALIZED, + "daemon client must initialize before sending requests", + ) { + self.logger + .debug_value("daemon pending client -> ", &response); + pending.close_after_write = Some(write_id); + self.pending_connections.insert(generation, pending); + } + return Ok(()); + } + if self.active_client.is_some() { + if let Ok((write_id, response)) = pending.reject( + &id, + REQUEST_CANCELLED, + "another daemon client is already connected", + ) { + self.logger + .debug_value("daemon pending client -> ", &response); + pending.close_after_write = Some(write_id); + self.pending_connections.insert(generation, pending); + } + return Ok(()); + } + let params = message.get("params").unwrap_or(&Value::Null); + if let Err(error) = normalize_initialize_params(params, &self.target) { + if let Ok((write_id, response)) = + pending.reject(&id, INVALID_REQUEST, &error.to_string()) + { + self.logger + .debug_value("daemon pending client -> ", &response); + pending.close_after_write = Some(write_id); + self.pending_connections.insert(generation, pending); + } + return Ok(()); + } + // Move the existing reader rather than reopening the stream: initialized and later + // frames may already be buffered behind this first message in the same read. + self.active_client = Some(pending.client); + self.handle_client_message(&message) + } +} + +#[cfg(test)] +mod tests; diff --git a/src/commands/daemon/connections/tests.rs b/src/commands/daemon/connections/tests.rs new file mode 100644 index 0000000..63698e6 --- /dev/null +++ b/src/commands/daemon/connections/tests.rs @@ -0,0 +1,473 @@ +use super::super::events::{Event, Source}; +use super::super::protocol::stop_request; +use super::super::session_tests::Fixture; +use super::super::{ClientPhase, LifecycleState}; +use super::*; +use crate::lsp::transport::read_message; +use crate::lsp::transport::write_message; +use serde_json::json; +use std::io::{BufReader, Read, Write}; + +const TEST_TIMEOUT: Duration = Duration::from_secs(3); + +struct Peer { + reader: BufReader, +} + +impl Peer { + fn new(daemon: &mut Daemon, accepted_at: Instant) -> Self { + let (socket, peer) = UnixStream::pair().expect("connection pair"); + peer.set_read_timeout(Some(TEST_TIMEOUT)) + .expect("read timeout"); + daemon + .dispatch(Event::Accepted { + stream: socket, + accepted_at, + }) + .expect("accept connection"); + Self { + reader: BufReader::new(peer), + } + } + + fn send(&mut self, message: &Value) { + write_message(self.reader.get_mut(), message).expect("send message"); + } + + fn response(&mut self) -> Value { + read_message(&mut self.reader) + .expect("read response") + .expect("response exists") + } + + fn assert_closed(&mut self) { + match self.reader.read(&mut [0]) { + Ok(bytes) => assert_eq!(bytes, 0, "connection closed without a response"), + Err(error) => assert_eq!(error.kind(), std::io::ErrorKind::ConnectionReset), + } + } +} + +impl Fixture { + fn idle() -> Self { + let mut fixture = Self::new(); + fixture + .daemon + .disconnect_client() + .expect("disconnect initial client"); + fixture + } + + fn connect(&mut self) -> Peer { + Peer::new(&mut self.daemon, Instant::now()) + } + + fn initialize_message(&self) -> Value { + json!({"jsonrpc": "2.0", "id": 1, "method": "initialize", "params": { + "rootUri": self.daemon.target.root_uri, "capabilities": {} + }}) + } + + fn latest_pending(&self) -> u64 { + *self + .daemon + .pending_connections + .last_key_value() + .expect("pending connection") + .0 + } + + fn expire_all(&mut self) { + self.daemon + .expire_pending_connections(Instant::now() + HANDSHAKE_TIMEOUT); + } + + fn pump_until(&mut self, finished: impl Fn(&Daemon) -> bool) { + for _ in 0..100 { + if finished(&self.daemon) { + return; + } + self.step(); + } + assert!(finished(&self.daemon), "coordinator made progress"); + } +} + +#[test] +fn silent_pending_peers_do_not_block_active_requests_or_stop() { + let mut fixture = Fixture::new(); + fixture.initialize(false); + let _silent = fixture.connect(); + let mut partial = fixture.connect(); + partial + .reader + .get_mut() + .write_all(b"Content-Length: 100\r\n\r\n{") + .expect("partial frame"); + for id in 10..20 { + fixture.send(&json!({"jsonrpc": "2.0", "id": id, "method": "latency/echo", "params": id})); + fixture.step(); + fixture.step(); + assert_eq!(fixture.read()["result"], id); + } + let mut control = fixture.connect(); + control.send(&stop_request()); + fixture.pump_until(|daemon| daemon.stop_requested); + assert_eq!(control.response()["result"], Value::Null); + assert!( + fixture.daemon.active_client.is_some(), + "stop did not need an active-client disconnect" + ); +} + +#[test] +fn pending_slot_does_not_reserve_active_session_and_pipelining_survives_promotion() { + let mut fixture = Fixture::idle(); + let _silent_first = fixture.connect(); + let mut ready_second = fixture.connect(); + let generation = fixture.latest_pending(); + let initialize = fixture.initialize_message(); + let mut frames = Vec::new(); + for message in [ + initialize, + json!({"method": "initialized", "params": {}}), + json!({"id": 2, "method": "latency/echo", "params": "pipeline"}), + ] { + write_message(&mut frames, &message).expect("encode pipeline"); + } + ready_second + .reader + .get_mut() + .write_all(&frames) + .expect("single pipelined write"); + // Three client frames and two upstream replies, regardless of interleaving. + for _ in 0..5 { + fixture.step(); + } + fixture.pump_until(|daemon| { + daemon.active_client.as_ref().is_some_and(|client| { + matches!(client.phase, ClientPhase::Ready) + && client.forwarded_client_requests.is_empty() + }) + }); + assert_eq!( + fixture + .daemon + .active_client + .as_ref() + .expect("promoted") + .generation, + generation + ); + assert!(ready_second.response().get("result").is_some()); + assert_eq!(ready_second.response()["result"], "pipeline"); + assert_eq!(fixture.daemon.pending_connections.len(), 1); +} + +#[test] +fn second_initializer_gets_busy_without_disrupting_active_client() { + let mut fixture = Fixture::idle(); + let mut first = fixture.connect(); + let mut second = fixture.connect(); + let initialize = fixture.initialize_message(); + first.send(&initialize); + fixture.pump_until(|daemon| daemon.active_client.is_some()); + let admitted = fixture + .daemon + .active_client + .as_ref() + .expect("first client") + .generation; + second.send(&initialize); + fixture.pump_until(|daemon| daemon.pending_connections.is_empty()); + assert_eq!( + second.response()["error"]["message"], + "another daemon client is already connected" + ); + second.assert_closed(); + assert_eq!( + fixture + .daemon + .active_client + .as_ref() + .expect("first remains") + .generation, + admitted + ); +} + +#[test] +fn capacity_rejects_newcomers_preserves_existing_slots_and_recovers() { + let mut fixture = Fixture::idle(); + let mut peers: Vec<_> = (0..MAX_PENDING_CONNECTIONS) + .map(|_| fixture.connect()) + .collect(); + let generations: Vec<_> = fixture.daemon.pending_connections.keys().copied().collect(); + let (socket, mut stream) = UnixStream::pair().expect("excess control connection"); + stream + .set_read_timeout(Some(TEST_TIMEOUT)) + .expect("control read timeout"); + write_message(&mut stream, &stop_request()).expect("queued stop request"); + fixture + .daemon + .dispatch(Event::Accepted { + stream: socket, + accepted_at: Instant::now(), + }) + .expect("reject excess control connection"); + let mut newcomer = Peer { + reader: BufReader::new(stream), + }; + newcomer.assert_closed(); + assert_eq!( + fixture + .daemon + .pending_connections + .keys() + .copied() + .collect::>(), + generations + ); + assert!(fixture.daemon.active_client.is_none()); + // The rejected socket is closed before a stop request (or any first message) can be read. + assert!(!fixture.daemon.stop_requested); + fixture.expire_all(); + for peer in &mut peers { + peer.assert_closed(); + } + let mut control = fixture.connect(); + control.send(&stop_request()); + fixture.pump_until(|daemon| daemon.stop_requested); + assert_eq!(control.response()["result"], Value::Null); +} + +#[test] +fn eof_frees_capacity_without_waiting_for_the_deadline() { + let mut fixture = Fixture::idle(); + let mut peers: Vec<_> = (0..MAX_PENDING_CONNECTIONS) + .map(|_| fixture.connect()) + .collect(); + let peer = peers.pop().expect("last peer"); + peer.reader + .get_ref() + .shutdown(std::net::Shutdown::Write) + .expect("peer closes input"); + fixture.pump_until(|daemon| daemon.pending_connections.len() < MAX_PENDING_CONNECTIONS); + let _replacement = fixture.connect(); + assert_eq!( + fixture.daemon.pending_connections.len(), + MAX_PENDING_CONNECTIONS + ); +} + +#[test] +fn deadline_includes_accept_queue_time_and_ignores_late_events() { + let mut fixture = Fixture::idle(); + let idle_since = fixture.daemon.idle_since; + let mut expired = Peer::new( + &mut fixture.daemon, + Instant::now() + .checked_sub(HANDSHAKE_TIMEOUT) + .expect("past acceptance time"), + ); + expired.assert_closed(); + assert!(fixture.daemon.pending_connections.is_empty()); + let mut pending = fixture.connect(); + let retired = fixture.latest_pending(); + fixture.expire_all(); + pending.assert_closed(); + let _replacement = fixture.connect(); + let replacement = fixture.latest_pending(); + for event in [ + ReaderEvent::Message(fixture.initialize_message().into()), + ReaderEvent::EndOfStream, + ReaderEvent::Error("expired".into()), + ] { + fixture + .daemon + .dispatch(Event::Reader(Source::Client(retired), event)) + .expect("ignore retired event"); + } + assert!(fixture.daemon.active_client.is_none()); + assert!( + fixture + .daemon + .pending_connections + .contains_key(&replacement) + ); + assert_eq!(fixture.daemon.idle_since, idle_since); +} + +#[test] +fn expiry_wins_over_first_message_and_runs_during_other_events() { + let mut fixture = Fixture::idle(); + let mut peer = fixture.connect(); + let generation = fixture.latest_pending(); + fixture + .daemon + .pending_connections + .get_mut(&generation) + .expect("pending") + .deadline = Instant::now(); + fixture + .daemon + .dispatch(Event::Reader( + Source::Client(generation), + ReaderEvent::Message(fixture.initialize_message().into()), + )) + .expect("expired first message"); + peer.assert_closed(); + assert!(fixture.daemon.active_client.is_none()); + let mut peer = fixture.connect(); + let generation = fixture.latest_pending(); + fixture + .daemon + .pending_connections + .get_mut(&generation) + .expect("pending") + .deadline = Instant::now(); + fixture + .daemon + .dispatch(Event::Reader( + Source::Upstream(999), + ReaderEvent::Message(json!({"method": "notification"}).into()), + )) + .expect("continuous unrelated traffic still checks expiry"); + peer.assert_closed(); + assert!(fixture.daemon.pending_connections.is_empty()); +} + +#[test] +fn invalid_first_messages_are_isolated_to_pending_connection() { + let mut fixture = Fixture::idle(); + for message in [ + json!({"id": 1, "method": "initialize", "params": {"rootUri": "file:///elsewhere/"}}), + json!({"id": 1, "method": "initialize"}), + json!({"id": 1, "method": "latency/echo"}), + ] { + let mut peer = fixture.connect(); + peer.send(&message); + fixture.pump_until(|daemon| daemon.pending_connections.is_empty()); + assert!(peer.response().get("error").is_some()); + peer.assert_closed(); + assert!(fixture.daemon.active_client.is_none()); + } + for bytes in [ + b"invalid-header\r\n\r\n".as_slice(), + b"Content-Length: 2\r\n\r\n{}", + ] { + let mut peer = fixture.connect(); + peer.reader + .get_mut() + .write_all(bytes) + .expect("invalid first message"); + fixture.pump_until(|daemon| daemon.pending_connections.is_empty()); + peer.assert_closed(); + assert!(!fixture.daemon.stop_requested); + } + let mut control = fixture.connect(); + control.send(&stop_request()); + fixture.pump_until(|daemon| daemon.stop_requested); + assert_eq!(control.response()["id"], "lsp-cli/stop"); +} + +#[test] +fn pending_deadlines_compete_with_idle_and_disappear_after_admission() { + let mut fixture = Fixture::idle(); + fixture.daemon.idle_timeout = Duration::from_secs(10); + let _pending = fixture.connect(); + let deadline = fixture + .daemon + .pending_connections + .values() + .next() + .expect("pending") + .deadline; + let now = Instant::now(); + assert_eq!( + fixture.daemon.next_event_timeout(now), + Some(deadline.saturating_duration_since(now)) + ); + fixture.daemon.idle_timeout = Duration::ZERO; + assert_eq!(fixture.daemon.next_event_timeout(now), Some(Duration::ZERO)); + fixture.expire_all(); + fixture.daemon.idle_timeout = Duration::from_secs(10); + let mut peer = fixture.connect(); + peer.send(&fixture.initialize_message()); + fixture.pump_until(|daemon| daemon.active_client.is_some()); + assert_eq!(fixture.daemon.next_event_timeout(Instant::now()), None); +} + +#[test] +fn stop_and_error_teardown_close_all_pending_readers() { + for normal_stop in [false, true] { + let mut fixture = Fixture::new(); + fixture.initialize(false); + let mut silent = fixture.connect(); + let mut partial = fixture.connect(); + partial + .reader + .get_mut() + .write_all(b"Content-Len") + .expect("partial header"); + if normal_stop { + fixture.daemon.begin_stop().expect("begin normal stop"); + fixture.pump_until(|daemon| daemon.lifecycle == LifecycleState::Stopped); + assert!(fixture.daemon.pending_connections.is_empty()); + } + // Explicit destruction also exercises error-exit cleanup with live pending readers. + drop(fixture); + silent.assert_closed(); + partial.assert_closed(); + } +} + +#[test] +fn pending_connections_do_not_prevent_idle_exit() { + let mut fixture = Fixture::idle(); + fixture.daemon.upstream.take(); + let mut peer = fixture.connect(); + fixture.daemon.idle_timeout = Duration::ZERO; + fixture + .daemon + .serve() + .expect("idle exit with pending connection"); + assert!(fixture.daemon.pending_connections.is_empty()); + peer.assert_closed(); +} + +#[test] +fn event_loop_wakes_to_expire_pending_client_while_active_client_remains() { + use std::sync::mpsc; + use std::thread; + let mut fixture = Fixture::new(); + fixture.initialize(false); + let mut pending = fixture.connect(); + let generation = fixture.latest_pending(); + fixture + .daemon + .pending_connections + .get_mut(&generation) + .expect("pending") + .deadline = Instant::now() + Duration::from_millis(20); + // A generous watchdog below the worker's two-second deadline distinguishes coordinator + // wakeup from the independent reader timeout, without measuring forwarding latency. + pending + .reader + .get_ref() + .set_read_timeout(Some(Duration::from_secs(1))) + .expect("expiry watchdog"); + let mut active = fixture.peer.get_ref().try_clone().expect("active writer"); + let (done, result) = mpsc::channel(); + let coordinator = thread::spawn(move || { + done.send(fixture.daemon.serve()).expect("serve result"); + }); + // This closure comes from the coordinator's timer, before the reader's two-second budget. + pending.assert_closed(); + write_message(&mut active, &stop_request()).expect("stop on still-active connection"); + result + .recv_timeout(TEST_TIMEOUT) + .expect("coordinator remained responsive") + .expect("clean stop"); + coordinator.join().expect("coordinator exits"); +} diff --git a/src/commands/daemon/events.rs b/src/commands/daemon/events.rs new file mode 100644 index 0000000..9e5a849 --- /dev/null +++ b/src/commands/daemon/events.rs @@ -0,0 +1,293 @@ +use super::protocol::ReaderEvent; +use super::socket_reader::SocketReader; +use crate::error::{Error, Result}; +use crate::lsp::transport::read_message; +use crate::system_log::log_unexpected_error; +use serde_json::Value; +use std::io::{BufReader, Read}; +use std::net::Shutdown; +use std::os::unix::net::{UnixListener, UnixStream}; +use std::path::{Path, PathBuf}; +use std::sync::Arc; +use std::sync::atomic::{AtomicBool, Ordering}; +use std::sync::mpsc::{self, Receiver, RecvTimeoutError, Sender}; +use std::thread::{self, JoinHandle}; +use std::time::{Duration, Instant}; + +#[derive(Clone, Copy, Debug, Eq, PartialEq)] +pub(super) enum Source { + Client(u64), + Upstream(u64), +} + +pub(super) enum Event { + Accepted { + stream: UnixStream, + accepted_at: Instant, + }, + AcceptError(String), + Reader(Source, ReaderEvent), + Writer(Source, super::writer::WriterEvent), + Process(u64, super::process_worker::ProcessEvent), +} + +pub(super) struct Delivery { + pub(super) event: Event, + pub(super) acknowledge: Sender<()>, +} + +pub(super) struct EventQueue { + sender: Sender, + receiver: Receiver, + generation: u64, +} + +impl EventQueue { + pub(super) fn new() -> Self { + let (sender, receiver) = mpsc::channel(); + Self { + sender, + receiver, + generation: 0, + } + } + + pub(super) fn next_generation(&mut self) -> Result { + let Some(generation) = self.generation.checked_add(1) else { + return Err(Error::unexpected( + "daemon exhausted its connection identifiers; restart the daemon", + )); + }; + self.generation = generation; + Ok(self.generation) + } + + pub(super) fn admission(&self) -> (Arc, Sender<()>, Admission) { + let cancelled = Arc::new(AtomicBool::new(false)); + let (acknowledge, replies) = mpsc::channel(); + let admission = Admission { + cancelled: Arc::clone(&cancelled), + acknowledge: acknowledge.clone(), + replies, + events: self.sender.clone(), + }; + (cancelled, acknowledge, admission) + } + + pub(super) fn receive( + &mut self, + timeout: Option, + ) -> std::result::Result { + match timeout { + Some(timeout) => self.receiver.recv_timeout(timeout), + None => self + .receiver + .recv() + .map_err(|_| RecvTimeoutError::Disconnected), + } + } +} + +pub(super) struct Admission { + cancelled: Arc, + acknowledge: Sender<()>, + replies: Receiver<()>, + events: Sender, +} + +impl Admission { + pub(super) fn publish(&self, event: Event) -> bool { + if self.cancelled.load(Ordering::Acquire) { + return false; + } + let (acknowledge, replies) = mpsc::channel(); + drop(replies); + self.events.send(Delivery { event, acknowledge }).is_ok() + } + + pub(super) fn deliver(&self, event: Event) -> bool { + if self.cancelled.load(Ordering::Acquire) { + return false; + } + // Only this producer uses replies: it cannot read/accept again until coordination + // completes this event. The shared FIFO therefore needs no blocking coordinator send. + if self + .events + .send(Delivery { + event, + acknowledge: self.acknowledge.clone(), + }) + .is_err() + { + return false; + } + self.replies.recv().is_ok() && !self.cancelled.load(Ordering::Acquire) + } +} + +pub(super) struct ReaderWorker { + cancelled: Arc, + acknowledge: Sender<()>, + socket: Option, + thread: Option>, +} + +impl ReaderWorker { + pub(super) fn admission(events: &EventQueue) -> (Self, Admission) { + let (cancelled, acknowledge, admission) = events.admission(); + ( + Self { + cancelled, + acknowledge, + socket: None, + thread: None, + }, + admission, + ) + } + + pub(super) fn spawn( + reader: R, + source: Source, + events: &EventQueue, + ) -> Result { + let mut reader = BufReader::new(reader); + Self::spawn_messages(move || read_message(&mut reader), source, events) + } + + fn spawn_messages( + mut next_message: impl FnMut() -> Result> + Send + 'static, + source: Source, + events: &EventQueue, + ) -> Result { + let (mut worker, admission) = Self::admission(events); + worker.thread = Some( + thread::Builder::new() + .name("daemon-reader".into()) + .spawn(move || { + while !admission.cancelled.load(Ordering::Acquire) { + let event = match next_message() { + Ok(Some(message)) => ReaderEvent::Message(Arc::new(message)), + Ok(None) => ReaderEvent::EndOfStream, + Err(error) => ReaderEvent::Error(error.to_string()), + }; + let terminal = !matches!(event, ReaderEvent::Message(_)); + if !admission.deliver(Event::Reader(source, event)) || terminal { + return; + } + } + }) + .map_err(|error| { + Error::unexpected(format!("failed to start daemon reader: {error}")) + })?, + ); + Ok(worker) + } + + #[cfg(test)] + pub(super) fn socket(socket: UnixStream, source: Source, events: &EventQueue) -> Result { + Self::socket_with_deadline(socket, source, events, None) + } + + pub(super) fn socket_with_deadline( + socket: UnixStream, + source: Source, + events: &EventQueue, + deadline: Option, + ) -> Result { + let reader = socket.try_clone().map_err(|error| { + Error::unexpected(format!("failed to clone daemon client socket: {error}")) + })?; + let mut reader = SocketReader::new(reader, deadline); + let mut worker = Self::spawn_messages(move || reader.next_message(), source, events)?; + worker.socket = Some(socket); + Ok(worker) + } + + pub(super) fn cancel(&self) -> bool { + self.cancelled.store(true, Ordering::Release); + let _ = self.acknowledge.send(()); + if let Some(socket) = &self.socket { + return socket.shutdown(Shutdown::Both).is_ok(); + } + false + } +} + +impl Drop for ReaderWorker { + fn drop(&mut self) { + // Admission can be blocked even after the peer closes; socket shutdown also interrupts + // partial-frame reads. Inherited child pipes cannot safely be joined until EOF arrives. + let interrupted = self.cancel(); + if let Some(thread) = self.thread.take() + && (interrupted || thread.is_finished()) + { + let _ = thread.join(); + } + } +} + +pub(super) struct AcceptWorker { + worker: ReaderWorker, + socket_path: PathBuf, +} + +impl AcceptWorker { + pub(super) fn spawn( + listener: UnixListener, + socket_path: &Path, + events: &EventQueue, + ) -> Result { + let (mut worker, admission) = ReaderWorker::admission(events); + worker.thread = Some( + thread::Builder::new() + .name("daemon-accept".into()) + .spawn(move || { + while !admission.cancelled.load(Ordering::Acquire) { + let event = match listener.accept() { + Ok((stream, _)) => Event::Accepted { + stream, + accepted_at: Instant::now(), + }, + Err(error) if error.kind() == std::io::ErrorKind::Interrupted => { + continue; + } + Err(error) => Event::AcceptError(error.to_string()), + }; + let terminal = matches!(event, Event::AcceptError(_)); + if !admission.deliver(event) || terminal { + return; + } + } + }) + .map_err(|error| { + Error::unexpected(format!("failed to start daemon listener: {error}")) + })?, + ); + Ok(Self { + worker, + socket_path: socket_path.to_owned(), + }) + } +} + +impl Drop for AcceptWorker { + fn drop(&mut self) { + // Cancellation releases admission; a self-connection wakes blocking accept. Check the + // cancellation flag before publishing so this wakeup never becomes a client session. + self.worker.cancel(); + let wakeup = UnixStream::connect(&self.socket_path); + if let Some(thread) = self.worker.thread.take() { + if wakeup.is_ok() || thread.is_finished() { + let _ = thread.join(); + } else { + // An externally removed/replaced socket may no longer reach our listener. + // Do not turn that error into an unbounded join during daemon teardown. + log_unexpected_error("could not wake daemon listener during shutdown"); + } + } + } +} + +#[cfg(test)] +mod tests; diff --git a/src/commands/daemon/events/tests.rs b/src/commands/daemon/events/tests.rs new file mode 100644 index 0000000..3d88b46 --- /dev/null +++ b/src/commands/daemon/events/tests.rs @@ -0,0 +1,199 @@ +use super::*; +use crate::lsp::transport::write_message; +use crate::test_support::TestDir; +use serde_json::{Value, json}; +use std::io::Write; + +const TIMEOUT: Duration = Duration::from_secs(3); + +struct Fixture { + events: EventQueue, + workers: Vec, + peers: Vec, +} + +impl Fixture { + fn new(sources: &[Source]) -> Self { + let events = EventQueue::new(); + let mut workers = Vec::new(); + let mut peers = Vec::new(); + for source in sources { + let (reader, peer) = UnixStream::pair().expect("socket pair"); + workers.push(ReaderWorker::socket(reader, *source, &events).expect("reader worker")); + peers.push(peer); + } + Self { + events, + workers, + peers, + } + } + + fn send(&mut self, index: usize, value: &Value) { + write_message(self.peers.get_mut(index).expect("peer"), value).expect("write frame"); + } + + fn receive(&mut self) -> Delivery { + self.events + .receive(Some(TIMEOUT)) + .expect("event before timeout") + } +} + +fn message(delivery: Delivery, source: Source) -> Value { + let Event::Reader(actual_source, ReaderEvent::Message(value)) = delivery.event else { + panic!("expected message"); + }; + assert_eq!(actual_source, source); + delivery.acknowledge.send(()).expect("acknowledge"); + Arc::unwrap_or_clone(value) +} + +#[test] +fn reader_admission_preserves_order_and_opposite_direction_opportunities() { + let client = Source::Client(1); + let upstream = Source::Upstream(2); + let mut fixture = Fixture::new(&[client, upstream]); + for number in 0..20 { + fixture.send(0, &json!(number)); + } + let first = fixture.receive(); + assert!(matches!( + fixture.events.receiver.try_recv(), + Err(mpsc::TryRecvError::Empty) + )); + fixture.send(1, &json!("reply")); + assert_eq!(message(fixture.receive(), upstream), json!("reply")); + assert_eq!(message(first, client), json!(0)); + for number in 1..20 { + assert_eq!(message(fixture.receive(), client), json!(number)); + } +} + +#[test] +fn cancellation_releases_unacknowledged_reader() { + let mut fixture = Fixture::new(&[Source::Client(1)]); + fixture.send(0, &json!(1)); + let delivery = fixture.receive(); + let mut worker = fixture.workers.pop().expect("worker"); + worker.cancel(); + worker + .thread + .take() + .expect("reader thread") + .join() + .expect("cancelled reader exits"); + assert!(delivery.acknowledge.send(()).is_err()); +} + +#[test] +fn cancellation_interrupts_partial_frame_reads() { + for partial in ["", "Content-Len", "Content-Length: 100\r\n\r\n{"] { + let mut fixture = Fixture::new(&[Source::Client(1)]); + fixture + .peers + .first_mut() + .expect("peer") + .write_all(partial.as_bytes()) + .expect("partial frame"); + let mut worker = fixture.workers.pop().expect("worker"); + worker.cancel(); + worker + .thread + .take() + .expect("reader thread") + .join() + .expect("cancelled reader exits"); + } +} + +#[test] +fn reader_reports_eof_and_malformed_frames() { + for (bytes, malformed) in [("", false), ("bad-header\r\n\r\n", true)] { + let source = Source::Client(1); + let mut fixture = Fixture::new(&[source]); + let peer = fixture.peers.first_mut().expect("peer"); + peer.write_all(bytes.as_bytes()).expect("frame"); + peer.shutdown(Shutdown::Write).expect("close writer"); + let delivery = fixture.receive(); + assert!(matches!(delivery.event, Event::Reader(actual, _) if actual == source)); + assert_eq!( + matches!(delivery.event, Event::Reader(_, ReaderEvent::Error(_))), + malformed + ); + assert_eq!( + matches!(delivery.event, Event::Reader(_, ReaderEvent::EndOfStream)), + !malformed + ); + delivery + .acknowledge + .send(()) + .expect("acknowledge terminal event"); + } +} + +#[test] +fn blocking_receive_wakes_on_reader_event() { + let mut fixture = Fixture::new(&[Source::Client(1)]); + let mut events = fixture.events; + let (done, result) = mpsc::channel(); + let receiver = thread::spawn(move || { + let delivery = events.receive(None).expect("blocking receive"); + done.send(message(delivery, Source::Client(1))) + .expect("result"); + }); + write_message(fixture.peers.first_mut().expect("peer"), &json!("wake")).expect("frame"); + assert_eq!( + result.recv_timeout(TIMEOUT).expect("receiver woke"), + json!("wake") + ); + receiver.join().expect("receiver exits"); +} + +#[test] +fn listener_bounds_accepted_sockets_and_cancels_in_both_wait_states() { + for pending in [false, true] { + let dir = TestDir::new("event-accept"); + let path = dir.path().join("daemon.sock"); + let listener = UnixListener::bind(&path).expect("listener"); + let mut events = EventQueue::new(); + let worker = AcceptWorker::spawn(listener, &path, &events).expect("accept worker"); + let lifetime = Arc::downgrade(&worker.worker.cancelled); + if pending { + let _first_peer = UnixStream::connect(&path).expect("first connection"); + let first = events.receive(Some(TIMEOUT)).expect("first accepted"); + let _second_peer = UnixStream::connect(&path).expect("second connection"); + assert!(matches!( + events.receiver.try_recv(), + Err(mpsc::TryRecvError::Empty) + )); + assert!(matches!(first.event, Event::Accepted { .. })); + first.acknowledge.send(()).expect("admit second socket"); + let second = events.receive(Some(TIMEOUT)).expect("second accepted"); + assert!(matches!(second.event, Event::Accepted { .. })); + // Teardown must release admission even while this delivery remains unacknowledged. + drop(worker); + assert!(second.acknowledge.send(()).is_err()); + } else { + // Teardown must wake a listener that has no incoming connection. + drop(worker); + } + assert!( + lifetime.upgrade().is_none(), + "accept worker exited and was joined" + ); + } +} + +#[test] +fn generations_never_wrap_into_a_retired_identity() { + let mut events = EventQueue::new(); + assert_ne!( + events.next_generation().expect("first"), + events.next_generation().expect("second") + ); + events.generation = u64::MAX; + events + .next_generation() + .expect_err("generation exhaustion must not wrap"); +} diff --git a/src/commands/daemon/forwarding.rs b/src/commands/daemon/forwarding.rs new file mode 100644 index 0000000..00bd615 --- /dev/null +++ b/src/commands/daemon/forwarding.rs @@ -0,0 +1,382 @@ +use super::protocol::{ + error_response, fingerprint_value, id_key, local_server_request_response, message_method, + normalize_initialize_params, request_id, response_id, stop_request_id, success_response, + update_background_work_tracker, wants_background_work, +}; +use super::{ + ClientPhase, Daemon, INTERNAL_ERROR, INVALID_REQUEST, PendingInitialize, SERVER_NOT_INITIALIZED, +}; +use crate::error::{Error, Result}; +use crate::lsp::{STOP_METHOD, jsonrpc}; +use lsp_types::request::{Initialize, Request}; +use serde_json::Value; +use std::sync::Arc; + +impl Daemon { + pub(super) fn handle_client_message(&mut self, message: &Arc) -> Result<()> { + self.logger.debug("daemon client <- ", Arc::clone(message)); + let method = message_method(message); + let request_id = request_id(message); + let response_id = response_id(message); + + if let Some(response_id) = response_id { + let Some(client) = self.active_client.as_mut() else { + return Ok(()); + }; + let key = id_key(&response_id); + if client.pending_server_requests.remove(&key).is_some() { + self.write_upstream_shared(message)?; + } + return Ok(()); + } + + match self.active_client.as_ref().map(|client| client.phase) { + Some(ClientPhase::WaitingForInitialize) => { + if stop_request_id(message).is_some() { + return self.handle_stop_request(message); + } + + if method == Some("initialize") && request_id.is_some() { + return self.handle_initialize_request(message); + } + + if method == Some("exit") { + self.disconnect_client()?; + return Ok(()); + } + + if let Some(request_id) = request_id { + return self.write_client_response(&error_response( + &request_id, + SERVER_NOT_INITIALIZED, + "daemon client must initialize before sending requests", + )); + } + + return Ok(()); + } + Some(ClientPhase::WaitingForInitialized { + forward_to_upstream, + }) => { + if method == Some("initialized") { + if forward_to_upstream { + self.write_upstream_shared(message)?; + } + if let Some(client) = self.active_client.as_mut() { + client.phase = ClientPhase::Ready; + } + self.notify_client_if_background_ready(!forward_to_upstream)?; + return Ok(()); + } + + if let Some(request_id) = request_id { + return self.write_client_response(&error_response( + &request_id, + INVALID_REQUEST, + "daemon client must send initialized before other requests", + )); + } + + return Ok(()); + } + Some(ClientPhase::WaitingForUpstream) => { + return self.handle_waiting_for_upstream(message, method, request_id); + } + Some(ClientPhase::WaitingForExit) => { + if method == Some("exit") { + self.disconnect_client()?; + } + return Ok(()); + } + Some(ClientPhase::Ready) | None => {} + } + + if method == Some("shutdown") { + let Some(request_id) = request_id else { + return Ok(()); + }; + if let Some(client) = self.active_client.as_mut() { + client.phase = ClientPhase::WaitingForExit; + } + return self.write_client_response(&success_response(&request_id, &Value::Null)); + } + + if method == Some("exit") { + self.disconnect_client()?; + return Ok(()); + } + + if method == Some(STOP_METHOD) { + return self.handle_stop_request(message); + } + + self.track_client_document_state(method, message.get("params")); + + if let Some(request_id) = request_id { + let Some(client) = self.active_client.as_mut() else { + return Ok(()); + }; + client.forwarded_client_requests.insert(id_key(&request_id)); + } + + self.write_upstream_shared(message) + } + + fn handle_waiting_for_upstream( + &mut self, + message: &Value, + method: Option<&str>, + request_id: Option, + ) -> Result<()> { + if stop_request_id(message).is_some() { + return self.handle_stop_request(message); + } + if method == Some("exit") { + return self.disconnect_client(); + } + if let Some(request_id) = request_id { + return self.write_client_response(&error_response( + &request_id, + SERVER_NOT_INITIALIZED, + "daemon is waiting for the LSP server to restart", + )); + } + Ok(()) + } + + fn handle_initialize_request(&mut self, message: &Value) -> Result<()> { + let Some(request_id) = request_id(message) else { + return Ok(()); + }; + let Some(params) = message.get("params").cloned() else { + return Err(Error::lsp("initialize request is missing params")); + }; + let normalized = normalize_initialize_params(¶ms, &self.target)?; + let fingerprint = fingerprint_value(&normalized); + let wants_background_work = wants_background_work(&normalized); + + let should_restart = match self.upstream.as_ref() { + Some(upstream) => { + upstream.restart_required + || upstream + .initialize_fingerprint + .as_ref() + .is_some_and(|value| value != &fingerprint) + } + None => true, + }; + + if should_restart { + self.pending_initialize = Some(PendingInitialize { + request_id, + normalized, + fingerprint, + wants_background_work, + }); + if let Some(client) = self.active_client.as_mut() { + client.phase = ClientPhase::WaitingForUpstream; + } + self.begin_restart()?; + return Ok(()); + } + + if self + .upstream + .as_ref() + .and_then(|upstream| upstream.initialize_fingerprint.as_ref()) + .is_some() + { + let Some(result) = self + .upstream + .as_ref() + .and_then(|upstream| upstream.initialize_result.clone()) + else { + return Err(Error::unexpected("daemon lost cached initialize result")); + }; + self.write_client_response(&success_response(&request_id, &result))?; + if let Some(client) = self.active_client.as_mut() { + client.wants_background_work = wants_background_work; + client.phase = ClientPhase::WaitingForInitialized { + forward_to_upstream: false, + }; + } + return Ok(()); + } + + self.forward_initialize(PendingInitialize { + request_id, + normalized, + fingerprint, + wants_background_work, + }) + } + + pub(super) fn resume_pending_initialize(&mut self) -> Result<()> { + let Some(initialize) = self.pending_initialize.take() else { + return Ok(()); + }; + if self.active_client.is_none() { + return Ok(()); + } + self.forward_initialize(initialize) + } + + fn forward_initialize(&mut self, initialize: PendingInitialize) -> Result<()> { + let Some(upstream) = self.upstream.as_mut() else { + return Err(Error::unexpected("daemon failed to start LSP server")); + }; + upstream.initialize_fingerprint = Some(initialize.fingerprint); + let forwarded = jsonrpc( + Some(initialize.request_id.clone()), + Initialize::METHOD, + &initialize.normalized, + )?; + self.write_upstream_message(&forwarded)?; + if let Some(client) = self.active_client.as_mut() { + client.wants_background_work = initialize.wants_background_work; + client.phase = ClientPhase::WaitingForInitialized { + forward_to_upstream: true, + }; + client + .forwarded_client_requests + .insert(id_key(&initialize.request_id)); + } + Ok(()) + } + + pub(super) fn fail_pending_initialize(&mut self, message: &str) -> Result<()> { + let Some(initialize) = self.pending_initialize.take() else { + return Ok(()); + }; + let response = error_response(&initialize.request_id, INTERNAL_ERROR, message); + let Some(write_id) = self.enqueue_client_response(&response)? else { + return Ok(()); + }; + if let Some(client) = self.active_client.as_mut() { + client.phase = ClientPhase::WaitingForExit; + client.disconnect_after_write = Some(write_id); + } + Ok(()) + } + + fn handle_stop_request(&mut self, message: &Value) -> Result<()> { + let Some(request_id) = stop_request_id(message) else { + return Err(Error::lsp("daemon stop request is missing an id")); + }; + let response = success_response(&request_id, &Value::Null); + let Some(write_id) = self.enqueue_client_response(&response)? else { + return Ok(()); + }; + if let Some(client) = self.active_client.as_mut() { + client.stop_after_write = Some(write_id); + } + Ok(()) + } + + pub(super) fn handle_upstream_message(&mut self, message: &Arc) -> Result<()> { + self.logger + .debug("daemon upstream -> ", Arc::clone(message)); + + if let Some(upstream) = self.upstream.as_mut() { + update_background_work_tracker(message, &mut upstream.background_work)?; + } + + if let Some(response_id) = response_id(message) { + let response_key = id_key(&response_id); + + if self.orphaned_client_requests.remove(&response_key) { + return Ok(()); + } + + let mut forwarded_client_request = false; + let mut initialize_response = false; + if let Some(client) = self.active_client.as_mut() { + forwarded_client_request = client.forwarded_client_requests.remove(&response_key); + initialize_response = forwarded_client_request + && matches!( + client.phase, + ClientPhase::WaitingForInitialized { + forward_to_upstream: true, + } + ); + if initialize_response && message.get("error").is_some() { + client.phase = ClientPhase::WaitingForExit; + } + } + + if initialize_response && let Some(upstream) = self.upstream.as_mut() { + if message.get("error").is_some() { + upstream.initialize_fingerprint = None; + upstream.initialize_result = None; + upstream.restart_required = true; + } else { + upstream.initialize_result = message.get("result").cloned(); + } + } + + if forwarded_client_request { + return self.enqueue_client_message(message).map(|_| ()); + } + + return Ok(()); + } + + if let Some(request_id) = request_id(message) { + let Some(method) = message_method(message) else { + return Err(Error::lsp("server request missing method")); + }; + + if matches!( + method, + "client/registerCapability" | "client/unregisterCapability" + ) && let Some(upstream) = self.upstream.as_mut() + { + upstream.restart_required = true; + } + + if let Some(client) = self.active_client.as_mut() { + client + .pending_server_requests + .insert(id_key(&request_id), request_id.clone()); + return self.enqueue_client_message(message).map(|_| ()); + } + + let response = local_server_request_response(&request_id, method); + return self.write_upstream_message(&response); + } + + if self.active_client.is_some() { + return self.enqueue_client_message(message).map(|_| ()); + } + + Ok(()) + } + + fn track_client_document_state(&mut self, method: Option<&str>, params: Option<&Value>) { + let Some(client) = self.active_client.as_mut() else { + return; + }; + + match method { + Some("textDocument/didOpen") => { + if let Some(uri) = params + .and_then(|value| value.get("textDocument")) + .and_then(|value| value.get("uri")) + .and_then(Value::as_str) + { + client.open_documents.insert(uri.to_string()); + } + } + Some("textDocument/didClose") => { + if let Some(uri) = params + .and_then(|value| value.get("textDocument")) + .and_then(|value| value.get("uri")) + .and_then(Value::as_str) + { + client.open_documents.remove(uri); + } + } + _ => {} + } + } +} diff --git a/src/commands/daemon/lifecycle.rs b/src/commands/daemon/lifecycle.rs new file mode 100644 index 0000000..d85e2f2 --- /dev/null +++ b/src/commands/daemon/lifecycle.rs @@ -0,0 +1,441 @@ +use super::process_worker::{ProcessEvent, ProcessSpec, ProcessWorker}; +use super::{ + AfterExit, Daemon, DaemonTarget, LifecycleState, UPSTREAM_SHUTDOWN_TIMEOUT, UpstreamServer, +}; +use crate::error::{Error, Result}; +use crate::lsp::jsonrpc; +use lsp_types::notification::{Exit, Notification}; +use lsp_types::request::{Request, Shutdown}; +use serde_json::Value; +use std::ffi::OsString; +use std::time::{Duration, Instant}; + +const SHUTDOWN_ID: &str = "lsp-cli/daemon-shutdown"; + +impl LifecycleState { + pub(super) fn is_stopping(self) -> bool { + matches!( + self, + Self::AwaitingShutdownReply { + after: AfterExit::Stop, + .. + } | Self::AwaitingExitWrite { + after: AfterExit::Stop, + .. + } | Self::AwaitingExit { + after: AfterExit::Stop, + .. + } | Self::Killing { + after: AfterExit::Stop, + .. + } | Self::Stopped + ) + } + + pub(super) fn deadline(self) -> Option { + match self { + Self::AwaitingShutdownReply { deadline, .. } + | Self::AwaitingExitWrite { deadline, .. } + | Self::AwaitingExit { deadline, .. } => Some(deadline), + _ => None, + } + } +} + +impl DaemonTarget { + fn process_spec(&self, debug: bool) -> Result { + let program = std::env::current_exe().map_err(|error| { + Error::unexpected(format!("failed to resolve lsp-cli executable: {error}")) + })?; + let mut args = vec![ + OsString::from("run"), + self.path.as_os_str().to_owned(), + OsString::from("--lsp"), + OsString::from(&self.server_name), + ]; + if debug { + args.push(OsString::from("--debug")); + } + Ok(ProcessSpec { program, args }) + } +} + +impl Daemon { + pub(super) fn start_upstream(&mut self, initial: bool) -> Result<()> { + let generation = self.events.next_generation()?; + let spec = self.target.process_spec(self.debug)?; + self.logger.server_starting(); + self.process = Some(ProcessWorker::spawn(spec, generation, &self.events)?); + self.lifecycle = LifecycleState::Starting { + generation, + initial, + }; + Ok(()) + } + + pub(super) fn wait_for_initial_upstream(&mut self) -> Result<()> { + while !matches!(self.lifecycle, LifecycleState::Running) { + let delivery = self.events.receive(None).map_err(|_| { + Error::unexpected("LSP process worker stopped during daemon startup") + })?; + let result = self.dispatch(delivery.event); + let _ = delivery.acknowledge.send(()); + result?; + } + Ok(()) + } + + pub(super) fn handle_process_event( + &mut self, + generation: u64, + event: ProcessEvent, + ) -> Result<()> { + if self.process.as_ref().map(ProcessWorker::generation) != Some(generation) { + return Ok(()); + } + match event { + ProcessEvent::Started(io) => { + if !matches!( + self.lifecycle, + LifecycleState::Starting { + generation: current, + .. + } if current == generation + ) { + return Ok(()); + } + self.logger.server_started(io.pid); + self.upstream = Some(UpstreamServer::from_io( + io, + generation, + self.logger.clone(), + &self.events, + )?); + self.lifecycle = LifecycleState::Running; + self.resume_pending_initialize()?; + } + ProcessEvent::StartFailed(error) => { + let initial = matches!( + self.lifecycle, + LifecycleState::Starting { + generation: current, + initial: true, + } if current == generation + ); + self.process.take(); + self.lifecycle = LifecycleState::Absent; + let message = format!( + "failed to start LSP server {}: {error}", + self.target.server_name + ); + if initial { + return Err(Error::unexpected(message)); + } + self.logger.unexpected(&message); + self.fail_pending_initialize(&message)?; + } + ProcessEvent::Exited(result) => self.handle_process_exit(generation, result)?, + } + Ok(()) + } + + fn handle_process_exit( + &mut self, + generation: u64, + result: std::result::Result, + ) -> Result<()> { + let after = match self.lifecycle { + LifecycleState::AwaitingShutdownReply { + generation: current, + after, + .. + } + | LifecycleState::AwaitingExitWrite { + generation: current, + after, + .. + } + | LifecycleState::AwaitingExit { + generation: current, + after, + .. + } + | LifecycleState::Killing { + generation: current, + after, + } if current == generation => after, + LifecycleState::Running => AfterExit::Absent, + _ => return Ok(()), + }; + if let Some(upstream) = self.upstream.take() { + // Stderr lines are logged by their capture worker. Take a non-waiting snapshot here + // only to avoid the former coordinator-side flush wait during lifecycle progress. + let _ = upstream.stderr.summary_now(); + } + self.process.take(); + match result { + Ok(status) => self.logger.server_exited(status), + Err(error) => self.logger.unexpected(error), + } + self.orphaned_client_requests.clear(); + match after { + AfterExit::Restart => self.start_upstream(false)?, + AfterExit::Stop => self.lifecycle = LifecycleState::Stopped, + AfterExit::Absent => { + self.active_client = None; + self.pending_initialize = None; + self.lifecycle = LifecycleState::Absent; + self.idle_since = Instant::now(); + } + } + Ok(()) + } + + pub(super) fn begin_restart(&mut self) -> Result<()> { + match self.lifecycle { + LifecycleState::Running => self.begin_shutdown(AfterExit::Restart), + LifecycleState::Absent => self.start_upstream(false), + _ => Ok(()), + } + } + + pub(super) fn begin_stop(&mut self) -> Result<()> { + self.stop_requested = true; + self.accept_worker.take(); + self.pending_connections.clear(); + self.disconnect_client()?; + match self.lifecycle { + LifecycleState::Running => self.begin_shutdown(AfterExit::Stop), + LifecycleState::Starting { generation, .. } => { + self.force_stop(generation, AfterExit::Stop); + Ok(()) + } + LifecycleState::Absent => { + self.lifecycle = LifecycleState::Stopped; + Ok(()) + } + LifecycleState::AwaitingShutdownReply { + generation, + deadline, + .. + } => { + self.lifecycle = LifecycleState::AwaitingShutdownReply { + generation, + deadline, + after: AfterExit::Stop, + }; + Ok(()) + } + LifecycleState::AwaitingExitWrite { + generation, + write_id, + deadline, + .. + } => { + self.lifecycle = LifecycleState::AwaitingExitWrite { + generation, + write_id, + deadline, + after: AfterExit::Stop, + }; + Ok(()) + } + LifecycleState::AwaitingExit { + generation, + deadline, + .. + } => { + self.lifecycle = LifecycleState::AwaitingExit { + generation, + deadline, + after: AfterExit::Stop, + }; + Ok(()) + } + LifecycleState::Killing { generation, .. } => { + self.lifecycle = LifecycleState::Killing { + generation, + after: AfterExit::Stop, + }; + Ok(()) + } + LifecycleState::Stopped => Ok(()), + } + } + + fn begin_shutdown(&mut self, after: AfterExit) -> Result<()> { + let Some(upstream) = self.upstream.as_mut() else { + self.lifecycle = match after { + AfterExit::Stop => LifecycleState::Stopped, + AfterExit::Restart | AfterExit::Absent => LifecycleState::Absent, + }; + if after == AfterExit::Restart { + self.start_upstream(false)?; + } + return Ok(()); + }; + let generation = upstream.generation; + if upstream.initialize_fingerprint.is_none() { + self.force_stop(generation, after); + return Ok(()); + } + let shutdown = jsonrpc( + Some(Value::String(SHUTDOWN_ID.into())), + Shutdown::METHOD, + &(), + )?; + self.logger.debug_value("daemon upstream <- ", &shutdown); + if upstream.writer.enqueue(&shutdown).is_err() { + self.force_stop(generation, after); + return Ok(()); + } + self.lifecycle = LifecycleState::AwaitingShutdownReply { + generation, + deadline: Instant::now() + UPSTREAM_SHUTDOWN_TIMEOUT, + after, + }; + Ok(()) + } + + pub(super) fn handle_lifecycle_message(&mut self, message: &Value) -> Result { + let Some(id) = super::response_id(message) else { + return Ok(false); + }; + if id != Value::String(SHUTDOWN_ID.into()) { + return Ok(false); + } + let LifecycleState::AwaitingShutdownReply { + generation, after, .. + } = self.lifecycle + else { + return Ok(true); + }; + let exit = jsonrpc::(None, Exit::METHOD, &())?; + self.logger.debug_value("daemon upstream <- ", &exit); + let Some(upstream) = self.upstream.as_mut() else { + self.force_stop(generation, after); + return Ok(true); + }; + match upstream.writer.enqueue(&exit) { + Ok(write_id) => { + self.lifecycle = LifecycleState::AwaitingExitWrite { + generation, + write_id, + deadline: Instant::now() + UPSTREAM_SHUTDOWN_TIMEOUT, + after, + }; + } + Err(_) => self.force_stop(generation, after), + } + Ok(true) + } + + pub(super) fn handle_lifecycle_write( + &mut self, + generation: u64, + write_id: u64, + completed_at: Instant, + ) { + if let LifecycleState::AwaitingExitWrite { + generation: current, + write_id: expected, + after, + .. + } = self.lifecycle + && current == generation + && expected == write_id + { + self.lifecycle = LifecycleState::AwaitingExit { + generation, + deadline: completed_at + UPSTREAM_SHUTDOWN_TIMEOUT, + after, + }; + } + } + + pub(super) fn advance_lifecycle_deadline(&mut self, now: Instant) { + let Some(deadline) = self.lifecycle.deadline() else { + return; + }; + if now < deadline { + return; + } + let (LifecycleState::AwaitingShutdownReply { + generation, after, .. + } + | LifecycleState::AwaitingExitWrite { + generation, after, .. + } + | LifecycleState::AwaitingExit { + generation, after, .. + }) = self.lifecycle + else { + return; + }; + self.force_stop(generation, after); + } + + pub(super) fn lifecycle_timeout(&self, now: Instant) -> Option { + self.lifecycle + .deadline() + .map(|deadline| deadline.saturating_duration_since(now)) + } + + pub(super) fn upstream_failed(&mut self) { + let Some(generation) = self.upstream.as_ref().map(|upstream| upstream.generation) else { + return; + }; + let after = match self.lifecycle { + LifecycleState::AwaitingShutdownReply { after, .. } + | LifecycleState::AwaitingExitWrite { after, .. } + | LifecycleState::AwaitingExit { after, .. } + | LifecycleState::Killing { after, .. } => after, + _ => AfterExit::Absent, + }; + if after == AfterExit::Absent { + self.active_client = None; + self.pending_initialize = None; + } + self.force_stop(generation, after); + } + + fn force_stop(&mut self, generation: u64, after: AfterExit) { + if let Some(process) = self.process.as_ref() + && let Err(error) = process.force_stop() + { + self.logger.unexpected(error); + } + self.lifecycle = LifecycleState::Killing { generation, after }; + } +} + +impl UpstreamServer { + pub(super) fn from_io( + io: super::process_worker::ProcessIo, + generation: u64, + logger: super::Logger, + events: &super::events::EventQueue, + ) -> Result { + let stderr = crate::server_stderr::CapturedStderr::spawn_with(io.stderr, logger); + let reader = super::events::ReaderWorker::spawn( + io.stdout, + super::events::Source::Upstream(generation), + events, + )?; + let writer = super::writer::WriterWorker::spawn( + io.stdin, + super::events::Source::Upstream(generation), + events, + )?; + Ok(Self { + writer, + stderr, + generation, + _reader: reader, + initialize_fingerprint: None, + initialize_result: None, + restart_required: false, + background_work: super::BackgroundWorkTracker::default(), + }) + } +} diff --git a/src/commands/daemon/logger.rs b/src/commands/daemon/logger.rs new file mode 100644 index 0000000..aaae228 --- /dev/null +++ b/src/commands/daemon/logger.rs @@ -0,0 +1,268 @@ +use crate::error::{Error, Result}; +use crate::lsp::transport::serialize_debug_message; +use crate::server_stderr::StderrSink; +use crate::system_log::{append_system_log_line, format_exit_status}; +use serde_json::Value; +use std::io::Write; +use std::process::ExitStatus; +use std::sync::Arc; +use std::sync::atomic::{AtomicBool, AtomicUsize, Ordering}; +use std::sync::mpsc::{self, Receiver, SyncSender, TrySendError}; +use std::thread::{self, JoinHandle}; +use std::time::Duration; + +const LOG_QUEUE_LIMIT: usize = 64; +const WORKER_WAKE_INTERVAL: Duration = Duration::from_millis(5); +pub(super) const LOG_SHUTDOWN_TIMEOUT: Duration = Duration::from_millis(100); + +enum LogRecord { + Debug { + prefix: &'static str, + message: Arc, + }, + System(String), + Stderr(Vec), +} + +trait LogDestination: Send + 'static { + fn write(&mut self, record: LogRecord); + fn report_dropped(&mut self, count: usize); +} + +struct ProductionDestination { + debug: bool, +} + +impl LogDestination for ProductionDestination { + fn write(&mut self, record: LogRecord) { + match record { + LogRecord::Debug { prefix, message } if self.debug => { + eprintln!("{prefix}{}", serialize_debug_message(&message)); + } + LogRecord::System(message) => append_system_log_line(&message), + LogRecord::Stderr(chunk) if self.debug => { + let mut stderr = std::io::stderr().lock(); + let _ = stderr.write_all(&chunk); + let _ = stderr.flush(); + } + LogRecord::Debug { .. } | LogRecord::Stderr(_) => {} + } + } + + fn report_dropped(&mut self, count: usize) { + let message = format!( + "daemon logger dropped {count} diagnostic record(s) because its queue was full" + ); + append_system_log_line(&message); + if self.debug { + eprintln!("{message}"); + } + } +} + +struct Shared { + accepting: AtomicBool, + shutdown: AtomicBool, + dropped: AtomicUsize, +} + +#[derive(Clone)] +pub(super) struct Logger { + sender: SyncSender, + shared: Arc, + debug: bool, +} + +impl Logger { + fn enqueue(&self, record: LogRecord) { + if !self.shared.accepting.load(Ordering::Acquire) { + return; + } + match self.sender.try_send(record) { + Err(TrySendError::Full(_)) => increment_saturating(&self.shared.dropped), + Ok(()) | Err(TrySendError::Disconnected(_)) => {} + } + } + + pub(super) fn debug(&self, prefix: &'static str, message: Arc) { + if self.debug { + self.enqueue(LogRecord::Debug { prefix, message }); + } + } + + pub(super) fn debug_value(&self, prefix: &'static str, message: &Value) { + if self.debug { + self.enqueue(LogRecord::Debug { + prefix, + message: Arc::new(message.clone()), + }); + } + } + + pub(super) fn system(&self, message: impl Into) { + self.enqueue(LogRecord::System(message.into())); + } + + pub(super) fn unexpected(&self, error: impl std::fmt::Display) { + self.system(format!("unexpected error: {error}")); + } + + pub(super) fn server_starting(&self) { + self.system("starting LSP server..."); + } + + pub(super) fn server_started(&self, pid: u32) { + self.system(format!("LSP server has started (pid {pid})")); + } + + pub(super) fn server_exited(&self, status: ExitStatus) { + self.system(format!( + "LSP server exited with {}", + format_exit_status(status) + )); + } + + #[cfg(test)] + fn dropped(&self) -> usize { + self.shared.dropped.load(Ordering::Acquire) + } +} + +impl StderrSink for Logger { + fn write_chunk(&self, chunk: &[u8]) { + if self.debug { + self.enqueue(LogRecord::Stderr(chunk.to_vec())); + } + } + + fn write_line(&self, line: String) { + self.system(format!("stderr: {line}")); + } + + fn write_error(&self, error: String) { + self.unexpected(error); + } +} + +pub(super) struct LoggerWorker { + logger: Logger, + finished: Receiver<()>, + thread: Option>, +} + +impl LoggerWorker { + pub(super) fn spawn(debug: bool) -> Result { + Self::spawn_with( + debug, + Box::new(ProductionDestination { debug }), + LOG_QUEUE_LIMIT, + ) + } + + fn spawn_with( + debug: bool, + mut destination: Box, + queue_limit: usize, + ) -> Result { + let (sender, receiver) = mpsc::sync_channel(queue_limit); + let shared = Arc::new(Shared { + accepting: AtomicBool::new(true), + shutdown: AtomicBool::new(false), + dropped: AtomicUsize::new(0), + }); + let worker_shared = Arc::clone(&shared); + let (finished_sender, finished) = mpsc::channel(); + let thread = thread::Builder::new() + .name("daemon-logger".into()) + .spawn(move || { + run_worker(&receiver, &worker_shared, &mut *destination); + let _ = finished_sender.send(()); + }) + .map_err(|error| { + Error::unexpected(format!("failed to start daemon logger: {error}")) + })?; + Ok(Self { + logger: Logger { + sender, + shared, + debug, + }, + finished, + thread: Some(thread), + }) + } + + pub(super) fn logger(&self) -> Logger { + self.logger.clone() + } + + pub(super) fn finish(&mut self, timeout: Duration) { + if self.thread.is_none() { + return; + } + self.signal_shutdown(); + if self.finished.recv_timeout(timeout).is_ok() + && let Some(thread) = self.thread.take() + { + let _ = thread.join(); + } + } + + fn signal_shutdown(&self) { + self.logger.shared.accepting.store(false, Ordering::Release); + self.logger.shared.shutdown.store(true, Ordering::Release); + } +} + +impl Drop for LoggerWorker { + fn drop(&mut self) { + // Error paths must stop accepting logs, but waiting here could put an unlimited file-lock + // delay back on daemon cleanup. Normal shutdown calls finish with an explicit deadline. + self.signal_shutdown(); + if self + .thread + .as_ref() + .is_some_and(std::thread::JoinHandle::is_finished) + && let Some(thread) = self.thread.take() + { + let _ = thread.join(); + } + } +} + +fn run_worker(receiver: &Receiver, shared: &Shared, output: &mut dyn LogDestination) { + loop { + if shared.shutdown.load(Ordering::Acquire) { + while let Ok(record) = receiver.try_recv() { + output.write(record); + report_dropped(shared, output); + } + report_dropped(shared, output); + return; + } + match receiver.recv_timeout(WORKER_WAKE_INTERVAL) { + Ok(record) => { + output.write(record); + report_dropped(shared, output); + } + Err(mpsc::RecvTimeoutError::Timeout) => {} + Err(mpsc::RecvTimeoutError::Disconnected) => return, + } + } +} + +fn report_dropped(shared: &Shared, output: &mut dyn LogDestination) { + let dropped = shared.dropped.swap(0, Ordering::AcqRel); + if dropped > 0 { + output.report_dropped(dropped); + } +} + +fn increment_saturating(value: &AtomicUsize) { + let _ = value.fetch_update(Ordering::AcqRel, Ordering::Acquire, |current| { + Some(current.saturating_add(1)) + }); +} + +#[cfg(test)] +mod tests; diff --git a/src/commands/daemon/logger/tests.rs b/src/commands/daemon/logger/tests.rs new file mode 100644 index 0000000..9862b79 --- /dev/null +++ b/src/commands/daemon/logger/tests.rs @@ -0,0 +1,108 @@ +use super::*; +use serde_json::json; +use std::sync::{Condvar, Mutex}; +use std::time::Instant; + +#[derive(Default)] +struct SinkState { + entered: bool, + released: bool, + records: Vec, + dropped: Vec, +} + +struct PausedDestination { + state: Arc<(Mutex, Condvar)>, +} + +impl LogDestination for PausedDestination { + fn write(&mut self, record: LogRecord) { + let (lock, ready) = &*self.state; + let mut state = lock.lock().expect("sink state"); + state.entered = true; + ready.notify_all(); + while !state.released { + state = ready.wait(state).expect("release sink"); + } + state.records.push(match record { + LogRecord::Debug { prefix, message } => { + format!("{prefix}{}", serialize_debug_message(&message)) + } + LogRecord::System(message) => message, + LogRecord::Stderr(chunk) => String::from_utf8_lossy(&chunk).into_owned(), + }); + } + + fn report_dropped(&mut self, count: usize) { + self.state.0.lock().expect("sink state").dropped.push(count); + } +} + +fn paused_worker(queue_limit: usize) -> (LoggerWorker, Arc<(Mutex, Condvar)>) { + let state = Arc::new((Mutex::new(SinkState::default()), Condvar::new())); + let worker = LoggerWorker::spawn_with( + true, + Box::new(PausedDestination { + state: Arc::clone(&state), + }), + queue_limit, + ) + .expect("logger worker"); + (worker, state) +} + +fn release(state: &Arc<(Mutex, Condvar)>) { + state.0.lock().expect("sink state").released = true; + state.1.notify_all(); +} + +fn wait_until_entered(state: &Arc<(Mutex, Condvar)>) { + let mut guard = state.0.lock().expect("sink state"); + while !guard.entered { + guard = state.1.wait(guard).expect("worker enters sink"); + } +} + +#[test] +fn full_queue_drops_new_records_and_reports_after_progress() { + let (mut worker, state) = paused_worker(1); + let logger = worker.logger(); + logger.system("blocked"); + wait_until_entered(&state); + logger.system("queued"); + logger.system("dropped"); + assert_eq!(logger.dropped(), 1); + release(&state); + worker.finish(Duration::from_secs(1)); + let state = state.0.lock().expect("sink state"); + assert_eq!(state.records, ["blocked", "queued"]); + assert_eq!(state.dropped.iter().sum::(), 1); +} + +#[test] +fn debug_serialization_runs_after_enqueue() { + let (mut worker, state) = paused_worker(2); + worker + .logger() + .debug("prefix: ", Arc::new(json!({"answer": 42}))); + wait_until_entered(&state); + assert!(state.0.lock().expect("sink state").records.is_empty()); + release(&state); + worker.finish(Duration::from_secs(1)); + assert_eq!( + state.0.lock().expect("sink state").records, + ["prefix: {\n \"answer\": 42\n}"] + ); +} + +#[test] +fn shutdown_wait_is_bounded_when_destination_is_blocked() { + let (mut worker, state) = paused_worker(1); + worker.logger().system("blocked"); + wait_until_entered(&state); + let started = Instant::now(); + worker.finish(Duration::from_millis(20)); + assert!(started.elapsed() < Duration::from_millis(100)); + release(&state); + worker.finish(Duration::from_secs(1)); +} diff --git a/src/commands/daemon/outputs.rs b/src/commands/daemon/outputs.rs new file mode 100644 index 0000000..6a073ea --- /dev/null +++ b/src/commands/daemon/outputs.rs @@ -0,0 +1,102 @@ +use super::Daemon; +use super::events::Source; +use super::writer::WriterEvent; +use crate::error::Result; +use std::time::Instant; + +impl Daemon { + pub(super) fn handle_writer_event(&mut self, source: Source, event: WriterEvent) -> Result<()> { + match (source, event) { + (Source::Client(generation), WriterEvent::Completed { id, completed_at }) => { + if let Some(pending) = self.pending_connections.get_mut(&generation) { + pending.client.writer.refresh_flag(completed_at); + if pending.close_after_write == Some(id) { + let stop = pending.stop_after_write; + self.pending_connections.remove(&generation); + self.stop_requested |= stop; + } + } else if let Some(client) = self.active_client.as_mut() + && client.generation == generation + { + client.writer.refresh_flag(completed_at); + if client.stop_after_write == Some(id) { + self.stop_requested = true; + } + if client.disconnect_after_write == Some(id) { + self.disconnect_client()?; + } + } + } + (Source::Client(generation), WriterEvent::Failed { id, error }) => { + self.logger.unexpected(format!( + "daemon client output failed while writing message {id}: {error}" + )); + if self.pending_connections.remove(&generation).is_none() + && self + .active_client + .as_ref() + .is_some_and(|client| client.generation == generation) + { + self.disconnect_client()?; + } + } + (Source::Upstream(generation), WriterEvent::Completed { id, completed_at }) => { + self.handle_lifecycle_write(generation, id, completed_at); + if let Some(upstream) = self.upstream.as_mut() + && upstream.generation == generation + { + upstream.writer.refresh_flag(completed_at); + } + } + (Source::Upstream(generation), WriterEvent::Failed { id, error }) => { + if self + .upstream + .as_ref() + .is_some_and(|upstream| upstream.generation == generation) + { + self.logger.unexpected(format!( + "LSP server stopped accepting message {id}: {error}" + )); + self.upstream_failed(); + } + } + } + Ok(()) + } + + pub(super) fn expire_stalled_outputs(&mut self, now: Instant) -> Result<()> { + let stalled_pending: Vec<_> = self + .pending_connections + .iter_mut() + .filter_map(|(generation, pending)| { + pending + .client + .writer + .timed_out(now, self.write_stall_timeout) + .then_some(*generation) + }) + .collect(); + for generation in stalled_pending { + self.pending_connections.remove(&generation); + } + if self + .active_client + .as_mut() + .is_some_and(|client| client.writer.timed_out(now, self.write_stall_timeout)) + { + self.logger + .unexpected("daemon client was disconnected because it stopped reading output"); + self.disconnect_client()?; + } + if self + .upstream + .as_mut() + .is_some_and(|upstream| upstream.writer.timed_out(now, self.write_stall_timeout)) + { + self.logger + .unexpected("LSP server was stopped because it stopped reading daemon output"); + self.upstream_failed(); + } + Ok(()) + } +} diff --git a/src/commands/daemon/process.rs b/src/commands/daemon/process.rs index b3b4746..1b40ac2 100644 --- a/src/commands/daemon/process.rs +++ b/src/commands/daemon/process.rs @@ -1,28 +1,17 @@ -use super::{ - BACKGROUND_ENV, ClientPhase, ClientSession, Daemon, DaemonArgs, DaemonTarget, POLL_INTERVAL, - ReaderEvent, UPSTREAM_SHUTDOWN_TIMEOUT, UpstreamServer, -}; +use super::events::{EventQueue, ReaderWorker, Source}; +use super::writer::WriterWorker; +use super::{BACKGROUND_ENV, ClientPhase, ClientSession, Daemon, DaemonArgs, DaemonTarget}; use crate::commands::common::prepare_workspace; use crate::config::ConfigStore; use crate::error::{Error, Result, error_fn}; -use crate::lsp::transport::read_message; -use crate::lsp::{jsonrpc, path_to_file_uri, workspace_name}; +use crate::lsp::{path_to_file_uri, workspace_name}; use crate::runtime_state::{daemon_socket_path, default_daemon_root}; -use crate::server_stderr::CapturedStderr; -use crate::system_log::{ - log_lsp_server_exit, log_lsp_server_started, log_lsp_server_starting, log_unexpected_error, -}; -use lsp_types::notification::{Exit, Notification}; -use lsp_types::request::{Request, Shutdown}; -use serde_json::Value; use std::collections::{BTreeMap, BTreeSet}; use std::fs::{self, File}; use std::io::{BufRead, BufReader, Write}; use std::os::unix::net::{UnixListener, UnixStream}; use std::path::Path; use std::process::{Command, Stdio}; -use std::sync::mpsc::{self, Receiver}; -use std::thread; use std::time::Instant; pub(super) fn resolve_target(args: &DaemonArgs, config: &ConfigStore) -> Result { @@ -165,9 +154,14 @@ pub(super) fn launch_background_for_connection( } pub(super) fn run_background(args: &DaemonArgs, target: DaemonTarget) -> Result { - let mut daemon = match unsafe { setsid_wrapper() } - .and_then(|()| Daemon::new(target, args.server.debug, args.idle_timeout)) - { + let mut daemon = match unsafe { setsid_wrapper() }.and_then(|()| { + Daemon::new( + target, + args.server.debug, + args.idle_timeout, + args.write_stall_timeout, + ) + }) { Ok(daemon) => daemon, Err(error) => { let startup_error = error.to_string(); @@ -222,188 +216,39 @@ pub(super) fn bind_listener(socket_path: &Path) -> Result { }) } -pub(super) fn spawn_reader(reader: R) -> Receiver -where - R: std::io::Read + Send + 'static, -{ - let (sender, receiver) = mpsc::channel(); - thread::spawn(move || { - let mut reader = BufReader::new(reader); - loop { - match read_message(&mut reader) { - Ok(Some(message)) => { - if sender.send(ReaderEvent::Message(message)).is_err() { - return; - } - } - Ok(None) => { - let _ = sender.send(ReaderEvent::EndOfStream); - return; - } - Err(error) => { - let _ = sender.send(ReaderEvent::Error(error.to_string())); - return; - } - } - } - }); - receiver -} - impl ClientSession { - pub(super) fn new(stream: UnixStream) -> Result { + pub(super) fn new( + stream: UnixStream, + events: &mut EventQueue, + deadline: Option, + ) -> Result { let reader = stream.try_clone().map_err(|error| { Error::unexpected(format!("failed to clone client socket: {error}")) })?; + let generation = events.next_generation()?; + let worker = ReaderWorker::socket_with_deadline( + reader, + Source::Client(generation), + events, + deadline, + )?; + let writer = WriterWorker::socket(stream, Source::Client(generation), events)?; Ok(Self { - writer: stream, - messages: spawn_reader(reader), + writer, + generation, + reader: worker, phase: ClientPhase::WaitingForInitialize, wants_background_work: false, forwarded_client_requests: BTreeSet::new(), pending_server_requests: BTreeMap::new(), open_documents: BTreeSet::new(), + stop_after_write: None, + disconnect_after_write: None, }) } } -impl UpstreamServer { - pub(super) fn spawn(target: &DaemonTarget, debug: bool) -> Result { - let executable = std::env::current_exe().map_err(|error| { - Error::unexpected(format!("failed to resolve lsp-cli executable: {error}")) - })?; - let mut command = Command::new(executable); - command - .arg("run") - .arg(&target.path) - .stdin(Stdio::piped()) - .stdout(Stdio::piped()) - .stderr(Stdio::piped()); - - if debug { - command.arg("--debug"); - } - - command.arg("--lsp").arg(&target.server_name); - - log_lsp_server_starting(); - let mut child = command.spawn().map_err(|error| { - let error = format!( - "failed to start lsp-cli run for {}: {error}", - target.server_name - ); - log_unexpected_error(&error); - Error::unexpected(error) - })?; - log_lsp_server_started(child.id()); - let Some(stdin) = child.stdin.take() else { - let error = "failed to open LSP server stdin".to_string(); - log_unexpected_error(&error); - return Err(Error::unexpected(error)); - }; - let Some(stdout) = child.stdout.take() else { - let error = "failed to open LSP server stdout".to_string(); - log_unexpected_error(&error); - return Err(Error::unexpected(error)); - }; - let stderr = CapturedStderr::spawn( - child.stderr.take().ok_or_else(|| { - let error = "failed to open LSP server stderr".to_string(); - log_unexpected_error(&error); - Error::unexpected(error) - })?, - debug, - ); - - Ok(Self { - child, - stdin, - stderr, - messages: spawn_reader(stdout), - initialize_fingerprint: None, - initialize_result: None, - restart_required: false, - background_work: super::BackgroundWorkTracker::default(), - }) - } - - pub(super) fn shutdown(&mut self, debug: bool) -> Result<()> { - let _ = self.stderr.summary(); - if self.initialize_fingerprint.is_some() { - let shutdown_id = Value::String("lsp-cli/daemon-shutdown".to_string()); - let shutdown = jsonrpc(Some(shutdown_id.clone()), Shutdown::METHOD, &())?; - crate::lsp::transport::log_debug_message(debug, "daemon upstream <- ", &shutdown); - let _ = crate::lsp::transport::write_message(&mut self.stdin, &shutdown); - - let started = Instant::now(); - while started.elapsed() < UPSTREAM_SHUTDOWN_TIMEOUT { - let Some(remaining) = UPSTREAM_SHUTDOWN_TIMEOUT.checked_sub(started.elapsed()) - else { - break; - }; - - match self.messages.recv_timeout(remaining) { - Ok(ReaderEvent::Message(message)) => { - if super::response_id(&message).as_ref().is_some_and(|value| { - *value == Value::String("lsp-cli/daemon-shutdown".to_string()) - }) { - break; - } - } - Ok(ReaderEvent::EndOfStream | ReaderEvent::Error(_)) | Err(_) => break, - } - } - - let exit = jsonrpc::(None, Exit::METHOD, &())?; - crate::lsp::transport::log_debug_message(debug, "daemon upstream <- ", &exit); - let _ = crate::lsp::transport::write_message(&mut self.stdin, &exit); - } - - match self.child.try_wait() { - Ok(Some(status)) => { - log_lsp_server_exit(status); - return Ok(()); - } - Ok(None) => {} - Err(error) => { - let error = format!("failed to inspect LSP server process: {error}"); - log_unexpected_error(&error); - return Err(Error::unexpected(error)); - } - } - - let started = Instant::now(); - while started.elapsed() < UPSTREAM_SHUTDOWN_TIMEOUT { - match self.child.try_wait() { - Ok(Some(status)) => { - log_lsp_server_exit(status); - return Ok(()); - } - Ok(None) => thread::sleep(POLL_INTERVAL), - Err(error) => { - let error = format!("failed to wait for LSP server exit: {error}"); - log_unexpected_error(&error); - return Err(Error::unexpected(error)); - } - } - } - - self.child.kill().map_err(|error| { - let error = format!("failed to stop LSP server process: {error}"); - log_unexpected_error(&error); - Error::unexpected(error) - })?; - let status = self.child.wait().map_err(|error| { - let error = format!("failed to reap LSP server process: {error}"); - log_unexpected_error(&error); - Error::unexpected(error) - })?; - log_lsp_server_exit(status); - Ok(()) - } -} - unsafe fn setsid_wrapper() -> Result<()> { unsafe extern "C" { fn setsid() -> i32; diff --git a/src/commands/daemon/process_worker.rs b/src/commands/daemon/process_worker.rs new file mode 100644 index 0000000..fef9469 --- /dev/null +++ b/src/commands/daemon/process_worker.rs @@ -0,0 +1,236 @@ +use super::events::{Event, EventQueue}; +use crate::error::{Error, Result}; +use std::ffi::OsString; +use std::path::PathBuf; +use std::process::{Child, ChildStderr, ChildStdin, ChildStdout, Command, ExitStatus, Stdio}; +use std::sync::Arc; +use std::sync::atomic::{AtomicBool, Ordering}; +use std::sync::mpsc::{self, Sender, TryRecvError}; +use std::thread; +use std::time::Duration; + +const PROCESS_POLL_INTERVAL: Duration = Duration::from_millis(25); + +pub(super) struct ProcessSpec { + pub(super) program: PathBuf, + pub(super) args: Vec, +} + +pub(super) struct ProcessIo { + pub(super) stdin: ChildStdin, + pub(super) stdout: ChildStdout, + pub(super) stderr: ChildStderr, + pub(super) pid: u32, +} + +pub(super) enum ProcessEvent { + Started(ProcessIo), + StartFailed(String), + Exited(std::result::Result), +} + +enum ProcessCommand { + ForceStop, +} + +pub(super) struct ProcessWorker { + generation: u64, + commands: Option>, + cancelled: Arc, +} + +impl ProcessWorker { + pub(super) fn spawn(spec: ProcessSpec, generation: u64, events: &EventQueue) -> Result { + let (commands, receiver) = mpsc::channel(); + let (cancelled, _, admission) = events.admission(); + let worker_cancelled = Arc::clone(&cancelled); + thread::Builder::new() + .name("daemon-process".into()) + .spawn(move || { + let mut command = Command::new(&spec.program); + command + .args(&spec.args) + .stdin(Stdio::piped()) + .stdout(Stdio::piped()) + .stderr(Stdio::piped()); + let mut child = match command.spawn() { + Ok(child) => child, + Err(error) => { + let _ = admission.publish(Event::Process( + generation, + ProcessEvent::StartFailed(error.to_string()), + )); + return; + } + }; + + if matches!(receiver.try_recv(), Ok(ProcessCommand::ForceStop)) { + publish_exit(generation, stop_child(&mut child), &admission); + return; + } + let Some(io) = take_io(&mut child) else { + let _ = child.kill(); + let _ = child.wait(); + let _ = admission.publish(Event::Process( + generation, + ProcessEvent::StartFailed( + "LSP server process did not provide standard I/O".into(), + ), + )); + return; + }; + if !admission.publish(Event::Process(generation, ProcessEvent::Started(io))) { + let _ = stop_child(&mut child); + return; + } + + loop { + match receiver.try_recv() { + Ok(ProcessCommand::ForceStop) => { + publish_exit(generation, stop_child(&mut child), &admission); + return; + } + Err(TryRecvError::Disconnected) => { + let _ = stop_child(&mut child); + return; + } + Err(TryRecvError::Empty) => {} + } + match child.try_wait() { + Ok(Some(status)) => { + publish_exit(generation, Ok(status), &admission); + return; + } + Ok(None) => thread::sleep(PROCESS_POLL_INTERVAL), + Err(error) => { + publish_exit(generation, Err(error.to_string()), &admission); + return; + } + } + if worker_cancelled.load(Ordering::Acquire) { + let _ = stop_child(&mut child); + return; + } + } + }) + .map_err(|error| { + Error::unexpected(format!("failed to start LSP process worker: {error}")) + })?; + Ok(Self { + generation, + commands: Some(commands), + cancelled, + }) + } + + pub(super) fn generation(&self) -> u64 { + self.generation + } + + #[cfg(test)] + pub(super) fn adopt( + mut child: Child, + generation: u64, + events: &EventQueue, + ) -> (Self, ProcessIo) { + let io = take_io(&mut child).expect("test process standard I/O"); + let (commands, receiver) = mpsc::channel(); + let (cancelled, _, admission) = events.admission(); + let worker_cancelled = Arc::clone(&cancelled); + thread::Builder::new() + .name("daemon-test-process".into()) + .spawn(move || { + loop { + match receiver.try_recv() { + Ok(ProcessCommand::ForceStop) => { + publish_exit(generation, stop_child(&mut child), &admission); + return; + } + Err(TryRecvError::Disconnected) => { + let _ = stop_child(&mut child); + return; + } + Err(TryRecvError::Empty) => {} + } + match child.try_wait() { + Ok(Some(status)) => { + publish_exit(generation, Ok(status), &admission); + return; + } + Ok(None) => thread::sleep(PROCESS_POLL_INTERVAL), + Err(error) => { + publish_exit(generation, Err(error.to_string()), &admission); + return; + } + } + if worker_cancelled.load(Ordering::Acquire) { + let _ = stop_child(&mut child); + return; + } + } + }) + .expect("test process worker"); + ( + Self { + generation, + commands: Some(commands), + cancelled, + }, + io, + ) + } + + pub(super) fn force_stop(&self) -> Result<()> { + self.commands + .as_ref() + .ok_or_else(|| Error::unexpected("LSP process worker is closed"))? + .send(ProcessCommand::ForceStop) + .map_err(|_| Error::unexpected("LSP process worker stopped before termination")) + } +} + +impl Drop for ProcessWorker { + fn drop(&mut self) { + // The worker owns Child, so request termination explicitly before closing its command + // channel. Joining here would put an unlimited process wait back on the coordinator. + if let Some(commands) = self.commands.take() { + let _ = commands.send(ProcessCommand::ForceStop); + } + self.cancelled.store(true, Ordering::Release); + } +} + +fn take_io(child: &mut Child) -> Option { + Some(ProcessIo { + stdin: child.stdin.take()?, + stdout: child.stdout.take()?, + stderr: child.stderr.take()?, + pid: child.id(), + }) +} + +fn stop_child(child: &mut Child) -> std::result::Result { + match child.try_wait() { + Ok(Some(status)) => return Ok(status), + Ok(None) => {} + Err(error) => return Err(format!("failed to inspect LSP server process: {error}")), + } + let kill_error = child.kill().err(); + match child.wait() { + Ok(status) => Ok(status), + Err(wait_error) => Err(match kill_error { + Some(kill_error) => format!( + "failed to stop LSP server process: {kill_error}; failed to reap it: {wait_error}" + ), + None => format!("failed to reap LSP server process: {wait_error}"), + }), + } +} + +fn publish_exit( + generation: u64, + result: std::result::Result, + admission: &super::events::Admission, +) { + let _ = admission.publish(Event::Process(generation, ProcessEvent::Exited(result))); +} diff --git a/src/commands/daemon/protocol.rs b/src/commands/daemon/protocol.rs index b8996e2..5f76e38 100644 --- a/src/commands/daemon/protocol.rs +++ b/src/commands/daemon/protocol.rs @@ -1,6 +1,6 @@ -use super::{BUSY_CLIENT_TIMEOUT, Daemon, DaemonTarget, INVALID_REQUEST, REQUEST_CANCELLED}; +use super::{Daemon, DaemonTarget, INVALID_REQUEST}; use crate::error::{Error, Result, error_fn}; -use crate::lsp::transport::{log_debug_message, read_message, write_message}; +use crate::lsp::transport::{log_debug_message, read_message}; use crate::lsp::{SERVER_STATUS_METHOD, ServerStatusParams, parse_lsp_uri}; use lsp_types::WorkspaceFolder; use serde::Deserialize; @@ -8,12 +8,13 @@ use serde_json::{Value, json}; use std::collections::BTreeSet; use std::io::BufReader; use std::os::unix::net::UnixStream; +use std::sync::Arc; use std::time::Duration; pub(super) use crate::lsp::STOP_METHOD; pub(super) enum ReaderEvent { - Message(Value), + Message(Arc), EndOfStream, Error(String), } @@ -76,38 +77,6 @@ impl Daemon { } } -pub(super) fn handle_busy_connection(mut stream: UnixStream, debug: bool) -> Result { - let _ = stream.set_read_timeout(Some(BUSY_CLIENT_TIMEOUT)); - let Ok(reader_stream) = stream.try_clone() else { - return Ok(false); - }; - let mut reader = BufReader::new(reader_stream); - let Ok(Some(message)) = read_message(&mut reader) else { - return Ok(false); - }; - log_debug_message(debug, "daemon busy client <- ", &message); - - if stop_request_id(&message).is_some() { - respond_to_stop_request(&mut stream, &message, debug)?; - return Ok(true); - } - - let Some(request_id) = request_id(&message) else { - return Ok(false); - }; - if message_method(&message) != Some("initialize") { - return Ok(false); - } - - let response = error_response( - &request_id, - REQUEST_CANCELLED, - "another daemon client is already connected", - ); - let _ = write_message(&mut stream, &response); - Ok(false) -} - pub(super) fn read_control_message( stream: &UnixStream, timeout: Duration, @@ -143,22 +112,6 @@ pub(super) fn stop_request_id(message: &Value) -> Option { } } -pub(super) fn respond_to_stop_request( - stream: &mut UnixStream, - message: &Value, - debug: bool, -) -> Result<()> { - let Some(request_id) = stop_request_id(message) else { - return Err(Error::lsp("daemon stop request is missing an id")); - }; - let response = success_response(&request_id, &Value::Null); - log_debug_message(debug, "daemon control <- ", &response); - write_message(stream, &response).map_err(error_fn!( - Error::lsp, - "failed to write daemon stop response" - )) -} - pub(super) fn local_server_request_response(request_id: &Value, method: &str) -> Value { match method { "window/showMessageRequest" diff --git a/src/commands/daemon/session_tests.rs b/src/commands/daemon/session_tests.rs new file mode 100644 index 0000000..add123b --- /dev/null +++ b/src/commands/daemon/session_tests.rs @@ -0,0 +1,379 @@ +use super::*; +use crate::lsp::transport::read_message; +use crate::test_support::{TestDir, with_env_vars}; +use serde_json::json; +use std::io::{BufRead, BufReader, ErrorKind}; +use std::os::unix::net::UnixListener; +use std::process::{Command, Stdio}; +use std::sync::mpsc; + +const TIMEOUT: Duration = Duration::from_secs(3); + +pub(super) struct Fixture { + pub(super) daemon: Daemon, + pub(super) peer: BufReader, + _dir: TestDir, +} + +impl Fixture { + pub(super) fn new() -> Self { + let dir = TestDir::new("daemon-session"); + let target = tests::daemon_target(&dir); + let mut events = EventQueue::new(); + let logger_worker = LoggerWorker::spawn(false).expect("logger"); + let logger = logger_worker.logger(); + let (upstream, process) = fake_upstream(&mut events, logger.clone()); + let (socket, peer) = UnixStream::pair().expect("client pair"); + peer.set_read_timeout(Some(TIMEOUT)).expect("read timeout"); + let client = ClientSession::new(socket, &mut events, None).expect("client"); + Self { + daemon: Daemon { + accept_worker: None, + events, + socket_owned: true, + target, + debug: false, + logger, + logger_worker, + idle_timeout: TIMEOUT, + write_stall_timeout: TIMEOUT, + upstream: Some(upstream), + process: Some(process), + lifecycle: LifecycleState::Running, + pending_initialize: None, + active_client: Some(client), + pending_connections: BTreeMap::new(), + orphaned_client_requests: BTreeSet::new(), + idle_since: Instant::now(), + stop_requested: false, + }, + peer: BufReader::new(peer), + _dir: dir, + } + } + + pub(super) fn send(&mut self, message: &Value) { + write_message(self.peer.get_mut(), message).expect("client write"); + } + + pub(super) fn step(&mut self) { + let delivery = self + .daemon + .events + .receive(Some(TIMEOUT)) + .expect("coordinator event"); + let result = self.daemon.dispatch(delivery.event); + let _ = delivery.acknowledge.send(()); + result.expect("dispatch event"); + } + + pub(super) fn read(&mut self) -> Value { + if self.peer.buffer().is_empty() { + self.peer + .get_ref() + .set_nonblocking(true) + .expect("nonblocking peer"); + loop { + let ready = match self.peer.fill_buf() { + Ok([]) => panic!("client output closed"), + Ok(_) => true, + Err(error) if error.kind() == ErrorKind::WouldBlock => false, + Err(error) => panic!("inspect client output: {error}"), + }; + if ready { + break; + } + self.step(); + } + self.peer + .get_ref() + .set_nonblocking(false) + .expect("blocking peer"); + } + read_message(&mut self.peer) + .expect("read response") + .expect("response") + } + + pub(super) fn initialize(&mut self, reused: bool) -> Value { + self.send( + &json!({"jsonrpc": "2.0", "id": 1, "method": "initialize", "params": { + "rootUri": self.daemon.target.root_uri, "capabilities": {} + }}), + ); + self.step(); + if !reused { + for _ in 0..10 { + if self + .daemon + .active_client + .as_ref() + .is_some_and(|client| client.forwarded_client_requests.is_empty()) + { + break; + } + self.step(); + } + assert!( + self.daemon + .active_client + .as_ref() + .is_some_and(|client| { client.forwarded_client_requests.is_empty() }), + "initialize response was queued" + ); + } + let response = self.read(); + self.send(&json!({"jsonrpc": "2.0", "method": "initialized", "params": {}})); + for _ in 0..10 { + if self + .daemon + .active_client + .as_ref() + .is_some_and(|client| matches!(client.phase, ClientPhase::Ready)) + { + break; + } + self.step(); + } + assert!( + self.daemon + .active_client + .as_ref() + .is_some_and(|client| { matches!(client.phase, ClientPhase::Ready) }), + "initialized notification was handled" + ); + response + } + + pub(super) fn replace_client(&mut self) { + self.daemon.disconnect_client().expect("disconnect"); + let (socket, peer) = UnixStream::pair().expect("replacement pair"); + peer.set_read_timeout(Some(TIMEOUT)).expect("read timeout"); + self.daemon.active_client = Some( + ClientSession::new(socket, &mut self.daemon.events, None).expect("replacement client"), + ); + self.peer = BufReader::new(peer); + } +} + +fn fake_upstream(events: &mut EventQueue, logger: Logger) -> (UpstreamServer, ProcessWorker) { + let child = with_env_vars(&[], || { + Command::new("python3") + .arg(concat!( + env!("CARGO_MANIFEST_DIR"), + "/scripts/daemon_latency.py" + )) + .arg("--server") + .stdin(Stdio::piped()) + .stdout(Stdio::piped()) + .stderr(Stdio::piped()) + .spawn() + .expect("fake server") + }); + let generation = events.next_generation().expect("upstream generation"); + let (process, io) = ProcessWorker::adopt(child, generation, events); + let upstream = UpstreamServer::from_io(io, generation, logger, events).expect("upstream"); + (upstream, process) +} + +#[test] +fn forwards_sequential_and_pipelined_requests_with_warm_reuse() { + let mut fixture = Fixture::new(); + let initialized = fixture.initialize(false); + for width in [1, 8] { + for id in 10..10 + width { + fixture + .send(&json!({"jsonrpc": "2.0", "id": id, "method": "latency/echo", "params": id})); + } + for _ in 0..width * 2 { + fixture.step(); + } + for id in 10..10 + width { + assert_eq!( + fixture.read(), + json!({"jsonrpc": "2.0", "id": id, "result": id}) + ); + } + } + fixture.replace_client(); + assert_eq!( + fixture.initialize(true), + initialized, + "reuse cached initialization and same process" + ); +} + +#[test] +fn stale_generations_cannot_modify_replacement_sessions() { + let mut fixture = Fixture::new(); + fixture.initialize(false); + let old_client = fixture + .daemon + .active_client + .as_ref() + .expect("client") + .generation; + let old_upstream = fixture + .daemon + .upstream + .as_ref() + .expect("upstream") + .generation; + fixture.replace_client(); + fixture.daemon.upstream.take(); + fixture.daemon.process.take(); + let (upstream, process) = + fake_upstream(&mut fixture.daemon.events, fixture.daemon.logger.clone()); + fixture.daemon.upstream = Some(upstream); + fixture.daemon.process = Some(process); + fixture.daemon.lifecycle = LifecycleState::Running; + let client = fixture + .daemon + .active_client + .as_ref() + .expect("client") + .generation; + let upstream = fixture + .daemon + .upstream + .as_ref() + .expect("upstream") + .generation; + for source in [Source::Client(old_client), Source::Upstream(old_upstream)] { + for event in [ + ReaderEvent::Message(json!({"id": 9, "method": "exit"}).into()), + ReaderEvent::EndOfStream, + ReaderEvent::Error("retired".into()), + ] { + fixture + .daemon + .dispatch(Event::Reader(source, event)) + .expect("ignore stale event"); + assert_eq!( + fixture + .daemon + .active_client + .as_ref() + .expect("client retained") + .generation, + client + ); + assert_eq!( + fixture + .daemon + .upstream + .as_ref() + .expect("upstream retained") + .generation, + upstream + ); + } + } + assert!(!fixture.daemon.stop_requested); +} + +#[test] +fn shutdown_keeps_dispatching_unrelated_client_messages() { + let mut fixture = Fixture::new(); + fixture.initialize(false); + fixture.send(&json!({"jsonrpc": "2.0", "method": "exit"})); + fixture + .daemon + .begin_stop() + .expect("begin event-driven stop"); + for _ in 0..20 { + if fixture.daemon.lifecycle == LifecycleState::Stopped { + break; + } + fixture.step(); + } + assert!( + fixture.daemon.active_client.is_none(), + "queued client exit was preserved" + ); +} + +#[test] +fn idle_deadline_does_not_discard_shutdown_events() { + let mut fixture = Fixture::new(); + fixture.daemon.disconnect_client().expect("disconnect"); + fixture.daemon.idle_timeout = Duration::ZERO; + fixture.daemon.begin_stop().expect("begin stop"); + assert!(!fixture.daemon.idle_stop_due()); +} + +#[test] +fn idle_deadline_runs_during_continuous_events() { + let mut fixture = Fixture::new(); + fixture.daemon.disconnect_client().expect("disconnect"); + fixture.daemon.upstream.take(); + fixture.daemon.idle_timeout = Duration::from_millis(20); + fixture.daemon.idle_since = Instant::now(); + let (socket, mut peer) = UnixStream::pair().expect("notification pair"); + let producer = ReaderWorker::socket(socket, Source::Upstream(999), &fixture.daemon.events) + .expect("producer"); + let writer = thread::spawn(move || { + while write_message(&mut peer, &json!({"method": "notification"})).is_ok() {} + }); + let (done, result) = mpsc::channel(); + let daemon_thread = thread::spawn(move || { + done.send(fixture.daemon.serve()).expect("serve result"); + }); + result + .recv_timeout(TIMEOUT) + .expect("idle deadline was not starved") + .expect("idle stop"); + producer.cancel(); + writer.join().expect("notification writer exits"); + daemon_thread.join().expect("daemon exits"); +} + +#[test] +fn idle_receive_wakes_for_connection_then_client_stop() { + let mut fixture = Fixture::new(); + fixture.daemon.disconnect_client().expect("disconnect"); + let path = fixture.daemon.target.socket_path.clone(); + let listener = UnixListener::bind(&path).expect("listener"); + fixture.daemon.accept_worker = + Some(AcceptWorker::spawn(listener, &path, &fixture.daemon.events).expect("accept worker")); + let (done, result) = mpsc::channel(); + let daemon_thread = thread::spawn(move || { + done.send(fixture.daemon.serve()).expect("serve result"); + }); + assert!(matches!( + stop_socket(&path, false).expect("stop while idle"), + StopSocketResult::Stopped + )); + result + .recv_timeout(TIMEOUT) + .expect("stop handled") + .expect("clean stop"); + daemon_thread.join().expect("daemon exits"); + assert!(!path.exists()); +} + +#[test] +fn dropping_stopped_daemon_preserves_replacement_socket() { + let Fixture { + mut daemon, + _dir: dir, + .. + } = Fixture::new(); + let path = daemon.target.socket_path.clone(); + let listener = UnixListener::bind(&path).expect("listener"); + daemon.accept_worker = + Some(AcceptWorker::spawn(listener, &path, &daemon.events).expect("accept worker")); + daemon.upstream.take(); + daemon.process.take(); + daemon.lifecycle = LifecycleState::Absent; + daemon.begin_stop().expect("begin stop"); + daemon.finish_stop().expect("stop removes owned socket"); + let _replacement = UnixListener::bind(&path).expect("replacement listener"); + // Explicit teardown reproduces another daemon binding between normal stop and destruction. + drop(daemon); + assert!(path.exists(), "replacement socket must remain linked"); + assert!( + dir.path().exists(), + "keep temporary directory alive through teardown" + ); +} diff --git a/src/commands/daemon/socket_reader.rs b/src/commands/daemon/socket_reader.rs new file mode 100644 index 0000000..846800f --- /dev/null +++ b/src/commands/daemon/socket_reader.rs @@ -0,0 +1,69 @@ +use crate::error::{Error, Result}; +use crate::lsp::transport::read_message; +use serde_json::Value; +use std::io::{self, BufReader, Read}; +use std::net::Shutdown; +use std::os::unix::net::UnixStream; +use std::time::Instant; + +const DEADLINE_MESSAGE: &str = "daemon client did not send its first message before the deadline"; + +pub(super) struct SocketReader { + reader: BufReader, +} + +impl SocketReader { + pub(super) fn new(socket: UnixStream, deadline: Option) -> Self { + Self { + reader: BufReader::new(DeadlineSocket { socket, deadline }), + } + } + + pub(super) fn next_message(&mut self) -> Result> { + let message = read_message(&mut self.reader); + let socket = self.reader.get_mut(); + if let Some(deadline) = socket.deadline { + // BufReader may satisfy reads from its buffer, so also check the deadline after + // the entire first frame has been parsed. Keep this buffer when admitting a client. + let finish = if Instant::now() >= deadline { + Err(Error::lsp(DEADLINE_MESSAGE)) + } else { + socket.socket.set_read_timeout(None).map_err(|error| { + Error::unexpected(format!( + "failed to clear daemon client handshake timeout: {error}" + )) + }) + }; + if finish.is_err() || !matches!(&message, Ok(Some(_))) { + // Close independently of coordinator progress, which may be in synchronous I/O. + let _ = socket.socket.shutdown(Shutdown::Both); + } + finish?; + socket.deadline = None; + } + message + } +} + +struct DeadlineSocket { + socket: UnixStream, + deadline: Option, +} + +impl Read for DeadlineSocket { + fn read(&mut self, buffer: &mut [u8]) -> io::Result { + if let Some(deadline) = self.deadline { + let remaining = deadline.saturating_duration_since(Instant::now()); + if remaining.is_zero() { + return Err(io::Error::new(io::ErrorKind::TimedOut, DEADLINE_MESSAGE)); + } + // Socket timeouts apply per read. Recompute the remaining absolute budget so + // partial headers/bodies and trickled bytes cannot renew the handshake deadline. + self.socket.set_read_timeout(Some(remaining))?; + } + self.socket.read(buffer) + } +} + +#[cfg(test)] +mod tests; diff --git a/src/commands/daemon/socket_reader/tests.rs b/src/commands/daemon/socket_reader/tests.rs new file mode 100644 index 0000000..f255e09 --- /dev/null +++ b/src/commands/daemon/socket_reader/tests.rs @@ -0,0 +1,101 @@ +use super::*; +use crate::lsp::transport::write_message; +use serde_json::json; +use std::io::{BufRead, Write}; +use std::sync::mpsc; +use std::thread; +use std::time::Duration; + +const TEST_TIMEOUT: Duration = Duration::from_secs(3); + +fn pair(deadline: Instant) -> (SocketReader, UnixStream) { + let (socket, peer) = UnixStream::pair().expect("socket pair"); + peer.set_read_timeout(Some(TEST_TIMEOUT)) + .expect("peer read timeout"); + peer.set_write_timeout(Some(TEST_TIMEOUT)) + .expect("peer write timeout"); + (SocketReader::new(socket, Some(deadline)), peer) +} + +fn assert_closed(peer: &mut UnixStream) { + match peer.read(&mut [0]) { + Ok(bytes) => assert_eq!(bytes, 0, "peer observes EOF"), + Err(error) => assert_eq!( + error.kind(), + std::io::ErrorKind::ConnectionReset, + "peer observes socket shutdown" + ), + } +} + +#[test] +fn silent_first_message_expires_without_coordinator_progress() { + let (mut reader, mut peer) = pair(Instant::now() + Duration::from_millis(30)); + reader + .next_message() + .expect_err("silent handshake must expire"); + assert_closed(&mut peer); +} + +#[test] +fn trickled_header_and_body_cannot_renew_deadline() { + for prefix in ["Content-Length: ", "Content-Length: 10000\r\n\r\n"] { + let (mut reader, mut peer) = pair(Instant::now() + Duration::from_millis(60)); + peer.write_all(prefix.as_bytes()).expect("partial frame"); + let (done, result) = mpsc::channel(); + let worker = thread::spawn(move || { + done.send(reader.next_message()).expect("reader result"); + }); + let writer = thread::spawn(move || { + while peer.write_all(b"1").is_ok() { + thread::sleep(Duration::from_millis(5)); + } + assert_closed(&mut peer); + }); + result + .recv_timeout(TEST_TIMEOUT) + .expect("trickling did not postpone expiry") + .expect_err("incomplete first frame must expire"); + worker.join().expect("reader exits"); + writer.join().expect("writer observes shutdown"); + } +} + +#[test] +fn expiry_wins_over_a_buffered_first_message() { + let (mut reader, mut peer) = pair(Instant::now() + TEST_TIMEOUT); + write_message(&mut peer, &json!({"id": 1})).expect("first frame"); + // Prefill the exact production buffer, then expire the deadline without relying on sleep. + assert!(!reader.reader.fill_buf().expect("prefill").is_empty()); + reader.reader.get_mut().deadline = Some(Instant::now()); + reader + .next_message() + .expect_err("buffered frame still needs deadline validation"); + assert_closed(&mut peer); +} + +#[test] +fn first_message_preserves_pipelined_frames_and_clears_read_timeout() { + let (mut reader, mut peer) = pair(Instant::now() + TEST_TIMEOUT); + let mut frames = Vec::new(); + for id in 1..=3 { + write_message(&mut frames, &json!({"id": id})).expect("encode frame"); + } + peer.write_all(&frames).expect("pipeline"); + for id in 1..=3 { + assert_eq!( + reader.next_message().expect("frame"), + Some(json!({"id": id})) + ); + assert!(reader.reader.get_ref().deadline.is_none()); + assert_eq!( + reader + .reader + .get_ref() + .socket + .read_timeout() + .expect("socket timeout"), + None + ); + } +} diff --git a/src/commands/daemon/tests.rs b/src/commands/daemon/tests.rs index fb77554..273742e 100644 --- a/src/commands/daemon/tests.rs +++ b/src/commands/daemon/tests.rs @@ -1,17 +1,19 @@ -use super::{ - BackgroundWorkTracker, StopSocketResult, fingerprint_value, normalize_initialize_params, - stop_socket, update_background_work_tracker, wants_background_work, +use super::protocol::{ + fingerprint_value, normalize_initialize_params, update_background_work_tracker, + wants_background_work, }; +use super::{BackgroundWorkTracker, StopSocketResult, stop_socket}; use crate::lsp::transport::{read_message, write_message}; use crate::runtime_state::daemon_socket_path; use crate::test_support::TestDir; use serde_json::json; use std::fs; use std::io::BufReader; -use std::os::unix::net::UnixListener; +use std::os::unix::net::{UnixListener, UnixStream}; +use std::sync::Arc; use std::thread; -fn daemon_target(dir: &TestDir) -> super::DaemonTarget { +pub(super) fn daemon_target(dir: &TestDir) -> super::DaemonTarget { let workspace_root = dir.path().join("workspace"); std::fs::create_dir_all(&workspace_root).expect("workspace should exist"); @@ -252,26 +254,6 @@ fn stop_socket_removes_stale_socket() { assert!(!socket_path.exists(), "stale socket should be removed"); } -#[test] -fn busy_stop_request_receives_success_response() { - let dir = TestDir::new("daemon-stop-busy"); - let socket_path = dir.path().join("daemon.sock"); - let listener = UnixListener::bind(&socket_path).expect("socket should bind"); - - let server = thread::spawn(move || { - let (stream, _) = listener.accept().expect("client should connect"); - let handled = super::protocol::handle_busy_connection(stream, false) - .expect("busy connection should parse"); - assert!(handled, "stop request should be handled as busy control"); - }); - - assert!(matches!( - stop_socket(&socket_path, false).expect("stop should succeed"), - StopSocketResult::Stopped - )); - server.join().expect("server thread should finish"); -} - #[test] fn stop_socket_returns_not_running_when_socket_is_missing() { let dir = TestDir::new("daemon-stop-missing"); @@ -284,68 +266,95 @@ fn stop_socket_returns_not_running_when_socket_is_missing() { )); } -#[test] -fn forwards_multiple_requests_and_out_of_order_responses() { - use super::{ClientPhase, ClientSession, Daemon, ReaderEvent, UpstreamServer}; - use crate::server_stderr::CapturedStderr; +fn window_fixture() -> (super::Daemon, UnixStream, TestDir) { + use super::events::EventQueue; + use super::{ClientPhase, ClientSession, Daemon, UpstreamServer}; use std::collections::{BTreeMap, BTreeSet}; - use std::os::unix::net::UnixStream; use std::process::{Command, Stdio}; use std::time::{Duration, Instant}; let dir = TestDir::new("daemon-window"); let target = daemon_target(&dir); + let mut events = EventQueue::new(); + let logger_worker = super::LoggerWorker::spawn(false).expect("logger"); + let logger = logger_worker.logger(); // Echo upstream bytes so the test can inspect forwarding without a real LSP. - let mut child = Command::new("/bin/cat") + let child = Command::new("/bin/cat") .stdin(Stdio::piped()) .stdout(Stdio::piped()) .stderr(Stdio::piped()) .spawn() .expect("start echo process"); - let upstream = UpstreamServer { - stdin: child.stdin.take().expect("stdin"), - messages: super::process::spawn_reader(child.stdout.take().expect("stdout")), - stderr: CapturedStderr::spawn(child.stderr.take().expect("stderr"), false), - child, - initialize_fingerprint: None, - initialize_result: None, - restart_required: false, - background_work: BackgroundWorkTracker::default(), - }; + let generation = events.next_generation().expect("generation"); + let (process, io) = super::ProcessWorker::adopt(child, generation, &events); + let upstream = + UpstreamServer::from_io(io, generation, logger.clone(), &events).expect("upstream"); let (client, proxy) = UnixStream::pair().expect("client socket pair"); client .set_read_timeout(Some(Duration::from_secs(3))) .expect("read timeout"); - let mut session = ClientSession::new(proxy).expect("session"); + let mut session = ClientSession::new(proxy, &mut events, None).expect("session"); session.phase = ClientPhase::Ready; - let mut daemon = Daemon { - listener: UnixListener::bind(&target.socket_path).expect("listener"), + let daemon = Daemon { + accept_worker: None, + events, + socket_owned: false, target, debug: false, + logger, + logger_worker, idle_timeout: Duration::from_secs(60), + write_stall_timeout: Duration::from_secs(2), upstream: Some(upstream), + process: Some(process), + lifecycle: super::LifecycleState::Running, + pending_initialize: None, active_client: Some(session), + pending_connections: BTreeMap::new(), orphaned_client_requests: BTreeSet::new(), idle_since: Instant::now(), stop_requested: false, }; + (daemon, client, dir) +} + +fn receive_forwarded(daemon: &mut super::Daemon, expected: &serde_json::Value) { + use super::ReaderEvent; + use super::events::{Event, Source}; + use std::time::Duration; + + loop { + let delivery = daemon + .events + .receive(Some(Duration::from_secs(3))) + .expect("forwarded message"); + match delivery.event { + Event::Reader(Source::Upstream(_), ReaderEvent::Message(message)) => { + assert_eq!(*message, *expected); + let _ = delivery.acknowledge.send(()); + return; + } + event => { + daemon.dispatch(event).expect("dispatch progress"); + let _ = delivery.acknowledge.send(()); + } + } + } +} + +#[test] +fn forwards_multiple_requests_and_out_of_order_responses() { + use std::collections::BTreeMap; + use std::time::Duration; + + let (mut daemon, client, _dir) = window_fixture(); let mut expected = BTreeMap::new(); for id in 1..=20 { let request = json!({"jsonrpc":"2.0","id":id,"method":"textDocument/documentSymbol", "params":{"textDocument":{"uri":format!("file:///{id}.lua")}}}); daemon - .handle_client_message(&request) + .handle_client_message(&Arc::new(request.clone())) .expect("forward request"); - match daemon - .upstream - .as_ref() - .expect("upstream") - .messages - .recv_timeout(Duration::from_secs(3)) - .expect("echo") - { - ReaderEvent::Message(message) => assert_eq!(message, request), - _ => panic!("expected echoed request"), - } + receive_forwarded(&mut daemon, &request); expected.insert(id, json!({"jsonrpc":"2.0","id":id,"result":[]})); } assert_eq!( @@ -360,12 +369,20 @@ fn forwards_multiple_requests_and_out_of_order_responses() { let mut reader = BufReader::new(client); for response in expected.values().rev() { daemon - .handle_upstream_message(response) + .handle_upstream_message(&Arc::new(response.clone())) .expect("forward response"); assert_eq!( read_message(&mut reader).expect("read").expect("response"), *response ); + let delivery = daemon + .events + .receive(Some(Duration::from_secs(3))) + .expect("write completion"); + daemon + .dispatch(delivery.event) + .expect("dispatch completion"); + let _ = delivery.acknowledge.send(()); } assert!( daemon @@ -375,8 +392,91 @@ fn forwards_multiple_requests_and_out_of_order_responses() { .forwarded_client_requests .is_empty() ); - // Child handles do not stop/reap processes automatically; finish the echo helper. - let upstream = daemon.upstream.as_mut().expect("upstream"); - upstream.child.kill().expect("stop echo process"); - upstream.child.wait().expect("reap echo process"); + daemon.upstream_failed(); + while daemon.lifecycle != super::LifecycleState::Absent { + let delivery = daemon + .events + .receive(Some(Duration::from_secs(3))) + .expect("process exit"); + daemon + .dispatch(delivery.event) + .expect("dispatch process exit"); + let _ = delivery.acknowledge.send(()); + } +} + +#[test] +fn shutdown_deadline_forces_process_exit_without_blocking_dispatch() { + use std::time::{Duration, Instant}; + + let (mut daemon, _client, _dir) = window_fixture(); + daemon + .upstream + .as_mut() + .expect("upstream") + .initialize_fingerprint = Some("initialized".into()); + daemon.begin_stop().expect("begin stop"); + assert!(matches!( + daemon.lifecycle, + super::LifecycleState::AwaitingShutdownReply { .. } + )); + daemon.advance_lifecycle_deadline(Instant::now() + Duration::from_secs(3)); + assert!(matches!( + daemon.lifecycle, + super::LifecycleState::Killing { .. } + )); + while daemon.lifecycle != super::LifecycleState::Stopped { + let delivery = daemon + .events + .receive(Some(Duration::from_secs(3))) + .expect("lifecycle event"); + daemon.dispatch(delivery.event).expect("dispatch lifecycle"); + let _ = delivery.acknowledge.send(()); + } +} + +#[test] +fn replacement_start_failure_replies_and_keeps_daemon_available() { + use super::process_worker::ProcessEvent; + use std::time::Duration; + + let (mut daemon, client, _dir) = window_fixture(); + let generation = daemon.process.as_ref().expect("process").generation(); + daemon.upstream.take(); + daemon.lifecycle = super::LifecycleState::Starting { + generation, + initial: false, + }; + daemon.pending_initialize = Some(super::PendingInitialize { + request_id: json!(42), + normalized: json!({}), + fingerprint: "replacement".into(), + wants_background_work: false, + }); + daemon + .handle_process_event(generation, ProcessEvent::StartFailed("not found".into())) + .expect("handle start failure"); + + let mut reader = BufReader::new(client); + let response = read_message(&mut reader) + .expect("read failure response") + .expect("failure response"); + assert_eq!(response["id"], 42); + assert_eq!(response["error"]["code"], super::INTERNAL_ERROR); + assert!( + response["error"]["message"] + .as_str() + .expect("message") + .contains("failed to start LSP server") + ); + + while daemon.active_client.is_some() { + let delivery = daemon + .events + .receive(Some(Duration::from_secs(3))) + .expect("client close event"); + daemon.dispatch(delivery.event).expect("dispatch close"); + let _ = delivery.acknowledge.send(()); + } + assert_eq!(daemon.lifecycle, super::LifecycleState::Absent); } diff --git a/src/commands/daemon/writer.rs b/src/commands/daemon/writer.rs new file mode 100644 index 0000000..e49e76f --- /dev/null +++ b/src/commands/daemon/writer.rs @@ -0,0 +1,205 @@ +use super::events::{Event, EventQueue, Source}; +use crate::error::{Error, Result}; +use crate::lsp::transport::frame_message; +use serde_json::Value; +use std::io::Write; +use std::net::Shutdown; +use std::os::unix::net::UnixStream; +use std::sync::Arc; +use std::sync::atomic::AtomicBool; +use std::sync::atomic::{AtomicUsize, Ordering}; +use std::sync::mpsc::{self, Sender}; +use std::thread::{self, JoinHandle}; +use std::time::{Duration, Instant}; + +pub(super) const MESSAGE_LIMIT: usize = 64; +pub(super) const BYTE_LIMIT: usize = 8 * 1024 * 1024; + +pub(super) type WriteId = u64; + +#[derive(Debug)] +pub(super) enum WriterEvent { + Completed { id: WriteId, completed_at: Instant }, + Failed { id: WriteId, error: String }, +} + +struct Frame { + id: WriteId, + bytes: Vec, +} + +struct Progress { + messages: AtomicUsize, + bytes: AtomicUsize, +} + +pub(super) struct WriterWorker { + sender: Option>, + progress: Arc, + flagged_since: Option, + next_id: WriteId, + socket: Option, + cancelled: Arc, + acknowledge: Sender<()>, + thread: Option>, +} + +impl WriterWorker { + pub(super) fn spawn( + mut writer: W, + source: Source, + events: &EventQueue, + ) -> Result { + let (sender, receiver) = mpsc::channel::(); + let progress = Arc::new(Progress { + messages: AtomicUsize::new(0), + bytes: AtomicUsize::new(0), + }); + let worker_progress = Arc::clone(&progress); + let (cancelled, acknowledge, admission) = events.admission(); + let handle = thread::Builder::new() + .name("daemon-writer".to_string()) + .spawn(move || { + while let Ok(frame) = receiver.recv() { + let result = writer.write_all(&frame.bytes).and_then(|()| writer.flush()); + let failed = result.is_err(); + worker_progress.messages.fetch_sub(1, Ordering::AcqRel); + worker_progress + .bytes + .fetch_sub(frame.bytes.len(), Ordering::AcqRel); + let event = match result { + Ok(()) => WriterEvent::Completed { + id: frame.id, + completed_at: Instant::now(), + }, + Err(error) => WriterEvent::Failed { + id: frame.id, + error: error.to_string(), + }, + }; + // Completion must not hold up the next write; progress atomics bound the + // coordinator's view while events report ordering and failures. + if !admission.publish(Event::Writer(source, event)) || failed { + return; + } + } + }) + .map_err(|error| { + Error::unexpected(format!("failed to start daemon writer: {error}")) + })?; + Ok(Self { + sender: Some(sender), + progress, + flagged_since: None, + next_id: 0, + socket: None, + cancelled, + acknowledge, + thread: Some(handle), + }) + } + + pub(super) fn socket(socket: UnixStream, source: Source, events: &EventQueue) -> Result { + let writer = socket.try_clone().map_err(|error| { + Error::unexpected(format!("failed to clone daemon client writer: {error}")) + })?; + let mut worker = Self::spawn(writer, source, events)?; + worker.socket = Some(socket); + Ok(worker) + } + + pub(super) fn enqueue(&mut self, message: &Value) -> Result { + let frame = frame_message(message)?; + let messages = self + .progress + .messages + .load(Ordering::Acquire) + .checked_add(1) + .ok_or_else(|| Error::unexpected("daemon output message count overflowed"))?; + let bytes = self + .progress + .bytes + .load(Ordering::Acquire) + .checked_add(frame.len()) + .ok_or_else(|| Error::unexpected("daemon output byte count overflowed"))?; + let Some(id) = self.next_id.checked_add(1) else { + return Err(Error::unexpected( + "daemon exhausted its output message identifiers", + )); + }; + self.next_id = id; + self.progress.messages.fetch_add(1, Ordering::AcqRel); + self.progress.bytes.fetch_add(frame.len(), Ordering::AcqRel); + let Some(sender) = self.sender.as_ref() else { + self.rollback(frame.len()); + return Err(Error::lsp("daemon output is closed")); + }; + if let Err(error) = sender.send(Frame { id, bytes: frame }) { + self.rollback(error.0.bytes.len()); + return Err(Error::lsp("daemon output writer stopped")); + } + if (messages >= MESSAGE_LIMIT || bytes >= BYTE_LIMIT) && self.flagged_since.is_none() { + self.flagged_since = Some(Instant::now()); + } + Ok(id) + } + + fn rollback(&self, bytes: usize) { + self.progress.messages.fetch_sub(1, Ordering::AcqRel); + self.progress.bytes.fetch_sub(bytes, Ordering::AcqRel); + } + + pub(super) fn refresh_flag(&mut self, now: Instant) { + let messages = self.progress.messages.load(Ordering::Acquire); + let bytes = self.progress.bytes.load(Ordering::Acquire); + if messages < MESSAGE_LIMIT && bytes < BYTE_LIMIT { + self.flagged_since = None; + } else if self.flagged_since.is_none() { + self.flagged_since = Some(now); + } + } + + pub(super) fn deadline(&self, timeout: Duration) -> Option { + self.flagged_since + .and_then(|started| started.checked_add(timeout)) + } + + pub(super) fn timed_out(&mut self, now: Instant, timeout: Duration) -> bool { + self.refresh_flag(now); + self.deadline(timeout) + .is_some_and(|deadline| now >= deadline) + } + + #[cfg(test)] + pub(super) fn outstanding(&self) -> (usize, usize) { + ( + self.progress.messages.load(Ordering::Acquire), + self.progress.bytes.load(Ordering::Acquire), + ) + } + + pub(super) fn cancel(&mut self) { + self.cancelled.store(true, Ordering::Release); + let _ = self.acknowledge.send(()); + self.sender.take(); + if let Some(socket) = &self.socket { + let _ = socket.shutdown(Shutdown::Both); + } + } +} + +impl Drop for WriterWorker { + fn drop(&mut self) { + // A socket shutdown interrupts a blocked write. Child pipes have no equivalent safe + // standard-library operation, so never impose an unlimited join on their writer. + self.cancel(); + if let Some(thread) = self.thread.take() + && (self.socket.is_some() || thread.is_finished()) + { + let _ = thread.join(); + } + } +} + +#[cfg(test)] +mod tests; diff --git a/src/commands/daemon/writer/tests.rs b/src/commands/daemon/writer/tests.rs new file mode 100644 index 0000000..bdc1685 --- /dev/null +++ b/src/commands/daemon/writer/tests.rs @@ -0,0 +1,57 @@ +use super::*; + +fn worker(messages: usize, bytes: usize, flagged_since: Option) -> WriterWorker { + let (sender, _) = mpsc::channel(); + let (acknowledge, _) = mpsc::channel(); + WriterWorker { + sender: Some(sender), + progress: Arc::new(Progress { + messages: AtomicUsize::new(messages), + bytes: AtomicUsize::new(bytes), + }), + flagged_since, + next_id: 0, + socket: None, + cancelled: Arc::new(AtomicBool::new(false)), + acknowledge, + thread: None, + } +} + +#[test] +fn queue_flag_tracks_both_limits_and_clears_below_them() { + let now = Instant::now(); + let mut writer = worker(MESSAGE_LIMIT, 1, None); + assert_eq!(writer.outstanding(), (MESSAGE_LIMIT, 1)); + writer.refresh_flag(now); + assert_eq!( + writer.deadline(Duration::from_secs(2)), + Some(now + Duration::from_secs(2)) + ); + + writer + .progress + .messages + .store(MESSAGE_LIMIT - 1, Ordering::Release); + writer.progress.bytes.store(BYTE_LIMIT, Ordering::Release); + writer.refresh_flag(now); + assert!(writer.deadline(Duration::ZERO).is_some()); + + writer + .progress + .bytes + .store(BYTE_LIMIT - 1, Ordering::Release); + writer.refresh_flag(now); + assert_eq!(writer.deadline(Duration::ZERO), None); +} + +#[test] +fn persistent_flag_times_out_at_configured_duration() { + let started = Instant::now(); + let mut writer = worker(MESSAGE_LIMIT, 0, Some(started)); + assert!(!writer.timed_out( + started + Duration::from_millis(1999), + Duration::from_secs(2) + )); + assert!(writer.timed_out(started + Duration::from_secs(2), Duration::from_secs(2))); +} diff --git a/src/config.rs b/src/config.rs index a59016f..5587172 100644 --- a/src/config.rs +++ b/src/config.rs @@ -50,6 +50,7 @@ pub struct DetectCliConfig { #[derive(Clone, Debug, Default, Eq, PartialEq)] pub struct DaemonCliConfig { pub idle_timeout: Option, + pub write_stall_timeout: Option, } #[derive(Debug)] @@ -135,6 +136,8 @@ struct DetectCliConfigFile { struct DaemonCliConfigFile { #[serde(default, deserialize_with = "deserialize_optional_timeout")] idle_timeout: Option, + #[serde(default, deserialize_with = "deserialize_optional_timeout")] + write_stall_timeout: Option, } pub fn default_config_root() -> Result { @@ -244,6 +247,10 @@ impl CliConfig { ); override_if_some(&mut self.detect.quiet, other.detect.quiet); override_if_some(&mut self.daemon.idle_timeout, other.daemon.idle_timeout); + override_if_some( + &mut self.daemon.write_stall_timeout, + other.daemon.write_stall_timeout, + ); override_if_some(&mut self.download_version, other.download_version); self.lsp_preferences.extend(other.lsp_preferences); } @@ -265,6 +272,7 @@ impl From for CliConfig { }, daemon: DaemonCliConfig { idle_timeout: file.daemon.idle_timeout, + write_stall_timeout: file.daemon.write_stall_timeout, }, lsp_preferences: file.lsp, } diff --git a/src/config_tests.rs b/src/config_tests.rs index bc2df0b..d8b37c7 100644 --- a/src/config_tests.rs +++ b/src/config_tests.rs @@ -174,6 +174,7 @@ fn loads_layered_cli_config_with_user_overrides() { " quiet: true\n", "daemon:\n", " idle-timeout: 5\n", + " write-stall-timeout: 2.5\n", "lsp:\n", " cpp:\n", " - clangd\n", @@ -189,6 +190,7 @@ fn loads_layered_cli_config_with_user_overrides() { "limit: 50\n", "daemon:\n", " idle-timeout: 10\n", + " write-stall-timeout: 3\n", "lsp:\n", " python:\n", " - ty\n", @@ -210,6 +212,10 @@ fn loads_layered_cli_config_with_user_overrides() { config.daemon.idle_timeout, Some(std::time::Duration::from_secs(10)) ); + assert_eq!( + config.daemon.write_stall_timeout, + Some(std::time::Duration::from_secs(3)) + ); assert_eq!( config.lsp_preferences, BTreeMap::from([ diff --git a/src/lsp/client.rs b/src/lsp/client.rs index 5d10da6..5160881 100644 --- a/src/lsp/client.rs +++ b/src/lsp/client.rs @@ -27,9 +27,13 @@ mod requests; mod rpc; mod window; +#[cfg(test)] +mod test_support; #[cfg(test)] mod tests; #[cfg(test)] +mod tests_initialization; +#[cfg(test)] mod tests_initialize_stderr; #[cfg(test)] mod tests_logging; diff --git a/src/lsp/client/requests.rs b/src/lsp/client/requests.rs index a40f3cc..624cd15 100644 --- a/src/lsp/client/requests.rs +++ b/src/lsp/client/requests.rs @@ -1,4 +1,4 @@ -use super::{IncomingMessage, LspClient, request_id}; +use super::LspClient; use crate::error::{Error, Result, error_fn}; use crate::lsp::{InitializeResponse, parse_lsp_uri}; use lsp_types::notification::{DidOpenTextDocument, Initialized}; @@ -18,8 +18,6 @@ use lsp_types::{ }; use serde_json::{Value, json}; use std::path::Path; -use std::sync::mpsc::RecvTimeoutError; -use std::time::Duration; impl LspClient { pub fn open_document(&mut self, path: &Path, uri: &str) -> Result<()> { @@ -101,34 +99,10 @@ impl LspClient { "failed to decode initialize response" ))?; self.send_notification::(&InitializedParams {})?; - self.drain_pending_server_requests_after_initialize()?; + self.drain_pending_server_requests()?; Ok(response) } - fn drain_pending_server_requests_after_initialize(&mut self) -> Result<()> { - const INITIALIZE_SERVER_REQUEST_GRACE: Duration = Duration::from_millis(10); - - // After `initialized`, some servers immediately send client requests. - // Wait briefly for the first one so it is handled before the next client request. - match self.recv_message(self.timeout.min(INITIALIZE_SERVER_REQUEST_GRACE)) { - Ok(IncomingMessage::Message(message)) => { - if let Some(request_id) = request_id(&message) { - self.handle_server_request(&request_id, &message)?; - } else if !self.handle_server_notification(&message)? { - self.pending_messages - .push_back(IncomingMessage::Message(message)); - } - } - Ok(message @ (IncomingMessage::EndOfStream | IncomingMessage::Error(_))) => { - self.pending_messages.push_back(message); - return Ok(()); - } - Err(RecvTimeoutError::Timeout | RecvTimeoutError::Disconnected) => return Ok(()), - } - - self.drain_pending_server_requests() - } - pub fn workspace_symbol(&mut self, pattern: &str) -> Result { let params = WorkspaceSymbolParams { query: pattern.to_string(), diff --git a/src/lsp/client/test_support.rs b/src/lsp/client/test_support.rs new file mode 100644 index 0000000..5b91a3f --- /dev/null +++ b/src/lsp/client/test_support.rs @@ -0,0 +1,24 @@ +use crate::lsp::transport::read_message; +use serde_json::Value; +use std::io::{BufReader, Read}; + +pub(super) fn read_existing_message( + reader: &mut BufReader, + parse_context: &str, + missing_context: &str, +) -> Value { + read_message(reader) + .expect(parse_context) + .expect(missing_context) +} + +pub(super) fn expect_method(message: &Value, expected: &str) { + assert_eq!( + message.get("method").and_then(Value::as_str), + Some(expected) + ); +} + +pub(super) fn expect_id(message: &Value, expected: &str) { + assert_eq!(message.get("id").and_then(Value::as_str), Some(expected)); +} diff --git a/src/lsp/client/tests.rs b/src/lsp/client/tests.rs index df126cf..311ad6e 100644 --- a/src/lsp/client/tests.rs +++ b/src/lsp/client/tests.rs @@ -1,3 +1,5 @@ +#[cfg(unix)] +use super::test_support::{expect_method, read_existing_message}; use super::{ClientTransport, LspClient, format_spawn_error}; #[cfg(unix)] use crate::lsp::transport::{read_message, write_message}; @@ -7,8 +9,6 @@ use crate::test_support::{ subprocess_helper_env, with_env_vars, }; #[cfg(unix)] -use serde_json::Value; -#[cfg(unix)] use serde_json::json; use std::fs; use std::time::Duration; @@ -16,9 +16,9 @@ use std::time::Duration; #[cfg(unix)] use std::fs::File; #[cfg(unix)] -use std::io::Write; +use std::io::BufReader; #[cfg(unix)] -use std::io::{BufReader, Read}; +use std::io::Write; #[cfg(unix)] use std::os::fd::AsRawFd; #[cfg(unix)] @@ -38,33 +38,6 @@ fn formats_missing_binary_error() { ); } -#[cfg(unix)] -fn read_existing_message( - reader: &mut BufReader, - parse_context: &str, - missing_context: &str, -) -> Value { - read_message(reader) - .expect(parse_context) - .expect(missing_context) -} - -#[cfg(unix)] -fn expect_method(message: &Value, expected: &str) { - assert_eq!( - message.get("method").and_then(serde_json::Value::as_str), - Some(expected) - ); -} - -#[cfg(unix)] -fn expect_id(message: &Value, expected: &str) { - assert_eq!( - message.get("id").and_then(serde_json::Value::as_str), - Some(expected) - ); -} - #[cfg(unix)] fn write_publish_diagnostics( writer: &mut W, @@ -138,225 +111,6 @@ fn keeps_server_stderr_visible_with_debug() { assert!(captured_server_stderr(true).contains("server stderr\n")); } -#[cfg(unix)] -#[test] -fn initialize_replies_to_queued_server_requests_before_next_request() { - let dir = TestDir::new("client-init-queue"); - let socket_path = dir.path().join("server.sock"); - let listener = UnixListener::bind(&socket_path).expect("socket should bind"); - - let server = thread::spawn(move || { - let (stream, _) = listener.accept().expect("client should connect"); - let reader_stream = stream.try_clone().expect("stream should clone"); - let mut reader = BufReader::new(reader_stream); - let mut writer = stream; - - let initialize = read_existing_message( - &mut reader, - "initialize should parse", - "initialize should exist", - ); - assert_eq!( - initialize.get("method").and_then(serde_json::Value::as_str), - Some("initialize") - ); - write_message( - &mut writer, - &json!({ - "jsonrpc": "2.0", - "id": initialize.get("id").cloned().expect("initialize id should exist"), - "result": { - "capabilities": { - "documentSymbolProvider": true, - } - }, - }), - ) - .expect("initialize response should write"); - write_message( - &mut writer, - &json!({ - "jsonrpc": "2.0", - "id": "register-1", - "method": "client/registerCapability", - "params": { - "registrations": [{ - "id": "watcher", - "method": "workspace/didChangeWatchedFiles", - "registerOptions": { - "watchers": [{"globPattern": "**/*", "kind": 4}] - } - }] - } - }), - ) - .expect("registerCapability request should write"); - - let initialized = read_message(&mut reader) - .expect("initialized should parse") - .expect("initialized should exist"); - assert_eq!( - initialized - .get("method") - .and_then(serde_json::Value::as_str), - Some("initialized") - ); - - let register_response = read_message(&mut reader) - .expect("register response should parse") - .expect("register response should exist"); - assert_eq!( - register_response - .get("id") - .and_then(serde_json::Value::as_str), - Some("register-1") - ); - assert!(register_response.get("result").is_some()); - - let shutdown = read_message(&mut reader) - .expect("shutdown should parse") - .expect("shutdown should exist"); - assert_eq!( - shutdown.get("method").and_then(serde_json::Value::as_str), - Some("shutdown") - ); - write_message( - &mut writer, - &json!({ - "jsonrpc": "2.0", - "id": shutdown.get("id").cloned().expect("shutdown id should exist"), - "result": null, - }), - ) - .expect("shutdown response should write"); - - let exit = read_message(&mut reader) - .expect("exit should parse") - .expect("exit should exist"); - assert_eq!( - exit.get("method").and_then(serde_json::Value::as_str), - Some("exit") - ); - }); - - let mut client = - LspClient::connect_unix(&socket_path, false, Duration::from_secs(1)).expect("connect"); - client - .initialize("file:///workspace", "workspace", false) - .expect("initialize should succeed"); - client.shutdown().expect("shutdown should succeed"); - - server.join().expect("server thread should finish"); -} - -#[cfg(unix)] -#[test] -fn initialize_advertises_and_returns_workspace_folders() { - let dir = TestDir::new("client-init-workspace-folders"); - let socket_path = dir.path().join("server.sock"); - let listener = UnixListener::bind(&socket_path).expect("socket should bind"); - - let server = thread::spawn(move || { - let (stream, _) = listener.accept().expect("client should connect"); - let reader_stream = stream.try_clone().expect("stream should clone"); - let mut reader = BufReader::new(reader_stream); - let mut writer = stream; - - let initialize = read_message(&mut reader) - .expect("initialize should parse") - .expect("initialize should exist"); - let params = initialize - .get("params") - .cloned() - .expect("initialize params should exist"); - assert_eq!( - params - .get("capabilities") - .and_then(|value| value.get("workspace")) - .and_then(|value| value.get("workspaceFolders")) - .and_then(serde_json::Value::as_bool), - Some(true) - ); - let workspace_folders = params - .get("workspaceFolders") - .cloned() - .expect("workspaceFolders should exist"); - - write_message( - &mut writer, - &json!({ - "jsonrpc": "2.0", - "id": initialize.get("id").cloned().expect("initialize id should exist"), - "result": { - "capabilities": { - "documentSymbolProvider": true, - } - }, - }), - ) - .expect("initialize response should write"); - write_message( - &mut writer, - &json!({ - "jsonrpc": "2.0", - "id": "folders-1", - "method": "workspace/workspaceFolders", - }), - ) - .expect("workspaceFolders request should write"); - - expect_method( - &read_existing_message( - &mut reader, - "initialized should parse", - "initialized should exist", - ), - "initialized", - ); - - let workspace_folders_response = read_existing_message( - &mut reader, - "workspaceFolders response should parse", - "workspaceFolders response should exist", - ); - expect_id(&workspace_folders_response, "folders-1"); - assert_eq!( - workspace_folders_response.get("result").cloned(), - Some(workspace_folders) - ); - - let shutdown = read_existing_message( - &mut reader, - "shutdown should parse", - "shutdown should exist", - ); - expect_method(&shutdown, "shutdown"); - write_message( - &mut writer, - &json!({ - "jsonrpc": "2.0", - "id": shutdown.get("id").cloned().expect("shutdown id should exist"), - "result": null, - }), - ) - .expect("shutdown response should write"); - - expect_method( - &read_existing_message(&mut reader, "exit should parse", "exit should exist"), - "exit", - ); - }); - - let mut client = - LspClient::connect_unix(&socket_path, false, Duration::from_secs(1)).expect("connect"); - client - .initialize("file:///workspace", "workspace", false) - .expect("initialize should succeed"); - client.shutdown().expect("shutdown should succeed"); - - server.join().expect("server thread should finish"); -} - #[cfg(unix)] #[test] fn collects_latest_publish_diagnostics_notifications() { diff --git a/src/lsp/client/tests_initialization.rs b/src/lsp/client/tests_initialization.rs new file mode 100644 index 0000000..d2a7d3a --- /dev/null +++ b/src/lsp/client/tests_initialization.rs @@ -0,0 +1,216 @@ +use super::test_support::{expect_id, expect_method, read_existing_message}; +use super::{IncomingMessage, LspClient}; +use crate::lsp::transport::write_message; +use crate::test_support::TestDir; +use serde_json::{Value, json}; +use std::io::BufReader; +use std::os::unix::net::{UnixListener, UnixStream}; +use std::path::PathBuf; +use std::thread::{self, JoinHandle}; +use std::time::Duration; + +struct SocketFixture { + _dir: TestDir, + socket_path: PathBuf, + server: JoinHandle<()>, +} + +impl SocketFixture { + fn spawn(name: &str, run_server: impl FnOnce(Peer) + Send + 'static) -> Self { + let dir = TestDir::new(name); + let socket_path = dir.path().join("server.sock"); + let listener = UnixListener::bind(&socket_path).expect("socket should bind"); + let server = thread::spawn(move || { + let (stream, _) = listener.accept().expect("client should connect"); + run_server(Peer::new(stream)); + }); + Self { + _dir: dir, + socket_path, + server, + } + } + + fn connect(&self) -> LspClient { + LspClient::connect_unix(&self.socket_path, false, Duration::from_secs(1)) + .expect("client should connect") + } + + fn finish(self) { + self.server.join().expect("server thread should finish"); + } +} + +struct Peer { + reader: BufReader, + writer: UnixStream, +} + +impl Peer { + fn new(stream: UnixStream) -> Self { + let reader = BufReader::new(stream.try_clone().expect("stream should clone")); + Self { + reader, + writer: stream, + } + } + + fn read(&mut self, context: &str) -> Value { + read_existing_message( + &mut self.reader, + &format!("{context} should parse"), + &format!("{context} should exist"), + ) + } + + fn initialize(&mut self) -> Value { + let request = self.read("initialize"); + expect_method(&request, "initialize"); + self.respond(&request, &json!({ "capabilities": {} }), "initialize"); + request + } + + fn expect_initialized(&mut self) { + expect_method(&self.read("initialized"), "initialized"); + } + + fn respond(&mut self, request: &Value, result: &Value, context: &str) { + write_message( + &mut self.writer, + &json!({ + "jsonrpc": "2.0", + "id": request.get("id").cloned().expect("request id should exist"), + "result": result, + }), + ) + .unwrap_or_else(|error| panic!("{context} response should write: {error}")); + } + + fn send(&mut self, message: &Value, context: &str) { + write_message(&mut self.writer, message) + .unwrap_or_else(|error| panic!("{context} should write: {error}")); + } + + fn finish_shutdown(&mut self) { + let shutdown = self.read("shutdown"); + expect_method(&shutdown, "shutdown"); + self.respond(&shutdown, &Value::Null, "shutdown"); + expect_method(&self.read("exit"), "exit"); + } +} + +fn initialize_client(client: &mut LspClient) { + client + .initialize("file:///workspace", "workspace", false) + .expect("initialize should succeed"); +} + +#[test] +fn queued_server_request_is_answered_before_next_client_request() { + let fixture = SocketFixture::spawn("client-init-queue", |mut peer| { + peer.initialize(); + peer.expect_initialized(); + + let registration_response = peer.read("registration response"); + expect_id(®istration_response, "register-1"); + assert_eq!(registration_response.get("result"), Some(&Value::Null)); + + let symbols = peer.read("workspace symbol request"); + expect_method(&symbols, "workspace/symbol"); + peer.respond(&symbols, &json!([]), "workspace symbol"); + peer.finish_shutdown(); + }); + let mut client = fixture.connect(); + initialize_client(&mut client); + client + .pending_messages + .push_back(IncomingMessage::Message(json!({ + "jsonrpc": "2.0", + "id": "register-1", + "method": "client/registerCapability", + "params": { "registrations": [] }, + }))); + + assert_eq!( + client + .workspace_symbol("needle") + .expect("workspace symbol should succeed"), + json!([]) + ); + client.shutdown().expect("shutdown should succeed"); + fixture.finish(); +} + +#[test] +fn server_request_is_answered_while_client_request_is_outstanding() { + let fixture = SocketFixture::spawn("client-init-in-flight", |mut peer| { + peer.initialize(); + peer.expect_initialized(); + + let symbols = peer.read("workspace symbol request"); + expect_method(&symbols, "workspace/symbol"); + peer.send( + &json!({ + "jsonrpc": "2.0", + "id": "configuration-1", + "method": "workspace/configuration", + "params": { "items": [] }, + }), + "configuration request", + ); + let configuration_response = peer.read("configuration response"); + expect_id(&configuration_response, "configuration-1"); + assert_eq!(configuration_response.get("result"), Some(&json!([]))); + peer.respond(&symbols, &json!([]), "workspace symbol"); + peer.finish_shutdown(); + }); + let mut client = fixture.connect(); + initialize_client(&mut client); + + assert_eq!( + client + .workspace_symbol("needle") + .expect("workspace symbol should succeed"), + json!([]) + ); + client.shutdown().expect("shutdown should succeed"); + fixture.finish(); +} + +#[test] +fn initialize_advertises_and_returns_workspace_folders() { + let fixture = SocketFixture::spawn("client-init-workspace-folders", |mut peer| { + let initialize = peer.initialize(); + let params = initialize + .get("params") + .expect("initialize params should exist"); + assert_eq!( + params + .pointer("/capabilities/workspace/workspaceFolders") + .and_then(Value::as_bool), + Some(true) + ); + let workspace_folders = params + .get("workspaceFolders") + .cloned() + .expect("workspaceFolders should exist"); + peer.expect_initialized(); + + let folders_response = peer.read("workspace folders response"); + expect_id(&folders_response, "folders-1"); + assert_eq!(folders_response.get("result"), Some(&workspace_folders)); + peer.finish_shutdown(); + }); + let mut client = fixture.connect(); + initialize_client(&mut client); + client + .pending_messages + .push_back(IncomingMessage::Message(json!({ + "jsonrpc": "2.0", + "id": "folders-1", + "method": "workspace/workspaceFolders", + }))); + + client.shutdown().expect("shutdown should succeed"); + fixture.finish(); +} diff --git a/src/lsp/transport.rs b/src/lsp/transport.rs index 5729233..b45795b 100644 --- a/src/lsp/transport.rs +++ b/src/lsp/transport.rs @@ -58,15 +58,21 @@ pub(crate) fn write_message(writer: &mut W, message: &Value) -> Result<()> where W: Write, { + let frame = frame_message(message)?; + writer + .write_all(&frame) + .and_then(|()| writer.flush()) + .map_err(error_fn!(Error::lsp, "failed to write JSON-RPC message")) +} + +pub(crate) fn frame_message(message: &Value) -> Result> { let body = serde_json::to_vec(message).map_err(error_fn!( Error::lsp, "failed to serialize JSON-RPC message" ))?; - writer - .write_all(format!("Content-Length: {}\r\n\r\n", body.len()).as_bytes()) - .and_then(|()| writer.write_all(&body)) - .and_then(|()| writer.flush()) - .map_err(error_fn!(Error::lsp, "failed to write JSON-RPC message")) + let mut frame = format!("Content-Length: {}\r\n\r\n", body.len()).into_bytes(); + frame.extend_from_slice(&body); + Ok(frame) } pub(crate) fn serialize_debug_message(message: &Value) -> String { diff --git a/src/server_stderr.rs b/src/server_stderr.rs index 8a3630a..483e542 100644 --- a/src/server_stderr.rs +++ b/src/server_stderr.rs @@ -18,10 +18,47 @@ struct StderrState { finished: bool, } +pub(crate) trait StderrSink: Clone + Send + 'static { + fn write_chunk(&self, chunk: &[u8]); + fn write_line(&self, line: String); + fn write_error(&self, error: String); +} + +#[derive(Clone, Copy)] +struct DirectStderrSink { + mirror_to_stderr: bool, +} + +impl StderrSink for DirectStderrSink { + fn write_chunk(&self, chunk: &[u8]) { + if self.mirror_to_stderr { + let mut stderr = std::io::stderr().lock(); + let _ = stderr.write_all(chunk); + let _ = stderr.flush(); + } + } + + fn write_line(&self, line: String) { + log_lsp_server_stderr_line(&line); + } + + fn write_error(&self, error: String) { + log_unexpected_error(&error); + } +} + impl CapturedStderr { - pub(crate) fn spawn(mut reader: R, mirror_to_stderr: bool) -> Self + pub(crate) fn spawn(reader: R, mirror_to_stderr: bool) -> Self where R: Read + Send + 'static, + { + Self::spawn_with(reader, DirectStderrSink { mirror_to_stderr }) + } + + pub(crate) fn spawn_with(mut reader: R, sink: S) -> Self + where + R: Read + Send + 'static, + S: StderrSink, { let state = Arc::new(( Mutex::new(StderrState { @@ -37,15 +74,15 @@ impl CapturedStderr { loop { match reader.read(&mut buffer) { Ok(0) => break, - Ok(read) => append_stderr(&thread_state, &buffer[..read], mirror_to_stderr), + Ok(read) => append_stderr(&thread_state, &buffer[..read], &sink), Err(error) if error.kind() == std::io::ErrorKind::Interrupted => {} Err(error) => { - log_unexpected_error(&format!("failed to read LSP server stderr: {error}")); + sink.write_error(format!("failed to read LSP server stderr: {error}")); break; } } } - finish_stderr(&thread_state); + finish_stderr(&thread_state, &sink); }); Self { state } @@ -61,6 +98,16 @@ impl CapturedStderr { state = result.0; } + Self::format_summary(&state) + } + + pub(crate) fn summary_now(&self) -> Option { + let (lock, _) = &*self.state; + let state = lock.lock().unwrap_or_else(PoisonError::into_inner); + Self::format_summary(&state) + } + + fn format_summary(state: &StderrState) -> Option { let stderr = String::from_utf8_lossy(&state.tail.iter().copied().collect::>()) .split_whitespace() .collect::>() @@ -73,12 +120,12 @@ impl CapturedStderr { } } -fn append_stderr(state: &Arc<(Mutex, Condvar)>, chunk: &[u8], mirror_to_stderr: bool) { - if mirror_to_stderr { - let mut stderr = std::io::stderr().lock(); - let _write_result = stderr.write_all(chunk); - let _flush_result = stderr.flush(); - } +fn append_stderr( + state: &Arc<(Mutex, Condvar)>, + chunk: &[u8], + sink: &S, +) { + sink.write_chunk(chunk); let (lock, _) = &**state; let mut state = lock.lock().unwrap_or_else(PoisonError::into_inner); @@ -99,11 +146,11 @@ fn append_stderr(state: &Arc<(Mutex, Condvar)>, chunk: &[u8], mirro drop(state); for line in completed_lines { - log_lsp_server_stderr_line(&line); + sink.write_line(line); } } -fn finish_stderr(state: &Arc<(Mutex, Condvar)>) { +fn finish_stderr(state: &Arc<(Mutex, Condvar)>, sink: &S) { let (lock, ready) = &**state; let mut state = lock.lock().unwrap_or_else(PoisonError::into_inner); let final_line = if state.partial_line.is_empty() { @@ -116,7 +163,7 @@ fn finish_stderr(state: &Arc<(Mutex, Condvar)>) { drop(state); if let Some(line) = final_line { - log_lsp_server_stderr_line(&line); + sink.write_line(line); } }