From a7c44f23781d70390180e5989f6b3a9513e1e8e9 Mon Sep 17 00:00:00 2001 From: Vasily Kulikov Date: Sat, 5 Sep 2026 16:16:34 +0300 Subject: [PATCH 1/7] Replace daemon polling with bounded event delivery --- GOTCHAS.md | 4 + playground/README.md | 22 ++ scripts/daemon_latency.py | 252 +++++++++++++ src/commands/daemon.rs | 527 +++++++-------------------- src/commands/daemon/events.rs | 284 +++++++++++++++ src/commands/daemon/events/tests.rs | 242 ++++++++++++ src/commands/daemon/forwarding.rs | 301 +++++++++++++++ src/commands/daemon/process.rs | 71 ++-- src/commands/daemon/session_tests.rs | 305 ++++++++++++++++ src/commands/daemon/tests.rs | 9 +- 10 files changed, 1584 insertions(+), 433 deletions(-) create mode 100644 scripts/daemon_latency.py create mode 100644 src/commands/daemon/events.rs create mode 100644 src/commands/daemon/events/tests.rs create mode 100644 src/commands/daemon/forwarding.rs create mode 100644 src/commands/daemon/session_tests.rs diff --git a/GOTCHAS.md b/GOTCHAS.md index d794b73..fe2ae65 100644 --- a/GOTCHAS.md +++ b/GOTCHAS.md @@ -31,6 +31,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/playground/README.md b/playground/README.md index 95fe426..22f2e0c 100644 --- a/playground/README.md +++ b/playground/README.md @@ -31,3 +31,25 @@ cargo run -- stop playground/python 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. 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, and stop with an active client. + +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, and handshakes, writes, logging, and upstream shutdown still run +synchronously. These measurements describe an immediate-reply fixture, not a +latency guarantee for real language servers or stalled peers. diff --git a/scripts/daemon_latency.py b/scripts/daemon_latency.py new file mode 100644 index 0000000..90369fc --- /dev/null +++ b/scripts/daemon_latency.py @@ -0,0 +1,252 @@ +#!/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 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(): + 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": + 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) + + +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): + with tempfile.TemporaryDirectory(prefix="lsp-latency-") as temporary: + root = Path(temporary) + 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, "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", "--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) + 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) + # Stop through a secondary connection while a client remains active. + subprocess.run([str(binary), "stop", str(workspace), "--lsp", "latency-fixture"], + env=env, capture_output=True, timeout=15, check=True) + 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("--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)}), flush=True) + + +if __name__ == "__main__": + main() diff --git a/src/commands/daemon.rs b/src/commands/daemon.rs index e203b7e..10c9d2a 100644 --- a/src/commands/daemon.rs +++ b/src/commands/daemon.rs @@ -2,37 +2,38 @@ 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::mpsc::RecvTimeoutError; use std::thread; use std::time::{Duration, Instant}; +mod events; +mod forwarding; mod process; mod protocol; +#[cfg(test)] +mod session_tests; #[cfg(test)] mod tests; +use events::{AcceptWorker, Event, EventQueue, ReaderWorker, Source}; use process::{bind_listener, launch_background, resolve_target, run_background}; 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, handle_busy_connection, + read_control_message, request_id_from_key, response_id, stop_request, stop_request_id, }; const BACKGROUND_ENV: &str = "LSP_CLI_DAEMON_BACKGROUND"; @@ -169,7 +170,9 @@ struct DaemonTarget { } struct Daemon { - listener: UnixListener, + accept_worker: Option, + events: EventQueue, + socket_owned: bool, target: DaemonTarget, debug: bool, idle_timeout: Duration, @@ -184,7 +187,8 @@ struct UpstreamServer { child: Child, stdin: ChildStdin, stderr: CapturedStderr, - messages: Receiver, + generation: u64, + reader: ReaderWorker, initialize_fingerprint: Option, initialize_result: Option, restart_required: bool, @@ -193,7 +197,8 @@ struct UpstreamServer { struct ClientSession { writer: UnixStream, - messages: Receiver, + generation: u64, + reader: ReaderWorker, phase: ClientPhase, wants_background_work: bool, forwarded_client_requests: BTreeSet, @@ -212,415 +217,124 @@ enum ClientPhase { impl Daemon { fn new(target: DaemonTarget, debug: bool, idle_timeout: Duration) -> Result { 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, idle_timeout, - upstream: Some(upstream), + upstream: None, active_client: None, orphaned_client_requests: BTreeSet::new(), idle_since: Instant::now(), stop_requested: false, - }) + }; + daemon.upstream = Some(UpstreamServer::spawn( + &daemon.target, + debug, + &mut daemon.events, + )?); + 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 { + if self.stop_requested || self.idle_expired() { return self.stop(); } - - if self.active_client.is_none() && self.idle_since.elapsed() >= self.idle_timeout { - return self.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; - } - continue; - } - - self.active_client = Some(ClientSession::new(stream)?); - } - 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() - ))); - } - } - } - } - - 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(()), + let timeout = if self.active_client.is_none() { + Some(self.idle_timeout.saturating_sub(self.idle_since.elapsed())) + } else { + None }; - - 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 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(()); + match self.events.receive(timeout) { + Ok(event) => { + if self.idle_expired() { + // 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(()); + return self.stop(); } - }, - None => return Ok(()), - }; - - match event { - ReaderEvent::Message(message) => self.handle_client_message(&message)?, - ReaderEvent::EndOfStream => { - self.disconnect_client()?; - return Ok(()); + let result = self.dispatch(event.event); + // Release admission even when dispatch fails; cancellation handles retired readers. + let _ = event.acknowledge.send(()); + result?; } - ReaderEvent::Error(error) => { - self.disconnect_client()?; - return Err(Error::lsp(format!( - "failed to read daemon client message: {error}" - ))); - } - } - } - } - - 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)?; - } - 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", + Err(RecvTimeoutError::Timeout) => {} + Err(RecvTimeoutError::Disconnected) => { + return Err(Error::unexpected( + "daemon event workers stopped unexpectedly", )); } - - return Ok(()); } - Some(ClientPhase::WaitingForInitialized { - forward_to_upstream, - }) => { - if method == Some("initialized") { - if forward_to_upstream { - self.write_upstream_message(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::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 idle_expired(&self) -> bool { + self.active_client.is_none() && self.idle_since.elapsed() >= self.idle_timeout } - 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; + fn dispatch(&mut self, event: Event) -> Result<()> { + match event { + Event::Accepted(stream) => { + if self.active_client.is_some() { + if handle_busy_connection(stream, self.debug)? { + self.stop_requested = true; + } } else { - upstream.initialize_result = message.get("result").cloned(); + self.active_client = Some(ClientSession::new(stream, &mut self.events)?); } } - - if forwarded_client_request { - return self.write_client_response(message); + Event::AcceptError(error) => { + return Err(Error::unexpected(format!( + "failed to accept client on {}: {error}", + self.target.socket_path.display() + ))); } - - 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::Upstream(generation), event) + if self + .upstream + .as_ref() + .is_some_and(|upstream| upstream.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()); + match event { + ReaderEvent::Message(message) => self.handle_upstream_message(&message)?, + ReaderEvent::EndOfStream => self.upstream_died(), + 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)); + } } } - 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); + Event::Reader(Source::Client(generation), event) + if self + .active_client + .as_ref() + .is_some_and(|client| client.generation == generation) => + { + 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}" + ))); + } } } - _ => {} + // 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 +342,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")?), @@ -661,7 +377,11 @@ impl Daemon { .is_some_and(|upstream| upstream.restart_required) { self.shutdown_upstream()?; - self.upstream = Some(UpstreamServer::spawn(&self.target, self.debug)?); + self.upstream = Some(UpstreamServer::spawn( + &self.target, + self.debug, + &mut self.events, + )?); } self.idle_since = Instant::now(); @@ -690,28 +410,36 @@ impl Daemon { fn shutdown_upstream(&mut self) -> Result<()> { if let Some(mut upstream) = self.upstream.take() { - upstream.shutdown(self.debug)?; + upstream.shutdown(self.debug, &mut self.events)?; } self.orphaned_client_requests.clear(); Ok(()) } fn stop(&mut self) -> Result<()> { + self.stop_requested = true; + // Stop accepting before unlinking the socket, so the wakeup still reaches our listener. + self.accept_worker.take(); self.disconnect_client()?; self.shutdown_upstream()?; 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() - ))), + )))?, } + Ok(()) } fn restart_upstream(&mut self) -> Result<()> { self.shutdown_upstream()?; - self.upstream = Some(UpstreamServer::spawn(&self.target, self.debug)?); + self.upstream = Some(UpstreamServer::spawn( + &self.target, + self.debug, + &mut self.events, + )?); Ok(()) } @@ -732,3 +460,16 @@ impl Daemon { self.idle_since = Instant::now(); } } + +impl Drop for Daemon { + fn drop(&mut self) { + // Error exits must also wake acceptance before removing its socket path. + self.accept_worker.take(); + self.active_client.take(); + self.upstream.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); + } + } +} diff --git a/src/commands/daemon/events.rs b/src/commands/daemon/events.rs new file mode 100644 index 0000000..ff491ca --- /dev/null +++ b/src/commands/daemon/events.rs @@ -0,0 +1,284 @@ +use super::protocol::ReaderEvent; +use crate::error::{Error, Result}; +use crate::lsp::transport::read_message; +use crate::system_log::log_unexpected_error; +use std::collections::VecDeque; +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(UnixStream), + AcceptError(String), + Reader(Source, ReaderEvent), +} + +pub(super) struct Delivery { + pub(super) event: Event, + pub(super) acknowledge: Sender<()>, +} + +pub(super) struct EventQueue { + sender: Sender, + receiver: Receiver, + deferred: VecDeque, + generation: u64, +} + +impl EventQueue { + pub(super) fn new() -> Self { + let (sender, receiver) = mpsc::channel(); + Self { + sender, + receiver, + deferred: VecDeque::new(), + 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 receive( + &mut self, + timeout: Option, + ) -> std::result::Result { + if let Some(event) = self.deferred.pop_front() { + return Ok(event); + } + match timeout { + Some(timeout) => self.receiver.recv_timeout(timeout), + None => self + .receiver + .recv() + .map_err(|_| RecvTimeoutError::Disconnected), + } + } + + pub(super) fn receive_upstream( + &mut self, + generation: u64, + timeout: Duration, + ) -> std::result::Result { + let started = Instant::now(); + loop { + let remaining = timeout + .checked_sub(started.elapsed()) + .ok_or(RecvTimeoutError::Timeout)?; + let delivery = self.receiver.recv_timeout(remaining)?; + match delivery.event { + Event::Reader(Source::Upstream(id), event) if id == generation => { + let _ = delivery.acknowledge.send(()); + return Ok(event); + } + event => { + // Withhold admission while shutdown is synchronous. At most one event per + // other producer can be deferred, and normal dispatch retains their order. + self.deferred.push_back(Delivery { + event, + acknowledge: delivery.acknowledge, + }); + } + } + } + } +} + +struct Admission { + cancelled: Arc, + acknowledge: Sender<()>, + replies: Receiver<()>, + events: Sender, +} + +impl Admission { + 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 { + fn admission(events: &EventQueue) -> (Self, 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: events.sender.clone(), + }; + ( + Self { + cancelled, + acknowledge, + socket: None, + thread: None, + }, + admission, + ) + } + + pub(super) fn spawn( + reader: R, + source: Source, + events: &EventQueue, + ) -> Result { + let (mut worker, admission) = Self::admission(events); + worker.thread = Some( + thread::Builder::new() + .name("daemon-reader".into()) + .spawn(move || { + let mut reader = BufReader::new(reader); + while !admission.cancelled.load(Ordering::Acquire) { + let event = match read_message(&mut reader) { + Ok(Some(message)) => ReaderEvent::Message(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) + } + + pub(super) fn socket(socket: UnixStream, source: Source, events: &EventQueue) -> Result { + let reader = socket.try_clone().map_err(|error| { + Error::unexpected(format!("failed to clone daemon client socket: {error}")) + })?; + let mut worker = Self::spawn(reader, 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), + 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..a3456c9 --- /dev/null +++ b/src/commands/daemon/events/tests.rs @@ -0,0 +1,242 @@ +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"); + 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 shutdown_defers_other_sources_without_releasing_admission() { + let client = Source::Client(1); + let upstream = Source::Upstream(2); + let retired = Source::Upstream(0); + let mut fixture = Fixture::new(&[client, upstream, retired]); + fixture.send(0, &json!("first")); + // Synchronize publication before queuing the next source, retaining FIFO order. + let first = fixture.receive(); + fixture.send(2, &json!("stale")); + let stale = fixture.receive(); + fixture + .events + .sender + .send(first) + .expect("restore first delivery"); + fixture + .events + .sender + .send(stale) + .expect("restore stale delivery"); + assert!(matches!( + fixture + .events + .receive_upstream(2, Duration::from_millis(20)), + Err(RecvTimeoutError::Timeout) + )); + assert_eq!(fixture.events.deferred.len(), 2); + fixture.send(0, &json!("second")); + fixture.send(1, &json!({"id": "shutdown", "result": null})); + assert!(matches!( + fixture.events.receive_upstream(2, TIMEOUT), + Ok(ReaderEvent::Message(_)) + )); + assert!(matches!( + fixture.events.receiver.try_recv(), + Err(mpsc::TryRecvError::Empty) + )); + assert_eq!(message(fixture.receive(), client), json!("first")); + assert_eq!(message(fixture.receive(), retired), json!("stale")); + assert_eq!(message(fixture.receive(), client), json!("second")); +} + +#[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..5ce74b4 --- /dev/null +++ b/src/commands/daemon/forwarding.rs @@ -0,0 +1,301 @@ +use super::protocol::{ + error_response, fingerprint_value, id_key, local_server_request_response, message_method, + normalize_initialize_params, request_id, respond_to_stop_request, response_id, stop_request_id, + success_response, update_background_work_tracker, wants_background_work, +}; +use super::{ClientPhase, Daemon, INVALID_REQUEST, SERVER_NOT_INITIALIZED}; +use crate::error::{Error, Result}; +use crate::lsp::transport::log_debug_message; +use crate::lsp::{STOP_METHOD, jsonrpc}; +use lsp_types::request::{Initialize, Request}; +use serde_json::Value; + +impl Daemon { + pub(super) 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)?; + } + 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_message(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::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(()) + } + + pub(super) 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() + { + 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); + } + } + _ => {} + } + } +} diff --git a/src/commands/daemon/process.rs b/src/commands/daemon/process.rs index b3b4746..747f57e 100644 --- a/src/commands/daemon/process.rs +++ b/src/commands/daemon/process.rs @@ -1,3 +1,4 @@ +use super::events::{EventQueue, ReaderWorker, Source}; use super::{ BACKGROUND_ENV, ClientPhase, ClientSession, Daemon, DaemonArgs, DaemonTarget, POLL_INTERVAL, ReaderEvent, UPSTREAM_SHUTDOWN_TIMEOUT, UpstreamServer, @@ -5,7 +6,6 @@ use super::{ 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::runtime_state::{daemon_socket_path, default_daemon_root}; use crate::server_stderr::CapturedStderr; @@ -21,7 +21,6 @@ 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; @@ -222,43 +221,18 @@ 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) -> 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(reader, Source::Client(generation), events)?; Ok(Self { writer: stream, - messages: spawn_reader(reader), + generation, + reader: worker, phase: ClientPhase::WaitingForInitialize, wants_background_work: false, forwarded_client_requests: BTreeSet::new(), @@ -269,7 +243,12 @@ impl ClientSession { } impl UpstreamServer { - pub(super) fn spawn(target: &DaemonTarget, debug: bool) -> Result { + pub(super) fn spawn( + target: &DaemonTarget, + debug: bool, + events: &mut EventQueue, + ) -> Result { + let generation = events.next_generation()?; let executable = std::env::current_exe().map_err(|error| { Error::unexpected(format!("failed to resolve lsp-cli executable: {error}")) })?; @@ -316,11 +295,20 @@ impl UpstreamServer { debug, ); + let reader = match ReaderWorker::spawn(stdout, Source::Upstream(generation), events) { + Ok(reader) => reader, + Err(error) => { + let _ = child.kill(); + let _ = child.wait(); + return Err(error); + } + }; Ok(Self { child, stdin, stderr, - messages: spawn_reader(stdout), + generation, + reader, initialize_fingerprint: None, initialize_result: None, restart_required: false, @@ -328,7 +316,7 @@ impl UpstreamServer { }) } - pub(super) fn shutdown(&mut self, debug: bool) -> Result<()> { + pub(super) fn shutdown(&mut self, debug: bool, events: &mut EventQueue) -> Result<()> { let _ = self.stderr.summary(); if self.initialize_fingerprint.is_some() { let shutdown_id = Value::String("lsp-cli/daemon-shutdown".to_string()); @@ -343,7 +331,7 @@ impl UpstreamServer { break; }; - match self.messages.recv_timeout(remaining) { + match events.receive_upstream(self.generation, 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()) @@ -404,6 +392,17 @@ impl UpstreamServer { } } +impl Drop for UpstreamServer { + fn drop(&mut self) { + // Error paths must cancel admission and reap the owned child as well as normal shutdown. + self.reader.cancel(); + if matches!(self.child.try_wait(), Ok(None)) { + let _ = self.child.kill(); + let _ = self.child.wait(); + } + } +} + unsafe fn setsid_wrapper() -> Result<()> { unsafe extern "C" { fn setsid() -> i32; diff --git a/src/commands/daemon/session_tests.rs b/src/commands/daemon/session_tests.rs new file mode 100644 index 0000000..d505142 --- /dev/null +++ b/src/commands/daemon/session_tests.rs @@ -0,0 +1,305 @@ +use super::*; +use crate::lsp::transport::read_message; +use crate::test_support::{TestDir, with_env_vars}; +use serde_json::json; +use std::io::BufReader; +use std::os::unix::net::UnixListener; +use std::process::{Command, Stdio}; +use std::sync::mpsc; + +const TIMEOUT: Duration = Duration::from_secs(3); + +struct Fixture { + daemon: Daemon, + peer: BufReader, + _dir: TestDir, +} + +impl Fixture { + fn new() -> Self { + let dir = TestDir::new("daemon-session"); + let target = tests::daemon_target(&dir); + let mut events = EventQueue::new(); + let upstream = fake_upstream(&mut events); + let (socket, peer) = UnixStream::pair().expect("client pair"); + peer.set_read_timeout(Some(TIMEOUT)).expect("read timeout"); + let client = ClientSession::new(socket, &mut events).expect("client"); + Self { + daemon: Daemon { + accept_worker: None, + events, + socket_owned: true, + target, + debug: false, + idle_timeout: TIMEOUT, + upstream: Some(upstream), + active_client: Some(client), + orphaned_client_requests: BTreeSet::new(), + idle_since: Instant::now(), + stop_requested: false, + }, + peer: BufReader::new(peer), + _dir: dir, + } + } + + fn send(&mut self, message: &Value) { + write_message(self.peer.get_mut(), message).expect("client write"); + } + + 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"); + } + + fn read(&mut self) -> Value { + read_message(&mut self.peer) + .expect("read response") + .expect("response") + } + + 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 { + self.step(); + } + let response = self.read(); + self.send(&json!({"jsonrpc": "2.0", "method": "initialized", "params": {}})); + self.step(); + response + } + + 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).expect("replacement client")); + self.peer = BufReader::new(peer); + } +} + +fn fake_upstream(events: &mut EventQueue) -> UpstreamServer { + let mut 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 stdin = child.stdin.take().expect("stdin"); + let stdout = child.stdout.take().expect("stdout"); + let stderr = CapturedStderr::spawn(child.stderr.take().expect("stderr"), false); + let generation = events.next_generation().expect("upstream generation"); + let reader = + ReaderWorker::spawn(stdout, Source::Upstream(generation), events).expect("upstream reader"); + UpstreamServer { + child, + stdin, + stderr, + generation, + reader, + initialize_fingerprint: None, + initialize_result: None, + restart_required: false, + background_work: BackgroundWorkTracker::default(), + } +} + +#[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.upstream = Some(fake_upstream(&mut fixture.daemon.events)); + 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"})), + 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_preserves_unrelated_client_message_for_dispatch() { + let mut fixture = Fixture::new(); + fixture.initialize(false); + fixture.send(&json!({"jsonrpc": "2.0", "method": "exit"})); + fixture + .daemon + .shutdown_upstream() + .expect("shutdown reply through event queue"); + assert!(fixture.daemon.upstream.is_none()); + fixture.step(); + assert!( + fixture.daemon.active_client.is_none(), + "queued client exit was preserved" + ); +} + +#[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.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/tests.rs b/src/commands/daemon/tests.rs index 66bf710..8aa1caf 100644 --- a/src/commands/daemon/tests.rs +++ b/src/commands/daemon/tests.rs @@ -1,7 +1,8 @@ -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; @@ -11,7 +12,7 @@ use std::io::BufReader; use std::os::unix::net::UnixListener; 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"); From bf964e02e886768883f108c3493e5a35d9ec004f Mon Sep 17 00:00:00 2001 From: Vasily Kulikov Date: Sat, 5 Sep 2026 16:41:42 +0300 Subject: [PATCH 2/7] Isolate daemon connection handshakes --- README.md | 5 + playground/README.md | 12 +- scripts/daemon_latency.py | 53 ++- src/commands/daemon.rs | 37 +- src/commands/daemon/connections.rs | 121 ++++++ src/commands/daemon/connections/tests.rs | 464 +++++++++++++++++++++ src/commands/daemon/events.rs | 37 +- src/commands/daemon/events/tests.rs | 4 +- src/commands/daemon/process.rs | 13 +- src/commands/daemon/protocol.rs | 34 +- src/commands/daemon/session_tests.rs | 26 +- src/commands/daemon/socket_reader.rs | 69 +++ src/commands/daemon/socket_reader/tests.rs | 94 +++++ src/commands/daemon/tests.rs | 20 - 14 files changed, 890 insertions(+), 99 deletions(-) create mode 100644 src/commands/daemon/connections.rs create mode 100644 src/commands/daemon/connections/tests.rs create mode 100644 src/commands/daemon/socket_reader.rs create mode 100644 src/commands/daemon/socket_reader/tests.rs diff --git a/README.md b/README.md index 7c9906d..85c4e5a 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 diff --git a/playground/README.md b/playground/README.md index 22f2e0c..e36e2af 100644 --- a/playground/README.md +++ b/playground/README.md @@ -40,16 +40,20 @@ python3 scripts/daemon_latency.py --binary target/debug/lsp-cli --samples 100 -- ``` Run this from the repository root. Add another `--binary /path/to/baseline/lsp-cli` -to compare builds. The script uses `playground/rust` with temporary server +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, and stop with an active client. +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, and handshakes, writes, logging, and upstream shutdown still run -synchronously. These measurements describe an immediate-reply fixture, not a +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 still run synchronously. These measurements describe an immediate-reply fixture, not a latency guarantee for real language servers or stalled peers. diff --git a/scripts/daemon_latency.py b/scripts/daemon_latency.py index 90369fc..8808f87 100644 --- a/scripts/daemon_latency.py +++ b/scripts/daemon_latency.py @@ -114,6 +114,44 @@ def connect(path): 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) @@ -136,7 +174,7 @@ def percentile(values, fraction): return results -def benchmark(binary, workspace, samples, pipeline): +def benchmark(binary, workspace, samples, pipeline, check_handshakes): with tempfile.TemporaryDirectory(prefix="lsp-latency-") as temporary: root = Path(temporary) data = root / "data" @@ -173,6 +211,8 @@ def benchmark(binary, workspace, samples, pipeline): with connect(path) as peer: assert peer.initialize(workspace) == pid, "warm upstream was not reused" measurements = report(peer, samples, pipeline) + if check_handshakes: + handshake_smoke(path, peer) peer.request("latency/register") peer.finish() time.sleep(.1) @@ -205,9 +245,10 @@ def benchmark(binary, workspace, samples, pipeline): time.sleep(.1) with connect(path) as peer: peer.initialize(workspace) - # Stop through a secondary connection while a client remains active. - subprocess.run([str(binary), "stop", str(workspace), "--lsp", "latency-fixture"], - env=env, capture_output=True, timeout=15, check=True) + # A silent connection must not delay a later stop control connection. + with raw_connection(path): + subprocess.run([str(binary), "stop", str(workspace), "--lsp", "latency-fixture"], + env=env, capture_output=True, timeout=15, check=True) assert not path.exists(), "daemon socket survived stop" return measurements except Exception: @@ -227,6 +268,8 @@ 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") @@ -245,7 +288,7 @@ def main(): 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)}), flush=True) + print(json.dumps({str(binary): benchmark(binary.resolve(), workspace, args.samples, args.pipeline, not args.skip_handshake_checks)}), flush=True) if __name__ == "__main__": diff --git a/src/commands/daemon.rs b/src/commands/daemon.rs index 10c9d2a..8d462ca 100644 --- a/src/commands/daemon.rs +++ b/src/commands/daemon.rs @@ -19,26 +19,28 @@ use std::sync::mpsc::RecvTimeoutError; use std::thread; use std::time::{Duration, Instant}; +mod connections; mod events; mod forwarding; mod process; mod protocol; +mod socket_reader; #[cfg(test)] mod session_tests; #[cfg(test)] mod tests; +use connections::PendingConnection; use events::{AcceptWorker, Event, EventQueue, ReaderWorker, Source}; use process::{bind_listener, launch_background, resolve_target, run_background}; use protocol::{ - BackgroundWorkTracker, ReaderEvent, error_response, handle_busy_connection, - read_control_message, request_id_from_key, response_id, stop_request, stop_request_id, + BackgroundWorkTracker, ReaderEvent, error_response, read_control_message, request_id_from_key, + response_id, stop_request, stop_request_id, }; 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); @@ -178,6 +180,7 @@ struct Daemon { idle_timeout: Duration, upstream: Option, active_client: Option, + pending_connections: BTreeMap, orphaned_client_requests: BTreeSet, idle_since: Instant, stop_requested: bool, @@ -226,6 +229,7 @@ impl Daemon { idle_timeout, upstream: None, active_client: None, + pending_connections: BTreeMap::new(), orphaned_client_requests: BTreeSet::new(), idle_since: Instant::now(), stop_requested: false, @@ -245,14 +249,11 @@ impl Daemon { fn serve(&mut self) -> Result<()> { loop { + self.expire_pending_connections(Instant::now()); if self.stop_requested || self.idle_expired() { return self.stop(); } - let timeout = if self.active_client.is_none() { - Some(self.idle_timeout.saturating_sub(self.idle_since.elapsed())) - } else { - None - }; + let timeout = self.next_event_timeout(Instant::now()); match self.events.receive(timeout) { Ok(event) => { if self.idle_expired() { @@ -281,15 +282,17 @@ impl Daemon { } 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) => { - if self.active_client.is_some() { - if handle_busy_connection(stream, self.debug)? { - self.stop_requested = true; - } - } else { - self.active_client = Some(ClientSession::new(stream, &mut self.events)?); - } + 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)?; } Event::AcceptError(error) => { return Err(Error::unexpected(format!( @@ -420,6 +423,7 @@ impl Daemon { self.stop_requested = true; // Stop accepting before unlinking the socket, so the wakeup still reaches our listener. self.accept_worker.take(); + self.pending_connections.clear(); self.disconnect_client()?; self.shutdown_upstream()?; match fs::remove_file(&self.target.socket_path) { @@ -465,6 +469,7 @@ 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(); // Normal stop already unlinked our socket; a replacement daemon may own that path now. diff --git a/src/commands/daemon/connections.rs b/src/commands/daemon/connections.rs new file mode 100644 index 0000000..744576f --- /dev/null +++ b/src/commands/daemon/connections.rs @@ -0,0 +1,121 @@ +use super::protocol::{ + ReaderEvent, error_response, message_method, normalize_initialize_params, request_id, + respond_to_stop_request, stop_request_id, +}; +use super::{ClientSession, Daemon, INVALID_REQUEST, REQUEST_CANCELLED, SERVER_NOT_INITIALIZED}; +use crate::error::Result; +use crate::lsp::transport::{log_debug_message, write_message}; +use serde_json::Value; +use std::os::unix::net::UnixStream; +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, +} + +impl PendingConnection { + fn reject(&mut self, id: &Value, code: i64, reason: &str, debug: bool) { + let response = error_response(id, code, reason); + log_debug_message(debug, "daemon pending client -> ", &response); + // A rejected peer may already have closed; its response failure must not stop the daemon. + let _ = write_message(&mut self.client.writer, &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 }); + Ok(()) + } + + pub(super) fn expire_pending_connections(&mut self, now: Instant) { + self.pending_connections + .retain(|_, pending| pending.deadline > now); + } + + pub(super) fn next_event_timeout(&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 + }; + self.pending_connections + .values() + .map(|pending| pending.deadline.saturating_duration_since(now)) + .chain(idle) + .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(()); + }; + log_debug_message(self.debug, "daemon pending client <- ", &message); + if stop_request_id(&message).is_some() { + if respond_to_stop_request(&mut pending.client.writer, &message, self.debug).is_ok() { + self.stop_requested = true; + } + return Ok(()); + } + let Some(id) = request_id(&message) else { + return Ok(()); + }; + if message_method(&message) != Some("initialize") { + pending.reject( + &id, + SERVER_NOT_INITIALIZED, + "daemon client must initialize before sending requests", + self.debug, + ); + return Ok(()); + } + if self.active_client.is_some() { + pending.reject( + &id, + REQUEST_CANCELLED, + "another daemon client is already connected", + self.debug, + ); + return Ok(()); + } + let params = message.get("params").unwrap_or(&Value::Null); + if let Err(error) = normalize_initialize_params(params, &self.target) { + pending.reject(&id, INVALID_REQUEST, &error.to_string(), self.debug); + 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..c5e91e3 --- /dev/null +++ b/src/commands/daemon/connections/tests.rs @@ -0,0 +1,464 @@ +use super::super::events::{Event, Source}; +use super::super::protocol::stop_request; +use super::super::session_tests::Fixture; +use super::*; +use crate::lsp::transport::read_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(); + } + 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()), + 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()), + )) + .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"})), + )) + .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.stop().expect("normal stop"); + 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 index ff491ca..03e6983 100644 --- a/src/commands/daemon/events.rs +++ b/src/commands/daemon/events.rs @@ -1,7 +1,9 @@ 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::collections::VecDeque; use std::io::{BufReader, Read}; use std::net::Shutdown; @@ -20,7 +22,10 @@ pub(super) enum Source { } pub(super) enum Event { - Accepted(UnixStream), + Accepted { + stream: UnixStream, + accepted_at: Instant, + }, AcceptError(String), Reader(Source, ReaderEvent), } @@ -163,15 +168,23 @@ impl ReaderWorker { 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 || { - let mut reader = BufReader::new(reader); while !admission.cancelled.load(Ordering::Acquire) { - let event = match read_message(&mut reader) { + let event = match next_message() { Ok(Some(message)) => ReaderEvent::Message(message), Ok(None) => ReaderEvent::EndOfStream, Err(error) => ReaderEvent::Error(error.to_string()), @@ -189,11 +202,22 @@ impl ReaderWorker { 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 worker = Self::spawn(reader, source, events)?; + 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) } @@ -239,7 +263,10 @@ impl AcceptWorker { .spawn(move || { while !admission.cancelled.load(Ordering::Acquire) { let event = match listener.accept() { - Ok((stream, _)) => Event::Accepted(stream), + Ok((stream, _)) => Event::Accepted { + stream, + accepted_at: Instant::now(), + }, Err(error) if error.kind() == std::io::ErrorKind::Interrupted => { continue; } diff --git a/src/commands/daemon/events/tests.rs b/src/commands/daemon/events/tests.rs index a3456c9..dd12b4b 100644 --- a/src/commands/daemon/events/tests.rs +++ b/src/commands/daemon/events/tests.rs @@ -210,10 +210,10 @@ fn listener_bounds_accepted_sockets_and_cancels_in_both_wait_states() { events.receiver.try_recv(), Err(mpsc::TryRecvError::Empty) )); - assert!(matches!(first.event, Event::Accepted(_))); + 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(_))); + assert!(matches!(second.event, Event::Accepted { .. })); // Teardown must release admission even while this delivery remains unacknowledged. drop(worker); assert!(second.acknowledge.send(()).is_err()); diff --git a/src/commands/daemon/process.rs b/src/commands/daemon/process.rs index 747f57e..2f6a27b 100644 --- a/src/commands/daemon/process.rs +++ b/src/commands/daemon/process.rs @@ -222,13 +222,22 @@ pub(super) fn bind_listener(socket_path: &Path) -> Result { } impl ClientSession { - pub(super) fn new(stream: UnixStream, events: &mut EventQueue) -> 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(reader, Source::Client(generation), events)?; + let worker = ReaderWorker::socket_with_deadline( + reader, + Source::Client(generation), + events, + deadline, + )?; Ok(Self { writer: stream, generation, diff --git a/src/commands/daemon/protocol.rs b/src/commands/daemon/protocol.rs index b8996e2..4c62ca6 100644 --- a/src/commands/daemon/protocol.rs +++ b/src/commands/daemon/protocol.rs @@ -1,4 +1,4 @@ -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::{SERVER_STATUS_METHOD, ServerStatusParams, parse_lsp_uri}; @@ -76,38 +76,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, diff --git a/src/commands/daemon/session_tests.rs b/src/commands/daemon/session_tests.rs index d505142..76caece 100644 --- a/src/commands/daemon/session_tests.rs +++ b/src/commands/daemon/session_tests.rs @@ -9,21 +9,21 @@ use std::sync::mpsc; const TIMEOUT: Duration = Duration::from_secs(3); -struct Fixture { - daemon: Daemon, - peer: BufReader, +pub(super) struct Fixture { + pub(super) daemon: Daemon, + pub(super) peer: BufReader, _dir: TestDir, } impl Fixture { - fn new() -> Self { + pub(super) fn new() -> Self { let dir = TestDir::new("daemon-session"); let target = tests::daemon_target(&dir); let mut events = EventQueue::new(); let upstream = fake_upstream(&mut events); let (socket, peer) = UnixStream::pair().expect("client pair"); peer.set_read_timeout(Some(TIMEOUT)).expect("read timeout"); - let client = ClientSession::new(socket, &mut events).expect("client"); + let client = ClientSession::new(socket, &mut events, None).expect("client"); Self { daemon: Daemon { accept_worker: None, @@ -34,6 +34,7 @@ impl Fixture { idle_timeout: TIMEOUT, upstream: Some(upstream), active_client: Some(client), + pending_connections: BTreeMap::new(), orphaned_client_requests: BTreeSet::new(), idle_since: Instant::now(), stop_requested: false, @@ -43,11 +44,11 @@ impl Fixture { } } - fn send(&mut self, message: &Value) { + pub(super) fn send(&mut self, message: &Value) { write_message(self.peer.get_mut(), message).expect("client write"); } - fn step(&mut self) { + pub(super) fn step(&mut self) { let delivery = self .daemon .events @@ -58,13 +59,13 @@ impl Fixture { result.expect("dispatch event"); } - fn read(&mut self) -> Value { + pub(super) fn read(&mut self) -> Value { read_message(&mut self.peer) .expect("read response") .expect("response") } - fn initialize(&mut self, reused: bool) -> Value { + 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": {} @@ -80,12 +81,13 @@ impl Fixture { response } - fn replace_client(&mut self) { + 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).expect("replacement client")); + self.daemon.active_client = Some( + ClientSession::new(socket, &mut self.daemon.events, None).expect("replacement client"), + ); self.peer = BufReader::new(peer); } } 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..d3a5dd5 --- /dev/null +++ b/src/commands/daemon/socket_reader/tests.rs @@ -0,0 +1,94 @@ +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) { + assert_eq!(peer.read(&mut [0]).expect("peer observes shutdown"), 0); +} + +#[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 8aa1caf..c57c662 100644 --- a/src/commands/daemon/tests.rs +++ b/src/commands/daemon/tests.rs @@ -253,26 +253,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"); From 5ce8c03537a69fd42b530206f58a3598c7021476 Mon Sep 17 00:00:00 2001 From: Vasily Kulikov Date: Sat, 5 Sep 2026 17:52:16 +0300 Subject: [PATCH 3/7] Separate daemon writing from coordination --- .../daemon-writer-completion-admission.md | 8 + README.md | 9 + playground/README.md | 7 +- src/cli.rs | 2 + src/cli/resolve.rs | 13 +- src/cli/tests/misc_commands.rs | 3 + src/commands/daemon.rs | 131 ++++++++++- src/commands/daemon/connections.rs | 83 +++++-- src/commands/daemon/connections/tests.rs | 8 + src/commands/daemon/events.rs | 50 +++-- src/commands/daemon/events/tests.rs | 2 +- src/commands/daemon/forwarding.rs | 16 +- src/commands/daemon/process.rs | 61 +++++- src/commands/daemon/protocol.rs | 18 +- src/commands/daemon/session_tests.rs | 67 +++++- src/commands/daemon/socket_reader/tests.rs | 9 +- src/commands/daemon/tests.rs | 92 ++++++-- src/commands/daemon/writer.rs | 205 ++++++++++++++++++ src/commands/daemon/writer/tests.rs | 57 +++++ src/config.rs | 8 + src/config_tests.rs | 6 + src/lsp/transport.rs | 16 +- 22 files changed, 761 insertions(+), 110 deletions(-) create mode 100644 .memory/unprocessed/daemon-writer-completion-admission.md create mode 100644 src/commands/daemon/writer.rs create mode 100644 src/commands/daemon/writer/tests.rs diff --git a/.memory/unprocessed/daemon-writer-completion-admission.md b/.memory/unprocessed/daemon-writer-completion-admission.md new file mode 100644 index 0000000..ef908c7 --- /dev/null +++ b/.memory/unprocessed/daemon-writer-completion-admission.md @@ -0,0 +1,8 @@ +# Daemon writer completion events must not use reader admission + +The daemon reader admission protocol waits for coordinator acknowledgement before +the producer reads again. Reusing that blocking delivery method for writer +completion events makes the writer stop draining its output queue until each +completion is dispatched. Writer progress events need nonblocking publication; +their acknowledgement sender must also have no live receiver, or unused +acknowledgements accumulate without bound. diff --git a/README.md b/README.md index 7cdaa3d..b697976 100644 --- a/README.md +++ b/README.md @@ -251,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++. @@ -264,6 +266,13 @@ 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. + ## 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 299f289..17eafd0 100644 --- a/playground/README.md +++ b/playground/README.md @@ -62,7 +62,12 @@ backlog bounded without a forwarding-loop polling delay. Individual message size 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 still run synchronously. These measurements describe an immediate-reply fixture, not a +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. +Logging and process-exit waits still run synchronously. 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, 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 8d462ca..27ed12b 100644 --- a/src/commands/daemon.rs +++ b/src/commands/daemon.rs @@ -14,7 +14,7 @@ use std::io::ErrorKind; use std::os::unix::net::UnixStream; use std::path::Path; use std::path::PathBuf; -use std::process::{Child, ChildStdin}; +use std::process::Child; use std::sync::mpsc::RecvTimeoutError; use std::thread; use std::time::{Duration, Instant}; @@ -25,6 +25,7 @@ mod forwarding; mod process; mod protocol; mod socket_reader; +mod writer; #[cfg(test)] mod session_tests; @@ -38,6 +39,7 @@ use protocol::{ BackgroundWorkTracker, ReaderEvent, error_response, read_control_message, request_id_from_key, response_id, stop_request, stop_request_id, }; +use writer::{WriteId, WriterEvent, WriterWorker}; const BACKGROUND_ENV: &str = "LSP_CLI_DAEMON_BACKGROUND"; const POLL_INTERVAL: Duration = Duration::from_millis(25); @@ -178,6 +180,7 @@ struct Daemon { target: DaemonTarget, debug: bool, idle_timeout: Duration, + write_stall_timeout: Duration, upstream: Option, active_client: Option, pending_connections: BTreeMap, @@ -188,7 +191,7 @@ struct Daemon { struct UpstreamServer { child: Child, - stdin: ChildStdin, + writer: WriterWorker, stderr: CapturedStderr, generation: u64, reader: ReaderWorker, @@ -199,7 +202,7 @@ struct UpstreamServer { } struct ClientSession { - writer: UnixStream, + writer: WriterWorker, generation: u64, reader: ReaderWorker, phase: ClientPhase, @@ -207,6 +210,7 @@ struct ClientSession { forwarded_client_requests: BTreeSet, pending_server_requests: BTreeMap, open_documents: BTreeSet, + stop_after_write: Option, } #[derive(Clone, Copy)] @@ -218,7 +222,12 @@ enum ClientPhase { } 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 listener = bind_listener(&target.socket_path)?; let mut daemon = Self { accept_worker: None, @@ -227,6 +236,7 @@ impl Daemon { target, debug, idle_timeout, + write_stall_timeout, upstream: None, active_client: None, pending_connections: BTreeMap::new(), @@ -249,7 +259,9 @@ impl Daemon { fn serve(&mut self) -> Result<()> { loop { - self.expire_pending_connections(Instant::now()); + let now = Instant::now(); + self.expire_pending_connections(now); + self.expire_stalled_outputs(now)?; if self.stop_requested || self.idle_expired() { return self.stop(); } @@ -334,6 +346,7 @@ impl Daemon { } } } + Event::Writer(source, event) => self.handle_writer_event(source, event)?, // Retired workers can still publish a final event while cancellation races with I/O. Event::Reader(_, _) => {} } @@ -392,13 +405,17 @@ impl Daemon { } fn write_client_response(&mut self, message: &Value) -> Result<()> { + self.enqueue_client_response(message).map(|_| ()) + } + + fn enqueue_client_response(&mut self, message: &Value) -> Result> { log_debug_message(self.debug, "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" )) } @@ -407,8 +424,102 @@ impl Daemon { 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")) + upstream + .writer + .enqueue(message) + .map(|_| ()) + .map_err(error_fn!(Error::lsp, "failed to queue LSP server message")) + } + + 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; + } + } + } + (Source::Client(generation), WriterEvent::Failed { id, error }) => { + log_unexpected_error(&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 { 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) + { + log_unexpected_error(&format!( + "LSP server stopped accepting message {id}: {error}" + )); + self.upstream_died(); + } + } + } + Ok(()) + } + + 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)) + { + log_unexpected_error( + "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)) + { + log_unexpected_error("LSP server was stopped because it stopped reading daemon output"); + self.upstream_died(); + } + Ok(()) } fn shutdown_upstream(&mut self) -> Result<()> { diff --git a/src/commands/daemon/connections.rs b/src/commands/daemon/connections.rs index 744576f..52fc00d 100644 --- a/src/commands/daemon/connections.rs +++ b/src/commands/daemon/connections.rs @@ -1,10 +1,11 @@ use super::protocol::{ ReaderEvent, error_response, message_method, normalize_initialize_params, request_id, - respond_to_stop_request, stop_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 crate::lsp::transport::{log_debug_message, write_message}; +use crate::lsp::transport::log_debug_message; use serde_json::Value; use std::os::unix::net::UnixStream; use std::time::{Duration, Instant}; @@ -15,14 +16,15 @@ 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, debug: bool) { + fn reject(&mut self, id: &Value, code: i64, reason: &str, debug: bool) -> Result { let response = error_response(id, code, reason); log_debug_message(debug, "daemon pending client -> ", &response); - // A rejected peer may already have closed; its response failure must not stop the daemon. - let _ = write_message(&mut self.client.writer, &response); + self.client.writer.enqueue(&response) } } @@ -39,17 +41,24 @@ impl Daemon { return Ok(()); } let client = ClientSession::new(stream, &mut self.events, Some(deadline))?; - self.pending_connections - .insert(client.generation, PendingConnection { client, 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.deadline > now); + .retain(|_, pending| pending.close_after_write.is_some() || pending.deadline > now); } - pub(super) fn next_event_timeout(&self, now: Instant) -> Option { + pub(super) fn next_event_timeout(&mut self, now: Instant) -> Option { let idle = if self.active_client.is_none() { Some( self.idle_timeout @@ -58,10 +67,35 @@ impl Daemon { } 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))) .min() } @@ -78,9 +112,13 @@ impl Daemon { return Ok(()); }; log_debug_message(self.debug, "daemon pending client <- ", &message); - if stop_request_id(&message).is_some() { - if respond_to_stop_request(&mut pending.client.writer, &message, self.debug).is_ok() { - self.stop_requested = true; + if let Some(id) = stop_request_id(&message) { + let response = success_response(&id, &Value::Null); + log_debug_message(self.debug, "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(()); } @@ -88,26 +126,37 @@ impl Daemon { return Ok(()); }; if message_method(&message) != Some("initialize") { - pending.reject( + if let Ok(write_id) = pending.reject( &id, SERVER_NOT_INITIALIZED, "daemon client must initialize before sending requests", self.debug, - ); + ) { + pending.close_after_write = Some(write_id); + self.pending_connections.insert(generation, pending); + } return Ok(()); } if self.active_client.is_some() { - pending.reject( + if let Ok(write_id) = pending.reject( &id, REQUEST_CANCELLED, "another daemon client is already connected", self.debug, - ); + ) { + 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) { - pending.reject(&id, INVALID_REQUEST, &error.to_string(), self.debug); + if let Ok(write_id) = + pending.reject(&id, INVALID_REQUEST, &error.to_string(), self.debug) + { + 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 diff --git a/src/commands/daemon/connections/tests.rs b/src/commands/daemon/connections/tests.rs index c5e91e3..5d92030 100644 --- a/src/commands/daemon/connections/tests.rs +++ b/src/commands/daemon/connections/tests.rs @@ -1,8 +1,10 @@ +use super::super::ClientPhase; use super::super::events::{Event, Source}; use super::super::protocol::stop_request; use super::super::session_tests::Fixture; use super::*; use crate::lsp::transport::read_message; +use crate::lsp::transport::write_message; use serde_json::json; use std::io::{BufReader, Read, Write}; @@ -142,6 +144,12 @@ fn pending_slot_does_not_reserve_active_session_and_pipelining_survives_promotio 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 diff --git a/src/commands/daemon/events.rs b/src/commands/daemon/events.rs index 03e6983..4891df4 100644 --- a/src/commands/daemon/events.rs +++ b/src/commands/daemon/events.rs @@ -28,6 +28,12 @@ pub(super) enum Event { }, AcceptError(String), Reader(Source, ReaderEvent), + Writer(Source, super::writer::WriterEvent), +} + +pub(super) enum UpstreamEvent { + Reader(ReaderEvent), + Writer(super::writer::WriterEvent), } pub(super) struct Delivery { @@ -63,6 +69,18 @@ impl EventQueue { 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, @@ -83,7 +101,7 @@ impl EventQueue { &mut self, generation: u64, timeout: Duration, - ) -> std::result::Result { + ) -> std::result::Result { let started = Instant::now(); loop { let remaining = timeout @@ -93,7 +111,11 @@ impl EventQueue { match delivery.event { Event::Reader(Source::Upstream(id), event) if id == generation => { let _ = delivery.acknowledge.send(()); - return Ok(event); + return Ok(UpstreamEvent::Reader(event)); + } + Event::Writer(Source::Upstream(id), event) if id == generation => { + let _ = delivery.acknowledge.send(()); + return Ok(UpstreamEvent::Writer(event)); } event => { // Withhold admission while shutdown is synchronous. At most one event per @@ -108,7 +130,7 @@ impl EventQueue { } } -struct Admission { +pub(super) struct Admission { cancelled: Arc, acknowledge: Sender<()>, replies: Receiver<()>, @@ -116,7 +138,16 @@ struct Admission { } impl Admission { - fn deliver(&self, event: Event) -> bool { + 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; } @@ -144,15 +175,8 @@ pub(super) struct ReaderWorker { } impl ReaderWorker { - fn admission(events: &EventQueue) -> (Self, 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: events.sender.clone(), - }; + pub(super) fn admission(events: &EventQueue) -> (Self, Admission) { + let (cancelled, acknowledge, admission) = events.admission(); ( Self { cancelled, diff --git a/src/commands/daemon/events/tests.rs b/src/commands/daemon/events/tests.rs index dd12b4b..497bec9 100644 --- a/src/commands/daemon/events/tests.rs +++ b/src/commands/daemon/events/tests.rs @@ -102,7 +102,7 @@ fn shutdown_defers_other_sources_without_releasing_admission() { fixture.send(1, &json!({"id": "shutdown", "result": null})); assert!(matches!( fixture.events.receive_upstream(2, TIMEOUT), - Ok(ReaderEvent::Message(_)) + Ok(UpstreamEvent::Reader(ReaderEvent::Message(_))) )); assert!(matches!( fixture.events.receiver.try_recv(), diff --git a/src/commands/daemon/forwarding.rs b/src/commands/daemon/forwarding.rs index 5ce74b4..ca8eadb 100644 --- a/src/commands/daemon/forwarding.rs +++ b/src/commands/daemon/forwarding.rs @@ -1,7 +1,7 @@ use super::protocol::{ error_response, fingerprint_value, id_key, local_server_request_response, message_method, - normalize_initialize_params, request_id, respond_to_stop_request, response_id, stop_request_id, - success_response, update_background_work_tracker, wants_background_work, + normalize_initialize_params, request_id, response_id, stop_request_id, success_response, + update_background_work_tracker, wants_background_work, }; use super::{ClientPhase, Daemon, INVALID_REQUEST, SERVER_NOT_INITIALIZED}; use crate::error::{Error, Result}; @@ -184,12 +184,16 @@ impl Daemon { } fn handle_stop_request(&mut self, message: &Value) -> Result<()> { - let Some(client) = self.active_client.as_mut() else { + 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(()); }; - - respond_to_stop_request(&mut client.writer, message, self.debug)?; - self.stop_requested = true; + if let Some(client) = self.active_client.as_mut() { + client.stop_after_write = Some(write_id); + } Ok(()) } diff --git a/src/commands/daemon/process.rs b/src/commands/daemon/process.rs index 2f6a27b..8f92512 100644 --- a/src/commands/daemon/process.rs +++ b/src/commands/daemon/process.rs @@ -1,4 +1,5 @@ -use super::events::{EventQueue, ReaderWorker, Source}; +use super::events::{EventQueue, ReaderWorker, Source, UpstreamEvent}; +use super::writer::{WriterEvent, WriterWorker}; use super::{ BACKGROUND_ENV, ClientPhase, ClientSession, Daemon, DaemonArgs, DaemonTarget, POLL_INTERVAL, ReaderEvent, UPSTREAM_SHUTDOWN_TIMEOUT, UpstreamServer, @@ -164,9 +165,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(); @@ -238,8 +244,9 @@ impl ClientSession { events, deadline, )?; + let writer = WriterWorker::socket(stream, Source::Client(generation), events)?; Ok(Self { - writer: stream, + writer, generation, reader: worker, phase: ClientPhase::WaitingForInitialize, @@ -247,6 +254,7 @@ impl ClientSession { forwarded_client_requests: BTreeSet::new(), pending_server_requests: BTreeMap::new(), open_documents: BTreeSet::new(), + stop_after_write: None, }) } } @@ -312,9 +320,17 @@ impl UpstreamServer { return Err(error); } }; + let writer = match WriterWorker::spawn(stdin, Source::Upstream(generation), events) { + Ok(writer) => writer, + Err(error) => { + let _ = child.kill(); + let _ = child.wait(); + return Err(error); + } + }; Ok(Self { child, - stdin, + writer, stderr, generation, reader, @@ -331,9 +347,10 @@ impl UpstreamServer { 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 shutdown_write = self.writer.enqueue(&shutdown).ok(); let started = Instant::now(); + let mut shutdown_written = shutdown_write.is_none(); while started.elapsed() < UPSTREAM_SHUTDOWN_TIMEOUT { let Some(remaining) = UPSTREAM_SHUTDOWN_TIMEOUT.checked_sub(started.elapsed()) else { @@ -341,20 +358,44 @@ impl UpstreamServer { }; match events.receive_upstream(self.generation, remaining) { - Ok(ReaderEvent::Message(message)) => { + Ok(UpstreamEvent::Writer(WriterEvent::Completed { id, .. })) => { + shutdown_written |= Some(id) == shutdown_write; + } + Ok( + UpstreamEvent::Writer(WriterEvent::Failed { .. }) + | UpstreamEvent::Reader(ReaderEvent::EndOfStream | ReaderEvent::Error(_)), + ) + | Err(_) => break, + Ok(UpstreamEvent::Reader(ReaderEvent::Message(message))) + if shutdown_written => + { 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, + Ok(UpstreamEvent::Reader(ReaderEvent::Message(_))) => {} } } 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); + if let Ok(exit_write) = self.writer.enqueue(&exit) { + let started = Instant::now(); + while let Some(remaining) = UPSTREAM_SHUTDOWN_TIMEOUT.checked_sub(started.elapsed()) + { + match events.receive_upstream(self.generation, remaining) { + Ok(UpstreamEvent::Writer(WriterEvent::Completed { id, .. })) + if id == exit_write => + { + break; + } + Ok(UpstreamEvent::Writer(WriterEvent::Failed { .. })) | Err(_) => break, + Ok(_) => {} + } + } + } } match self.child.try_wait() { diff --git a/src/commands/daemon/protocol.rs b/src/commands/daemon/protocol.rs index 4c62ca6..56dba1e 100644 --- a/src/commands/daemon/protocol.rs +++ b/src/commands/daemon/protocol.rs @@ -1,6 +1,6 @@ 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; @@ -111,22 +111,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 index 76caece..422dc21 100644 --- a/src/commands/daemon/session_tests.rs +++ b/src/commands/daemon/session_tests.rs @@ -2,7 +2,7 @@ use super::*; use crate::lsp::transport::read_message; use crate::test_support::{TestDir, with_env_vars}; use serde_json::json; -use std::io::BufReader; +use std::io::{BufRead, BufReader, ErrorKind}; use std::os::unix::net::UnixListener; use std::process::{Command, Stdio}; use std::sync::mpsc; @@ -32,6 +32,7 @@ impl Fixture { target, debug: false, idle_timeout: TIMEOUT, + write_stall_timeout: TIMEOUT, upstream: Some(upstream), active_client: Some(client), pending_connections: BTreeMap::new(), @@ -60,6 +61,28 @@ impl Fixture { } 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") @@ -73,11 +96,45 @@ impl Fixture { ); self.step(); if !reused { - self.step(); + 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": {}})); - self.step(); + 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 } @@ -112,9 +169,11 @@ fn fake_upstream(events: &mut EventQueue) -> UpstreamServer { let generation = events.next_generation().expect("upstream generation"); let reader = ReaderWorker::spawn(stdout, Source::Upstream(generation), events).expect("upstream reader"); + let writer = + WriterWorker::spawn(stdin, Source::Upstream(generation), events).expect("upstream writer"); UpstreamServer { child, - stdin, + writer, stderr, generation, reader, diff --git a/src/commands/daemon/socket_reader/tests.rs b/src/commands/daemon/socket_reader/tests.rs index d3a5dd5..f255e09 100644 --- a/src/commands/daemon/socket_reader/tests.rs +++ b/src/commands/daemon/socket_reader/tests.rs @@ -18,7 +18,14 @@ fn pair(deadline: Instant) -> (SocketReader, UnixStream) { } fn assert_closed(peer: &mut UnixStream) { - assert_eq!(peer.read(&mut [0]).expect("peer observes shutdown"), 0); + 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] diff --git a/src/commands/daemon/tests.rs b/src/commands/daemon/tests.rs index b1e6f31..bb29f7e 100644 --- a/src/commands/daemon/tests.rs +++ b/src/commands/daemon/tests.rs @@ -9,7 +9,7 @@ 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::thread; pub(super) fn daemon_target(dir: &TestDir) -> super::DaemonTarget { @@ -265,17 +265,18 @@ 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}; +fn window_fixture() -> (super::Daemon, UnixStream, TestDir) { + use super::events::{EventQueue, ReaderWorker, Source}; + use super::writer::WriterWorker; + use super::{ClientPhase, ClientSession, Daemon, UpstreamServer}; use crate::server_stderr::CapturedStderr; 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(); // Echo upstream bytes so the test can inspect forwarding without a real LSP. let mut child = Command::new("/bin/cat") .stdin(Stdio::piped()) @@ -283,9 +284,23 @@ fn forwards_multiple_requests_and_out_of_order_responses() { .stderr(Stdio::piped()) .spawn() .expect("start echo process"); + let generation = events.next_generation().expect("generation"); + let reader = ReaderWorker::spawn( + child.stdout.take().expect("stdout"), + Source::Upstream(generation), + &events, + ) + .expect("reader"); + let writer = WriterWorker::spawn( + child.stdin.take().expect("stdin"), + Source::Upstream(generation), + &events, + ) + .expect("writer"); let upstream = UpstreamServer { - stdin: child.stdin.take().expect("stdin"), - messages: super::process::spawn_reader(child.stdout.take().expect("stdout")), + writer, + reader, + generation, stderr: CapturedStderr::spawn(child.stderr.take().expect("stderr"), false), child, initialize_fingerprint: None, @@ -297,36 +312,63 @@ fn forwards_multiple_requests_and_out_of_order_responses() { 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, idle_timeout: Duration::from_secs(60), + write_stall_timeout: Duration::from_secs(2), upstream: Some(upstream), 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) .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!( @@ -347,6 +389,14 @@ fn forwards_multiple_requests_and_out_of_order_responses() { 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 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/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 { From f2bdbed3893dcd771457e672c7e4e88d27abb510 Mon Sep 17 00:00:00 2001 From: Vasily Kulikov Date: Sat, 5 Sep 2026 18:51:13 +0300 Subject: [PATCH 4/7] Make daemon lifecycle event-driven --- .../unprocessed/daemon-process-ownership.md | 7 + README.md | 3 + playground/README.md | 3 +- scripts/daemon_latency.py | 9 + src/commands/daemon.rs | 243 ++++------ src/commands/daemon/connections.rs | 1 + src/commands/daemon/connections/tests.rs | 5 +- src/commands/daemon/events.rs | 44 +- src/commands/daemon/events/tests.rs | 43 -- src/commands/daemon/forwarding.rs | 90 +++- src/commands/daemon/lifecycle.rs | 445 ++++++++++++++++++ src/commands/daemon/outputs.rs | 103 ++++ src/commands/daemon/process.rs | 214 +-------- src/commands/daemon/process_worker.rs | 236 ++++++++++ src/commands/daemon/session_tests.rs | 64 +-- src/commands/daemon/tests.rs | 125 +++-- src/server_stderr.rs | 10 + 17 files changed, 1125 insertions(+), 520 deletions(-) create mode 100644 .memory/unprocessed/daemon-process-ownership.md create mode 100644 src/commands/daemon/lifecycle.rs create mode 100644 src/commands/daemon/outputs.rs create mode 100644 src/commands/daemon/process_worker.rs diff --git a/.memory/unprocessed/daemon-process-ownership.md b/.memory/unprocessed/daemon-process-ownership.md new file mode 100644 index 0000000..b0ab428 --- /dev/null +++ b/.memory/unprocessed/daemon-process-ownership.md @@ -0,0 +1,7 @@ +# Child ownership determines lifecycle cancellation + +`std::process::Child` cannot be cloned. A worker that waits and reaps the child must +also receive force-stop commands and own termination. This keeps the daemon +coordinator responsive, but an unexpected daemon unwind can only send the worker a +best-effort stop command; joining that worker would restore an unlimited process +wait on the coordinator. diff --git a/README.md b/README.md index b697976..7b09505 100644 --- a/README.md +++ b/README.md @@ -272,6 +272,9 @@ limits. The daemon continues accepting messages during the grace period, so memo 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. ## Language Configs: filetypes/*.yaml diff --git a/playground/README.md b/playground/README.md index 17eafd0..a2af6c1 100644 --- a/playground/README.md +++ b/playground/README.md @@ -67,7 +67,8 @@ the coordinator. An output is flagged at 64 queued messages or 8 MiB of framed d 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. -Logging and process-exit waits still run synchronously. These measurements describe an immediate-reply fixture, not a +Process start, shutdown, exit monitoring, and reaping run through a lifecycle worker; +logging remains synchronous. 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, diff --git a/scripts/daemon_latency.py b/scripts/daemon_latency.py index 8808f87..3b85e02 100644 --- a/scripts/daemon_latency.py +++ b/scripts/daemon_latency.py @@ -40,6 +40,7 @@ def write_message(writer, message): def serve(): + hang_shutdown = False while message := read_message(sys.stdin.buffer): method = message.get("method") if method == "exit": @@ -54,6 +55,11 @@ def serve(): 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/register": write_message(sys.stdout.buffer, {"jsonrpc": "2.0", "id": "registration", "method": "client/registerCapability", "params": {"registrations": []}}) @@ -245,10 +251,13 @@ def benchmark(binary, workspace, samples, pipeline, check_handshakes): 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): + 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: diff --git a/src/commands/daemon.rs b/src/commands/daemon.rs index 27ed12b..9b554ed 100644 --- a/src/commands/daemon.rs +++ b/src/commands/daemon.rs @@ -4,7 +4,7 @@ use crate::error::{Error, Result, error_fn}; use crate::lsp::transport::{log_debug_message, write_message}; use crate::lsp::{jsonrpc, parse_lsp_uri}; use crate::server_stderr::CapturedStderr; -use crate::system_log::{log_lsp_server_exit, log_unexpected_error}; +use crate::system_log::log_unexpected_error; use lsp_types::notification::{Cancel, DidCloseTextDocument, Notification}; use lsp_types::{CancelParams, DidCloseTextDocumentParams, NumberOrString, TextDocumentIdentifier}; use serde_json::Value; @@ -14,7 +14,6 @@ use std::io::ErrorKind; use std::os::unix::net::UnixStream; use std::path::Path; use std::path::PathBuf; -use std::process::Child; use std::sync::mpsc::RecvTimeoutError; use std::thread; use std::time::{Duration, Instant}; @@ -22,7 +21,10 @@ use std::time::{Duration, Instant}; mod connections; mod events; mod forwarding; +mod lifecycle; +mod outputs; mod process; +mod process_worker; mod protocol; mod socket_reader; mod writer; @@ -35,11 +37,12 @@ mod tests; use connections::PendingConnection; use events::{AcceptWorker, Event, EventQueue, ReaderWorker, Source}; use process::{bind_listener, launch_background, resolve_target, run_background}; +use process_worker::ProcessWorker; use protocol::{ BackgroundWorkTracker, ReaderEvent, error_response, read_control_message, request_id_from_key, response_id, stop_request, stop_request_id, }; -use writer::{WriteId, WriterEvent, WriterWorker}; +use writer::{WriteId, WriterWorker}; const BACKGROUND_ENV: &str = "LSP_CLI_DAEMON_BACKGROUND"; const POLL_INTERVAL: Duration = Duration::from_millis(25); @@ -50,6 +53,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)?; @@ -182,6 +186,9 @@ struct Daemon { 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, @@ -190,11 +197,10 @@ struct Daemon { } struct UpstreamServer { - child: Child, writer: WriterWorker, stderr: CapturedStderr, generation: u64, - reader: ReaderWorker, + _reader: ReaderWorker, initialize_fingerprint: Option, initialize_result: Option, restart_required: bool, @@ -211,16 +217,63 @@ struct ClientSession { 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, @@ -238,17 +291,17 @@ impl Daemon { idle_timeout, 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.upstream = Some(UpstreamServer::spawn( - &daemon.target, - debug, - &mut daemon.events, - )?); + daemon.start_upstream(true)?; + daemon.wait_for_initial_upstream()?; daemon.accept_worker = Some(AcceptWorker::spawn( listener, &daemon.target.socket_path, @@ -262,17 +315,22 @@ impl Daemon { let now = Instant::now(); self.expire_pending_connections(now); self.expire_stalled_outputs(now)?; - if self.stop_requested || self.idle_expired() { - return self.stop(); + self.advance_lifecycle_deadline(now); + if (self.stop_requested && !self.lifecycle.is_stopping()) || self.idle_stop_due() { + self.begin_stop()?; + } + if self.lifecycle == LifecycleState::Stopped { + return self.finish_stop(); } let timeout = self.next_event_timeout(Instant::now()); match self.events.receive(timeout) { Ok(event) => { - if self.idle_expired() { + 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(()); - return self.stop(); + self.begin_stop()?; + continue; } let result = self.dispatch(event.event); // Release admission even when dispatch fails; cancellation handles retired readers. @@ -293,6 +351,10 @@ impl Daemon { self.active_client.is_none() && self.idle_since.elapsed() >= self.idle_timeout } + fn idle_stop_due(&self) -> bool { + self.idle_expired() && !self.lifecycle.is_stopping() + } + 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()); @@ -319,10 +381,14 @@ impl Daemon { .is_some_and(|upstream| upstream.generation == generation) => { match event { - ReaderEvent::Message(message) => self.handle_upstream_message(&message)?, - ReaderEvent::EndOfStream => self.upstream_died(), + ReaderEvent::Message(message) => { + if !self.handle_lifecycle_message(&message)? { + self.handle_upstream_message(&message)?; + } + } + ReaderEvent::EndOfStream => self.upstream_failed(), ReaderEvent::Error(error) => { - self.upstream_died(); + self.upstream_failed(); let error = format!("failed to read LSP server message: {error}"); log_unexpected_error(&error); return Err(Error::unexpected(error)); @@ -347,6 +413,7 @@ impl Daemon { } } 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(_, _) => {} } @@ -392,12 +459,7 @@ impl Daemon { .as_ref() .is_some_and(|upstream| upstream.restart_required) { - self.shutdown_upstream()?; - self.upstream = Some(UpstreamServer::spawn( - &self.target, - self.debug, - &mut self.events, - )?); + self.begin_restart()?; } self.idle_since = Instant::now(); @@ -431,112 +493,7 @@ impl Daemon { .map_err(error_fn!(Error::lsp, "failed to queue LSP server message")) } - 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; - } - } - } - (Source::Client(generation), WriterEvent::Failed { id, error }) => { - log_unexpected_error(&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 { 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) - { - log_unexpected_error(&format!( - "LSP server stopped accepting message {id}: {error}" - )); - self.upstream_died(); - } - } - } - Ok(()) - } - - 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)) - { - log_unexpected_error( - "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)) - { - log_unexpected_error("LSP server was stopped because it stopped reading daemon output"); - self.upstream_died(); - } - Ok(()) - } - - fn shutdown_upstream(&mut self) -> Result<()> { - if let Some(mut upstream) = self.upstream.take() { - upstream.shutdown(self.debug, &mut self.events)?; - } - self.orphaned_client_requests.clear(); - Ok(()) - } - - fn stop(&mut self) -> Result<()> { - self.stop_requested = true; - // Stop accepting before unlinking the socket, so the wakeup still reaches our listener. - self.accept_worker.take(); - self.pending_connections.clear(); - self.disconnect_client()?; - self.shutdown_upstream()?; + fn finish_stop(&mut self) -> Result<()> { match fs::remove_file(&self.target.socket_path) { Ok(()) => self.socket_owned = false, Err(error) if error.kind() == ErrorKind::NotFound => self.socket_owned = false, @@ -547,33 +504,6 @@ impl Daemon { } Ok(()) } - - fn restart_upstream(&mut self) -> Result<()> { - self.shutdown_upstream()?; - self.upstream = Some(UpstreamServer::spawn( - &self.target, - self.debug, - &mut self.events, - )?); - 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}")); - } - } - } - self.upstream = None; - self.active_client = None; - self.orphaned_client_requests.clear(); - self.idle_since = Instant::now(); - } } impl Drop for Daemon { @@ -583,6 +513,7 @@ impl Drop for Daemon { 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); diff --git a/src/commands/daemon/connections.rs b/src/commands/daemon/connections.rs index 52fc00d..217373b 100644 --- a/src/commands/daemon/connections.rs +++ b/src/commands/daemon/connections.rs @@ -96,6 +96,7 @@ impl Daemon { .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() } diff --git a/src/commands/daemon/connections/tests.rs b/src/commands/daemon/connections/tests.rs index 5d92030..b212ed5 100644 --- a/src/commands/daemon/connections/tests.rs +++ b/src/commands/daemon/connections/tests.rs @@ -1,7 +1,7 @@ -use super::super::ClientPhase; 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; @@ -411,7 +411,8 @@ fn stop_and_error_teardown_close_all_pending_readers() { .write_all(b"Content-Len") .expect("partial header"); if normal_stop { - fixture.daemon.stop().expect("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. diff --git a/src/commands/daemon/events.rs b/src/commands/daemon/events.rs index 4891df4..c4ac44b 100644 --- a/src/commands/daemon/events.rs +++ b/src/commands/daemon/events.rs @@ -4,7 +4,6 @@ use crate::error::{Error, Result}; use crate::lsp::transport::read_message; use crate::system_log::log_unexpected_error; use serde_json::Value; -use std::collections::VecDeque; use std::io::{BufReader, Read}; use std::net::Shutdown; use std::os::unix::net::{UnixListener, UnixStream}; @@ -29,11 +28,7 @@ pub(super) enum Event { AcceptError(String), Reader(Source, ReaderEvent), Writer(Source, super::writer::WriterEvent), -} - -pub(super) enum UpstreamEvent { - Reader(ReaderEvent), - Writer(super::writer::WriterEvent), + Process(u64, super::process_worker::ProcessEvent), } pub(super) struct Delivery { @@ -44,7 +39,6 @@ pub(super) struct Delivery { pub(super) struct EventQueue { sender: Sender, receiver: Receiver, - deferred: VecDeque, generation: u64, } @@ -54,7 +48,6 @@ impl EventQueue { Self { sender, receiver, - deferred: VecDeque::new(), generation: 0, } } @@ -85,9 +78,6 @@ impl EventQueue { &mut self, timeout: Option, ) -> std::result::Result { - if let Some(event) = self.deferred.pop_front() { - return Ok(event); - } match timeout { Some(timeout) => self.receiver.recv_timeout(timeout), None => self @@ -96,38 +86,6 @@ impl EventQueue { .map_err(|_| RecvTimeoutError::Disconnected), } } - - pub(super) fn receive_upstream( - &mut self, - generation: u64, - timeout: Duration, - ) -> std::result::Result { - let started = Instant::now(); - loop { - let remaining = timeout - .checked_sub(started.elapsed()) - .ok_or(RecvTimeoutError::Timeout)?; - let delivery = self.receiver.recv_timeout(remaining)?; - match delivery.event { - Event::Reader(Source::Upstream(id), event) if id == generation => { - let _ = delivery.acknowledge.send(()); - return Ok(UpstreamEvent::Reader(event)); - } - Event::Writer(Source::Upstream(id), event) if id == generation => { - let _ = delivery.acknowledge.send(()); - return Ok(UpstreamEvent::Writer(event)); - } - event => { - // Withhold admission while shutdown is synchronous. At most one event per - // other producer can be deferred, and normal dispatch retains their order. - self.deferred.push_back(Delivery { - event, - acknowledge: delivery.acknowledge, - }); - } - } - } - } } pub(super) struct Admission { diff --git a/src/commands/daemon/events/tests.rs b/src/commands/daemon/events/tests.rs index 497bec9..e00b206 100644 --- a/src/commands/daemon/events/tests.rs +++ b/src/commands/daemon/events/tests.rs @@ -70,49 +70,6 @@ fn reader_admission_preserves_order_and_opposite_direction_opportunities() { } } -#[test] -fn shutdown_defers_other_sources_without_releasing_admission() { - let client = Source::Client(1); - let upstream = Source::Upstream(2); - let retired = Source::Upstream(0); - let mut fixture = Fixture::new(&[client, upstream, retired]); - fixture.send(0, &json!("first")); - // Synchronize publication before queuing the next source, retaining FIFO order. - let first = fixture.receive(); - fixture.send(2, &json!("stale")); - let stale = fixture.receive(); - fixture - .events - .sender - .send(first) - .expect("restore first delivery"); - fixture - .events - .sender - .send(stale) - .expect("restore stale delivery"); - assert!(matches!( - fixture - .events - .receive_upstream(2, Duration::from_millis(20)), - Err(RecvTimeoutError::Timeout) - )); - assert_eq!(fixture.events.deferred.len(), 2); - fixture.send(0, &json!("second")); - fixture.send(1, &json!({"id": "shutdown", "result": null})); - assert!(matches!( - fixture.events.receive_upstream(2, TIMEOUT), - Ok(UpstreamEvent::Reader(ReaderEvent::Message(_))) - )); - assert!(matches!( - fixture.events.receiver.try_recv(), - Err(mpsc::TryRecvError::Empty) - )); - assert_eq!(message(fixture.receive(), client), json!("first")); - assert_eq!(message(fixture.receive(), retired), json!("stale")); - assert_eq!(message(fixture.receive(), client), json!("second")); -} - #[test] fn cancellation_releases_unacknowledged_reader() { let mut fixture = Fixture::new(&[Source::Client(1)]); diff --git a/src/commands/daemon/forwarding.rs b/src/commands/daemon/forwarding.rs index ca8eadb..deef546 100644 --- a/src/commands/daemon/forwarding.rs +++ b/src/commands/daemon/forwarding.rs @@ -3,7 +3,9 @@ use super::protocol::{ normalize_initialize_params, request_id, response_id, stop_request_id, success_response, update_background_work_tracker, wants_background_work, }; -use super::{ClientPhase, Daemon, INVALID_REQUEST, SERVER_NOT_INITIALIZED}; +use super::{ + ClientPhase, Daemon, INTERNAL_ERROR, INVALID_REQUEST, PendingInitialize, SERVER_NOT_INITIALIZED, +}; use crate::error::{Error, Result}; use crate::lsp::transport::log_debug_message; use crate::lsp::{STOP_METHOD, jsonrpc}; @@ -77,6 +79,9 @@ impl Daemon { 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()?; @@ -117,6 +122,28 @@ impl Daemon { self.write_upstream_message(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(()); @@ -140,7 +167,17 @@ impl Daemon { }; if should_restart { - self.restart_upstream()?; + 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 @@ -166,19 +203,58 @@ impl Daemon { 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(fingerprint); - - let forwarded = jsonrpc(Some(request_id.clone()), Initialize::METHOD, &normalized)?; + 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 = wants_background_work; + client.wants_background_work = initialize.wants_background_work; client.phase = ClientPhase::WaitingForInitialized { forward_to_upstream: true, }; - client.forwarded_client_requests.insert(id_key(&request_id)); + 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(()) } diff --git a/src/commands/daemon/lifecycle.rs b/src/commands/daemon/lifecycle.rs new file mode 100644 index 0000000..d5795ef --- /dev/null +++ b/src/commands/daemon/lifecycle.rs @@ -0,0 +1,445 @@ +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 crate::lsp::transport::log_debug_message; +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::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)?; + log_lsp_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(()); + } + log_lsp_server_started(io.pid); + self.upstream = Some(UpstreamServer::from_io( + io, + generation, + self.debug, + &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)); + } + log_unexpected_error(&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) => log_lsp_server_exit(status), + Err(error) => log_unexpected_error(&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, + &(), + )?; + log_debug_message(self.debug, "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, &())?; + log_debug_message(self.debug, "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() + { + log_unexpected_error(&error.to_string()); + } + self.lifecycle = LifecycleState::Killing { generation, after }; + } +} + +impl UpstreamServer { + pub(super) fn from_io( + io: super::process_worker::ProcessIo, + generation: u64, + debug: bool, + events: &super::events::EventQueue, + ) -> Result { + let stderr = crate::server_stderr::CapturedStderr::spawn(io.stderr, debug); + 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/outputs.rs b/src/commands/daemon/outputs.rs new file mode 100644 index 0000000..c43664f --- /dev/null +++ b/src/commands/daemon/outputs.rs @@ -0,0 +1,103 @@ +use super::Daemon; +use super::events::Source; +use super::writer::WriterEvent; +use crate::error::Result; +use crate::system_log::log_unexpected_error; +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 }) => { + log_unexpected_error(&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) + { + log_unexpected_error(&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)) + { + log_unexpected_error( + "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)) + { + log_unexpected_error("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 8f92512..1b40ac2 100644 --- a/src/commands/daemon/process.rs +++ b/src/commands/daemon/process.rs @@ -1,28 +1,17 @@ -use super::events::{EventQueue, ReaderWorker, Source, UpstreamEvent}; -use super::writer::{WriterEvent, WriterWorker}; -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::{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::thread; use std::time::Instant; pub(super) fn resolve_target(args: &DaemonArgs, config: &ConfigStore) -> Result { @@ -255,204 +244,11 @@ impl ClientSession { 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, - events: &mut EventQueue, - ) -> Result { - let generation = events.next_generation()?; - 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, - ); - - let reader = match ReaderWorker::spawn(stdout, Source::Upstream(generation), events) { - Ok(reader) => reader, - Err(error) => { - let _ = child.kill(); - let _ = child.wait(); - return Err(error); - } - }; - let writer = match WriterWorker::spawn(stdin, Source::Upstream(generation), events) { - Ok(writer) => writer, - Err(error) => { - let _ = child.kill(); - let _ = child.wait(); - return Err(error); - } - }; - Ok(Self { - child, - writer, - stderr, - generation, - reader, - initialize_fingerprint: None, - initialize_result: None, - restart_required: false, - background_work: super::BackgroundWorkTracker::default(), - }) - } - - pub(super) fn shutdown(&mut self, debug: bool, events: &mut EventQueue) -> 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 shutdown_write = self.writer.enqueue(&shutdown).ok(); - - let started = Instant::now(); - let mut shutdown_written = shutdown_write.is_none(); - while started.elapsed() < UPSTREAM_SHUTDOWN_TIMEOUT { - let Some(remaining) = UPSTREAM_SHUTDOWN_TIMEOUT.checked_sub(started.elapsed()) - else { - break; - }; - - match events.receive_upstream(self.generation, remaining) { - Ok(UpstreamEvent::Writer(WriterEvent::Completed { id, .. })) => { - shutdown_written |= Some(id) == shutdown_write; - } - Ok( - UpstreamEvent::Writer(WriterEvent::Failed { .. }) - | UpstreamEvent::Reader(ReaderEvent::EndOfStream | ReaderEvent::Error(_)), - ) - | Err(_) => break, - Ok(UpstreamEvent::Reader(ReaderEvent::Message(message))) - if shutdown_written => - { - if super::response_id(&message).as_ref().is_some_and(|value| { - *value == Value::String("lsp-cli/daemon-shutdown".to_string()) - }) { - break; - } - } - Ok(UpstreamEvent::Reader(ReaderEvent::Message(_))) => {} - } - } - - let exit = jsonrpc::(None, Exit::METHOD, &())?; - crate::lsp::transport::log_debug_message(debug, "daemon upstream <- ", &exit); - if let Ok(exit_write) = self.writer.enqueue(&exit) { - let started = Instant::now(); - while let Some(remaining) = UPSTREAM_SHUTDOWN_TIMEOUT.checked_sub(started.elapsed()) - { - match events.receive_upstream(self.generation, remaining) { - Ok(UpstreamEvent::Writer(WriterEvent::Completed { id, .. })) - if id == exit_write => - { - break; - } - Ok(UpstreamEvent::Writer(WriterEvent::Failed { .. })) | Err(_) => break, - Ok(_) => {} - } - } - } - } - - 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(()) - } -} - -impl Drop for UpstreamServer { - fn drop(&mut self) { - // Error paths must cancel admission and reap the owned child as well as normal shutdown. - self.reader.cancel(); - if matches!(self.child.try_wait(), Ok(None)) { - let _ = self.child.kill(); - let _ = self.child.wait(); - } - } -} - 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/session_tests.rs b/src/commands/daemon/session_tests.rs index 422dc21..7270e4a 100644 --- a/src/commands/daemon/session_tests.rs +++ b/src/commands/daemon/session_tests.rs @@ -20,7 +20,7 @@ impl Fixture { let dir = TestDir::new("daemon-session"); let target = tests::daemon_target(&dir); let mut events = EventQueue::new(); - let upstream = fake_upstream(&mut events); + let (upstream, process) = fake_upstream(&mut events); 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"); @@ -34,6 +34,9 @@ impl Fixture { 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(), @@ -149,8 +152,8 @@ impl Fixture { } } -fn fake_upstream(events: &mut EventQueue) -> UpstreamServer { - let mut child = with_env_vars(&[], || { +fn fake_upstream(events: &mut EventQueue) -> (UpstreamServer, ProcessWorker) { + let child = with_env_vars(&[], || { Command::new("python3") .arg(concat!( env!("CARGO_MANIFEST_DIR"), @@ -163,25 +166,10 @@ fn fake_upstream(events: &mut EventQueue) -> UpstreamServer { .spawn() .expect("fake server") }); - let stdin = child.stdin.take().expect("stdin"); - let stdout = child.stdout.take().expect("stdout"); - let stderr = CapturedStderr::spawn(child.stderr.take().expect("stderr"), false); let generation = events.next_generation().expect("upstream generation"); - let reader = - ReaderWorker::spawn(stdout, Source::Upstream(generation), events).expect("upstream reader"); - let writer = - WriterWorker::spawn(stdin, Source::Upstream(generation), events).expect("upstream writer"); - UpstreamServer { - child, - writer, - stderr, - generation, - reader, - initialize_fingerprint: None, - initialize_result: None, - restart_required: false, - background_work: BackgroundWorkTracker::default(), - } + let (process, io) = ProcessWorker::adopt(child, generation, events); + let upstream = UpstreamServer::from_io(io, generation, false, events).expect("upstream"); + (upstream, process) } #[test] @@ -229,7 +217,11 @@ fn stale_generations_cannot_modify_replacement_sessions() { .generation; fixture.replace_client(); fixture.daemon.upstream.take(); - fixture.daemon.upstream = Some(fake_upstream(&mut fixture.daemon.events)); + fixture.daemon.process.take(); + let (upstream, process) = fake_upstream(&mut fixture.daemon.events); + fixture.daemon.upstream = Some(upstream); + fixture.daemon.process = Some(process); + fixture.daemon.lifecycle = LifecycleState::Running; let client = fixture .daemon .active_client @@ -276,22 +268,35 @@ fn stale_generations_cannot_modify_replacement_sessions() { } #[test] -fn shutdown_preserves_unrelated_client_message_for_dispatch() { +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 - .shutdown_upstream() - .expect("shutdown reply through event queue"); - assert!(fixture.daemon.upstream.is_none()); - fixture.step(); + .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(); @@ -354,7 +359,10 @@ fn dropping_stopped_daemon_preserves_replacement_socket() { daemon.accept_worker = Some(AcceptWorker::spawn(listener, &path, &daemon.events).expect("accept worker")); daemon.upstream.take(); - daemon.stop().expect("stop removes owned socket"); + 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); diff --git a/src/commands/daemon/tests.rs b/src/commands/daemon/tests.rs index bb29f7e..01e8f0c 100644 --- a/src/commands/daemon/tests.rs +++ b/src/commands/daemon/tests.rs @@ -266,10 +266,8 @@ fn stop_socket_returns_not_running_when_socket_is_missing() { } fn window_fixture() -> (super::Daemon, UnixStream, TestDir) { - use super::events::{EventQueue, ReaderWorker, Source}; - use super::writer::WriterWorker; + use super::events::EventQueue; use super::{ClientPhase, ClientSession, Daemon, UpstreamServer}; - use crate::server_stderr::CapturedStderr; use std::collections::{BTreeMap, BTreeSet}; use std::process::{Command, Stdio}; use std::time::{Duration, Instant}; @@ -278,36 +276,15 @@ fn window_fixture() -> (super::Daemon, UnixStream, TestDir) { let target = daemon_target(&dir); let mut events = EventQueue::new(); // 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 generation = events.next_generation().expect("generation"); - let reader = ReaderWorker::spawn( - child.stdout.take().expect("stdout"), - Source::Upstream(generation), - &events, - ) - .expect("reader"); - let writer = WriterWorker::spawn( - child.stdin.take().expect("stdin"), - Source::Upstream(generation), - &events, - ) - .expect("writer"); - let upstream = UpstreamServer { - writer, - reader, - generation, - stderr: CapturedStderr::spawn(child.stderr.take().expect("stderr"), false), - child, - initialize_fingerprint: None, - initialize_result: None, - restart_required: false, - background_work: BackgroundWorkTracker::default(), - }; + let (process, io) = super::ProcessWorker::adopt(child, generation, &events); + let upstream = UpstreamServer::from_io(io, generation, false, &events).expect("upstream"); let (client, proxy) = UnixStream::pair().expect("client socket pair"); client .set_read_timeout(Some(Duration::from_secs(3))) @@ -323,6 +300,9 @@ fn window_fixture() -> (super::Daemon, UnixStream, TestDir) { 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(), @@ -406,8 +386,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/server_stderr.rs b/src/server_stderr.rs index 8a3630a..dfa21fb 100644 --- a/src/server_stderr.rs +++ b/src/server_stderr.rs @@ -61,6 +61,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::>() From b06bd60d7d5b3a57b215065ae3215fcfd35d3bcc Mon Sep 17 00:00:00 2001 From: Vasily Kulikov Date: Sat, 5 Sep 2026 19:15:47 +0300 Subject: [PATCH 5/7] cleanup --- .../unprocessed/daemon-process-ownership.md | 7 -- .../daemon-writer-completion-admission.md | 8 -- .../unprocessed/references-lua-performance.md | 32 ----- .../unprocessed/release-reference-profile.md | 117 ------------------ .../request-window-implementation.md | 27 ---- .../request-window-validation-difficulties.md | 27 ---- 6 files changed, 218 deletions(-) delete mode 100644 .memory/unprocessed/daemon-process-ownership.md delete mode 100644 .memory/unprocessed/daemon-writer-completion-admission.md delete mode 100644 .memory/unprocessed/references-lua-performance.md delete mode 100644 .memory/unprocessed/release-reference-profile.md delete mode 100644 .memory/unprocessed/request-window-implementation.md delete mode 100644 .memory/unprocessed/request-window-validation-difficulties.md diff --git a/.memory/unprocessed/daemon-process-ownership.md b/.memory/unprocessed/daemon-process-ownership.md deleted file mode 100644 index b0ab428..0000000 --- a/.memory/unprocessed/daemon-process-ownership.md +++ /dev/null @@ -1,7 +0,0 @@ -# Child ownership determines lifecycle cancellation - -`std::process::Child` cannot be cloned. A worker that waits and reaps the child must -also receive force-stop commands and own termination. This keeps the daemon -coordinator responsive, but an unexpected daemon unwind can only send the worker a -best-effort stop command; joining that worker would restore an unlimited process -wait on the coordinator. diff --git a/.memory/unprocessed/daemon-writer-completion-admission.md b/.memory/unprocessed/daemon-writer-completion-admission.md deleted file mode 100644 index ef908c7..0000000 --- a/.memory/unprocessed/daemon-writer-completion-admission.md +++ /dev/null @@ -1,8 +0,0 @@ -# Daemon writer completion events must not use reader admission - -The daemon reader admission protocol waits for coordinator acknowledgement before -the producer reads again. Reusing that blocking delivery method for writer -completion events makes the writer stop draining its output queue until each -completion is dispatched. Writer progress events need nonblocking publication; -their acknowledgement sender must also have no live receiver, or unused -acknowledgements accumulate without bound. 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). From e72e89570c510fa2951fd2cd13825bc53d614ffc Mon Sep 17 00:00:00 2001 From: Vasily Kulikov Date: Sat, 5 Sep 2026 19:24:42 +0300 Subject: [PATCH 6/7] Isolate daemon logging from coordination --- .../unprocessed/daemon-logger-lock-scope.md | 7 + README.md | 4 + playground/README.md | 4 +- scripts/daemon_latency.py | 31 +- src/commands/daemon.rs | 41 ++- src/commands/daemon/connections.rs | 32 ++- src/commands/daemon/connections/tests.rs | 6 +- src/commands/daemon/events.rs | 2 +- src/commands/daemon/events/tests.rs | 2 +- src/commands/daemon/forwarding.rs | 23 +- src/commands/daemon/lifecycle.rs | 26 +- src/commands/daemon/logger.rs | 268 ++++++++++++++++++ src/commands/daemon/logger/tests.rs | 108 +++++++ src/commands/daemon/outputs.rs | 13 +- src/commands/daemon/protocol.rs | 3 +- src/commands/daemon/session_tests.rs | 15 +- src/commands/daemon/tests.rs | 14 +- src/server_stderr.rs | 63 +++- 18 files changed, 579 insertions(+), 83 deletions(-) create mode 100644 .memory/unprocessed/daemon-logger-lock-scope.md create mode 100644 src/commands/daemon/logger.rs create mode 100644 src/commands/daemon/logger/tests.rs 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/README.md b/README.md index 7b09505..5c25241 100644 --- a/README.md +++ b/README.md @@ -275,6 +275,10 @@ server if the queue stays marked for `write-stall-timeout`. A message larger tha 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 diff --git a/playground/README.md b/playground/README.md index a2af6c1..b9dba32 100644 --- a/playground/README.md +++ b/playground/README.md @@ -68,7 +68,9 @@ it is unflagged after both values fall below their limits, or disconnected after 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; -logging remains synchronous. These measurements describe an immediate-reply fixture, not a +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, diff --git a/scripts/daemon_latency.py b/scripts/daemon_latency.py index 3b85e02..73019f3 100644 --- a/scripts/daemon_latency.py +++ b/scripts/daemon_latency.py @@ -8,6 +8,7 @@ import argparse import contextlib +import fcntl import json import math import os @@ -61,6 +62,11 @@ def serve(): 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: @@ -183,6 +189,10 @@ def percentile(values, fraction): 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() @@ -193,9 +203,9 @@ def benchmark(binary, workspace, samples, pipeline, check_handshakes): f'cmdline: {json.dumps(command)}\nwait-for-index: false\n' ) (data / "lsp-cli.yaml").write_text("download: false\ndetach: false\n") - env = {**os.environ, "LSP_DATA": str(data), "XDG_CONFIG_HOME": str(root / "config"), + 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", "--idle-timeout", "30"] + 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) @@ -217,6 +227,15 @@ def benchmark(binary, workspace, samples, pipeline, check_handshakes): 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") @@ -254,9 +273,11 @@ def benchmark(binary, workspace, samples, pipeline, check_handshakes): peer.request("latency/hangShutdown") # A silent connection must not delay a later stop control connection. with raw_connection(path): - started = time.monotonic() - subprocess.run([str(binary), "stop", str(workspace), "--lsp", "latency-fixture"], - env=env, capture_output=True, timeout=15, check=True) + 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 diff --git a/src/commands/daemon.rs b/src/commands/daemon.rs index 9b554ed..f03d851 100644 --- a/src/commands/daemon.rs +++ b/src/commands/daemon.rs @@ -4,7 +4,6 @@ use crate::error::{Error, Result, error_fn}; use crate::lsp::transport::{log_debug_message, write_message}; use crate::lsp::{jsonrpc, parse_lsp_uri}; use crate::server_stderr::CapturedStderr; -use crate::system_log::log_unexpected_error; use lsp_types::notification::{Cancel, DidCloseTextDocument, Notification}; use lsp_types::{CancelParams, DidCloseTextDocumentParams, NumberOrString, TextDocumentIdentifier}; use serde_json::Value; @@ -14,6 +13,7 @@ use std::io::ErrorKind; use std::os::unix::net::UnixStream; use std::path::Path; use std::path::PathBuf; +use std::sync::Arc; use std::sync::mpsc::RecvTimeoutError; use std::thread; use std::time::{Duration, Instant}; @@ -22,6 +22,7 @@ mod connections; mod events; mod forwarding; mod lifecycle; +mod logger; mod outputs; mod process; mod process_worker; @@ -36,6 +37,7 @@ 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::{ @@ -183,6 +185,8 @@ struct Daemon { socket_owned: bool, target: DaemonTarget, debug: bool, + logger: Logger, + logger_worker: LoggerWorker, idle_timeout: Duration, write_stall_timeout: Duration, upstream: Option, @@ -281,6 +285,8 @@ impl Daemon { 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)?; let mut daemon = Self { accept_worker: None, @@ -288,6 +294,8 @@ impl Daemon { socket_owned: true, target, debug, + logger, + logger_worker, idle_timeout, write_stall_timeout, upstream: None, @@ -390,7 +398,7 @@ impl Daemon { ReaderEvent::Error(error) => { self.upstream_failed(); let error = format!("failed to read LSP server message: {error}"); - log_unexpected_error(&error); + self.logger.unexpected(&error); return Err(Error::unexpected(error)); } } @@ -471,7 +479,18 @@ impl Daemon { } fn enqueue_client_response(&mut self, message: &Value) -> Result> { - log_debug_message(self.debug, "daemon client -> ", message); + self.logger.debug_value("daemon client -> ", 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" + )) + } + + 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); }; @@ -485,7 +504,20 @@ 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); + 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 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) @@ -502,6 +534,7 @@ impl Daemon { self.target.socket_path.display() )))?, } + self.logger_worker.finish(LOG_SHUTDOWN_TIMEOUT); Ok(()) } } diff --git a/src/commands/daemon/connections.rs b/src/commands/daemon/connections.rs index 217373b..e110b5b 100644 --- a/src/commands/daemon/connections.rs +++ b/src/commands/daemon/connections.rs @@ -5,9 +5,9 @@ use super::protocol::{ use super::writer::WriteId; use super::{ClientSession, Daemon, INVALID_REQUEST, REQUEST_CANCELLED, SERVER_NOT_INITIALIZED}; use crate::error::Result; -use crate::lsp::transport::log_debug_message; 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); @@ -21,10 +21,12 @@ pub(super) struct PendingConnection { } impl PendingConnection { - fn reject(&mut self, id: &Value, code: i64, reason: &str, debug: bool) -> Result { + fn reject(&mut self, id: &Value, code: i64, reason: &str) -> Result<(WriteId, Value)> { let response = error_response(id, code, reason); - log_debug_message(debug, "daemon pending client -> ", &response); - self.client.writer.enqueue(&response) + self.client + .writer + .enqueue(&response) + .map(|write_id| (write_id, response)) } } @@ -112,10 +114,12 @@ impl Daemon { // Malformed frames and EOF belong to this unadmitted connection only. return Ok(()); }; - log_debug_message(self.debug, "daemon pending client <- ", &message); + self.logger + .debug("daemon pending client <- ", Arc::clone(&message)); if let Some(id) = stop_request_id(&message) { let response = success_response(&id, &Value::Null); - log_debug_message(self.debug, "daemon pending client -> ", &response); + 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; @@ -127,24 +131,26 @@ impl Daemon { return Ok(()); }; if message_method(&message) != Some("initialize") { - if let Ok(write_id) = pending.reject( + if let Ok((write_id, response)) = pending.reject( &id, SERVER_NOT_INITIALIZED, "daemon client must initialize before sending requests", - self.debug, ) { + 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) = pending.reject( + if let Ok((write_id, response)) = pending.reject( &id, REQUEST_CANCELLED, "another daemon client is already connected", - self.debug, ) { + self.logger + .debug_value("daemon pending client -> ", &response); pending.close_after_write = Some(write_id); self.pending_connections.insert(generation, pending); } @@ -152,9 +158,11 @@ impl Daemon { } let params = message.get("params").unwrap_or(&Value::Null); if let Err(error) = normalize_initialize_params(params, &self.target) { - if let Ok(write_id) = - pending.reject(&id, INVALID_REQUEST, &error.to_string(), self.debug) + 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); } diff --git a/src/commands/daemon/connections/tests.rs b/src/commands/daemon/connections/tests.rs index b212ed5..63698e6 100644 --- a/src/commands/daemon/connections/tests.rs +++ b/src/commands/daemon/connections/tests.rs @@ -279,7 +279,7 @@ fn deadline_includes_accept_queue_time_and_ignores_late_events() { let _replacement = fixture.connect(); let replacement = fixture.latest_pending(); for event in [ - ReaderEvent::Message(fixture.initialize_message()), + ReaderEvent::Message(fixture.initialize_message().into()), ReaderEvent::EndOfStream, ReaderEvent::Error("expired".into()), ] { @@ -313,7 +313,7 @@ fn expiry_wins_over_first_message_and_runs_during_other_events() { .daemon .dispatch(Event::Reader( Source::Client(generation), - ReaderEvent::Message(fixture.initialize_message()), + ReaderEvent::Message(fixture.initialize_message().into()), )) .expect("expired first message"); peer.assert_closed(); @@ -330,7 +330,7 @@ fn expiry_wins_over_first_message_and_runs_during_other_events() { .daemon .dispatch(Event::Reader( Source::Upstream(999), - ReaderEvent::Message(json!({"method": "notification"})), + ReaderEvent::Message(json!({"method": "notification"}).into()), )) .expect("continuous unrelated traffic still checks expiry"); peer.assert_closed(); diff --git a/src/commands/daemon/events.rs b/src/commands/daemon/events.rs index c4ac44b..9e5a849 100644 --- a/src/commands/daemon/events.rs +++ b/src/commands/daemon/events.rs @@ -167,7 +167,7 @@ impl ReaderWorker { .spawn(move || { while !admission.cancelled.load(Ordering::Acquire) { let event = match next_message() { - Ok(Some(message)) => ReaderEvent::Message(message), + Ok(Some(message)) => ReaderEvent::Message(Arc::new(message)), Ok(None) => ReaderEvent::EndOfStream, Err(error) => ReaderEvent::Error(error.to_string()), }; diff --git a/src/commands/daemon/events/tests.rs b/src/commands/daemon/events/tests.rs index e00b206..3d88b46 100644 --- a/src/commands/daemon/events/tests.rs +++ b/src/commands/daemon/events/tests.rs @@ -46,7 +46,7 @@ fn message(delivery: Delivery, source: Source) -> Value { }; assert_eq!(actual_source, source); delivery.acknowledge.send(()).expect("acknowledge"); - value + Arc::unwrap_or_clone(value) } #[test] diff --git a/src/commands/daemon/forwarding.rs b/src/commands/daemon/forwarding.rs index deef546..00bd615 100644 --- a/src/commands/daemon/forwarding.rs +++ b/src/commands/daemon/forwarding.rs @@ -7,14 +7,14 @@ use super::{ ClientPhase, Daemon, INTERNAL_ERROR, INVALID_REQUEST, PendingInitialize, SERVER_NOT_INITIALIZED, }; use crate::error::{Error, Result}; -use crate::lsp::transport::log_debug_message; 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: &Value) -> Result<()> { - log_debug_message(self.debug, "daemon client <- ", message); + 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); @@ -25,7 +25,7 @@ impl Daemon { }; let key = id_key(&response_id); if client.pending_server_requests.remove(&key).is_some() { - self.write_upstream_message(message)?; + self.write_upstream_shared(message)?; } return Ok(()); } @@ -60,7 +60,7 @@ impl Daemon { }) => { if method == Some("initialized") { if forward_to_upstream { - self.write_upstream_message(message)?; + self.write_upstream_shared(message)?; } if let Some(client) = self.active_client.as_mut() { client.phase = ClientPhase::Ready; @@ -119,7 +119,7 @@ impl Daemon { client.forwarded_client_requests.insert(id_key(&request_id)); } - self.write_upstream_message(message) + self.write_upstream_shared(message) } fn handle_waiting_for_upstream( @@ -273,8 +273,9 @@ impl Daemon { Ok(()) } - pub(super) fn handle_upstream_message(&mut self, message: &Value) -> Result<()> { - log_debug_message(self.debug, "daemon upstream -> ", message); + 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)?; @@ -314,7 +315,7 @@ impl Daemon { } if forwarded_client_request { - return self.write_client_response(message); + return self.enqueue_client_message(message).map(|_| ()); } return Ok(()); @@ -337,7 +338,7 @@ impl Daemon { client .pending_server_requests .insert(id_key(&request_id), request_id.clone()); - return self.write_client_response(message); + return self.enqueue_client_message(message).map(|_| ()); } let response = local_server_request_response(&request_id, method); @@ -345,7 +346,7 @@ impl Daemon { } if self.active_client.is_some() { - return self.write_client_response(message); + return self.enqueue_client_message(message).map(|_| ()); } Ok(()) diff --git a/src/commands/daemon/lifecycle.rs b/src/commands/daemon/lifecycle.rs index d5795ef..d85e2f2 100644 --- a/src/commands/daemon/lifecycle.rs +++ b/src/commands/daemon/lifecycle.rs @@ -4,10 +4,6 @@ use super::{ }; use crate::error::{Error, Result}; use crate::lsp::jsonrpc; -use crate::lsp::transport::log_debug_message; -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; @@ -68,7 +64,7 @@ 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)?; - log_lsp_server_starting(); + self.logger.server_starting(); self.process = Some(ProcessWorker::spawn(spec, generation, &self.events)?); self.lifecycle = LifecycleState::Starting { generation, @@ -108,11 +104,11 @@ impl Daemon { ) { return Ok(()); } - log_lsp_server_started(io.pid); + self.logger.server_started(io.pid); self.upstream = Some(UpstreamServer::from_io( io, generation, - self.debug, + self.logger.clone(), &self.events, )?); self.lifecycle = LifecycleState::Running; @@ -135,7 +131,7 @@ impl Daemon { if initial { return Err(Error::unexpected(message)); } - log_unexpected_error(&message); + self.logger.unexpected(&message); self.fail_pending_initialize(&message)?; } ProcessEvent::Exited(result) => self.handle_process_exit(generation, result)?, @@ -178,8 +174,8 @@ impl Daemon { } self.process.take(); match result { - Ok(status) => log_lsp_server_exit(status), - Err(error) => log_unexpected_error(&error), + Ok(status) => self.logger.server_exited(status), + Err(error) => self.logger.unexpected(error), } self.orphaned_client_requests.clear(); match after { @@ -288,7 +284,7 @@ impl Daemon { Shutdown::METHOD, &(), )?; - log_debug_message(self.debug, "daemon upstream <- ", &shutdown); + self.logger.debug_value("daemon upstream <- ", &shutdown); if upstream.writer.enqueue(&shutdown).is_err() { self.force_stop(generation, after); return Ok(()); @@ -315,7 +311,7 @@ impl Daemon { return Ok(true); }; let exit = jsonrpc::(None, Exit::METHOD, &())?; - log_debug_message(self.debug, "daemon upstream <- ", &exit); + self.logger.debug_value("daemon upstream <- ", &exit); let Some(upstream) = self.upstream.as_mut() else { self.force_stop(generation, after); return Ok(true); @@ -407,7 +403,7 @@ impl Daemon { if let Some(process) = self.process.as_ref() && let Err(error) = process.force_stop() { - log_unexpected_error(&error.to_string()); + self.logger.unexpected(error); } self.lifecycle = LifecycleState::Killing { generation, after }; } @@ -417,10 +413,10 @@ impl UpstreamServer { pub(super) fn from_io( io: super::process_worker::ProcessIo, generation: u64, - debug: bool, + logger: super::Logger, events: &super::events::EventQueue, ) -> Result { - let stderr = crate::server_stderr::CapturedStderr::spawn(io.stderr, debug); + let stderr = crate::server_stderr::CapturedStderr::spawn_with(io.stderr, logger); let reader = super::events::ReaderWorker::spawn( io.stdout, super::events::Source::Upstream(generation), 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 index c43664f..6a073ea 100644 --- a/src/commands/daemon/outputs.rs +++ b/src/commands/daemon/outputs.rs @@ -2,7 +2,6 @@ use super::Daemon; use super::events::Source; use super::writer::WriterEvent; use crate::error::Result; -use crate::system_log::log_unexpected_error; use std::time::Instant; impl Daemon { @@ -29,7 +28,7 @@ impl Daemon { } } (Source::Client(generation), WriterEvent::Failed { id, error }) => { - log_unexpected_error(&format!( + self.logger.unexpected(format!( "daemon client output failed while writing message {id}: {error}" )); if self.pending_connections.remove(&generation).is_none() @@ -55,7 +54,7 @@ impl Daemon { .as_ref() .is_some_and(|upstream| upstream.generation == generation) { - log_unexpected_error(&format!( + self.logger.unexpected(format!( "LSP server stopped accepting message {id}: {error}" )); self.upstream_failed(); @@ -85,9 +84,8 @@ impl Daemon { .as_mut() .is_some_and(|client| client.writer.timed_out(now, self.write_stall_timeout)) { - log_unexpected_error( - "daemon client was disconnected because it stopped reading output", - ); + self.logger + .unexpected("daemon client was disconnected because it stopped reading output"); self.disconnect_client()?; } if self @@ -95,7 +93,8 @@ impl Daemon { .as_mut() .is_some_and(|upstream| upstream.writer.timed_out(now, self.write_stall_timeout)) { - log_unexpected_error("LSP server was stopped because it stopped reading daemon output"); + self.logger + .unexpected("LSP server was stopped because it stopped reading daemon output"); self.upstream_failed(); } Ok(()) diff --git a/src/commands/daemon/protocol.rs b/src/commands/daemon/protocol.rs index 56dba1e..5f76e38 100644 --- a/src/commands/daemon/protocol.rs +++ b/src/commands/daemon/protocol.rs @@ -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), } diff --git a/src/commands/daemon/session_tests.rs b/src/commands/daemon/session_tests.rs index 7270e4a..add123b 100644 --- a/src/commands/daemon/session_tests.rs +++ b/src/commands/daemon/session_tests.rs @@ -20,7 +20,9 @@ impl Fixture { let dir = TestDir::new("daemon-session"); let target = tests::daemon_target(&dir); let mut events = EventQueue::new(); - let (upstream, process) = fake_upstream(&mut events); + 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"); @@ -31,6 +33,8 @@ impl Fixture { socket_owned: true, target, debug: false, + logger, + logger_worker, idle_timeout: TIMEOUT, write_stall_timeout: TIMEOUT, upstream: Some(upstream), @@ -152,7 +156,7 @@ impl Fixture { } } -fn fake_upstream(events: &mut EventQueue) -> (UpstreamServer, ProcessWorker) { +fn fake_upstream(events: &mut EventQueue, logger: Logger) -> (UpstreamServer, ProcessWorker) { let child = with_env_vars(&[], || { Command::new("python3") .arg(concat!( @@ -168,7 +172,7 @@ fn fake_upstream(events: &mut EventQueue) -> (UpstreamServer, ProcessWorker) { }); let generation = events.next_generation().expect("upstream generation"); let (process, io) = ProcessWorker::adopt(child, generation, events); - let upstream = UpstreamServer::from_io(io, generation, false, events).expect("upstream"); + let upstream = UpstreamServer::from_io(io, generation, logger, events).expect("upstream"); (upstream, process) } @@ -218,7 +222,8 @@ fn stale_generations_cannot_modify_replacement_sessions() { fixture.replace_client(); fixture.daemon.upstream.take(); fixture.daemon.process.take(); - let (upstream, process) = fake_upstream(&mut fixture.daemon.events); + 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; @@ -236,7 +241,7 @@ fn stale_generations_cannot_modify_replacement_sessions() { .generation; for source in [Source::Client(old_client), Source::Upstream(old_upstream)] { for event in [ - ReaderEvent::Message(json!({"id": 9, "method": "exit"})), + ReaderEvent::Message(json!({"id": 9, "method": "exit"}).into()), ReaderEvent::EndOfStream, ReaderEvent::Error("retired".into()), ] { diff --git a/src/commands/daemon/tests.rs b/src/commands/daemon/tests.rs index 01e8f0c..273742e 100644 --- a/src/commands/daemon/tests.rs +++ b/src/commands/daemon/tests.rs @@ -10,6 +10,7 @@ use serde_json::json; use std::fs; use std::io::BufReader; use std::os::unix::net::{UnixListener, UnixStream}; +use std::sync::Arc; use std::thread; pub(super) fn daemon_target(dir: &TestDir) -> super::DaemonTarget { @@ -275,6 +276,8 @@ fn window_fixture() -> (super::Daemon, UnixStream, TestDir) { 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 child = Command::new("/bin/cat") .stdin(Stdio::piped()) @@ -284,7 +287,8 @@ fn window_fixture() -> (super::Daemon, UnixStream, TestDir) { .expect("start echo process"); let generation = events.next_generation().expect("generation"); let (process, io) = super::ProcessWorker::adopt(child, generation, &events); - let upstream = UpstreamServer::from_io(io, generation, false, &events).expect("upstream"); + 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))) @@ -297,6 +301,8 @@ fn window_fixture() -> (super::Daemon, UnixStream, TestDir) { 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), @@ -324,7 +330,7 @@ fn receive_forwarded(daemon: &mut super::Daemon, expected: &serde_json::Value) { .expect("forwarded message"); match delivery.event { Event::Reader(Source::Upstream(_), ReaderEvent::Message(message)) => { - assert_eq!(message, *expected); + assert_eq!(*message, *expected); let _ = delivery.acknowledge.send(()); return; } @@ -346,7 +352,7 @@ fn forwards_multiple_requests_and_out_of_order_responses() { 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"); receive_forwarded(&mut daemon, &request); expected.insert(id, json!({"jsonrpc":"2.0","id":id,"result":[]})); @@ -363,7 +369,7 @@ 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"), diff --git a/src/server_stderr.rs b/src/server_stderr.rs index dfa21fb..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 } @@ -83,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); @@ -109,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() { @@ -126,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); } } From 92b562e5afd5eccbbd7346564d7637e6a824d165 Mon Sep 17 00:00:00 2001 From: Vasily Kulikov Date: Sat, 5 Sep 2026 19:43:59 +0300 Subject: [PATCH 7/7] Remove fixed initialization grace --- GOTCHAS.md | 7 +- src/lsp/client.rs | 4 + src/lsp/client/requests.rs | 30 +-- src/lsp/client/test_support.rs | 24 +++ src/lsp/client/tests.rs | 254 +------------------------ src/lsp/client/tests_initialization.rs | 216 +++++++++++++++++++++ 6 files changed, 254 insertions(+), 281 deletions(-) create mode 100644 src/lsp/client/test_support.rs create mode 100644 src/lsp/client/tests_initialization.rs diff --git a/GOTCHAS.md b/GOTCHAS.md index 6a12bb4..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 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(); +}