From 8cd384e3812c4ed51d72a30493fc8fe7ad6a4dce Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Wed, 11 Dec 2024 10:19:16 -0500 Subject: [PATCH 01/15] Teach `log::` and tracing::` to send `window/logMessage` messages --- Cargo.lock | 155 ++++++++++++++++++++++++++ Cargo.toml | 2 + crates/lsp/Cargo.toml | 2 + crates/lsp/src/handlers_state.rs | 10 +- crates/lsp/src/lib.rs | 1 + crates/lsp/src/logging.rs | 181 +++++++++++++++++++++++++++++++ crates/lsp/src/main_loop.rs | 62 +---------- crates/lsp/src/tower_lsp.rs | 12 +- 8 files changed, 359 insertions(+), 66 deletions(-) create mode 100644 crates/lsp/src/logging.rs diff --git a/Cargo.lock b/Cargo.lock index 8e4a7fc7..3679a2b8 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -678,6 +678,15 @@ dependencies = [ "parking_lot_core", ] +[[package]] +name = "deranged" +version = "0.3.11" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b42b6fa04a440b495c8b04d0e71b707c585f83cb9cb28cf8cd0d976c315e31b4" +dependencies = [ + "powerfmt", +] + [[package]] name = "displaydoc" version = "0.2.5" @@ -1291,10 +1300,12 @@ dependencies = [ "serde_json", "struct-field-names-as-array", "tests_macros", + "time", "tokio", "tokio-util", "tower-lsp 0.20.0 (git+https://github.com/lionel-/tower-lsp?branch=bugfix%2Fpatches)", "tracing", + "tracing-subscriber", "tree-sitter", "tree-sitter-r", "triomphe", @@ -1360,6 +1371,31 @@ dependencies = [ "windows-sys 0.52.0", ] +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + +[[package]] +name = "num-conv" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "51d515d32fb182ee37cda2ccdcb92950d6a3c2893aa280e540671c2cd0f3b1d9" + +[[package]] +name = "num_threads" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5c7398b9c8b70908f6371f47ed36737907c87c52af34c268fed0bf0ceb92ead9" +dependencies = [ + "libc", +] + [[package]] name = "object" version = "0.36.5" @@ -1375,6 +1411,12 @@ version = "1.20.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1261fe7e33c73b354eab43b1273a57c8f967d0391e80353e51f764ac02cf6775" +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "oxc_resolver" version = "1.12.0" @@ -1480,6 +1522,12 @@ version = "0.3.31" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "953ec861398dccce10c670dfeaf3ec4911ca479e9c02154b3a215178c5f566f2" +[[package]] +name = "powerfmt" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "439ee305def115ba05938db6eb1644ff94165c5ab5e9420d1c1bcedbba909391" + [[package]] name = "proc-macro-error" version = "1.0.4" @@ -1751,6 +1799,15 @@ dependencies = [ "syn 2.0.90", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.3.0" @@ -1979,6 +2036,49 @@ dependencies = [ "syn 2.0.90", ] +[[package]] +name = "thread_local" +version = "1.1.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c" +dependencies = [ + "cfg-if", + "once_cell", +] + +[[package]] +name = "time" +version = "0.3.37" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "35e7868883861bd0e56d9ac6efcaaca0d6d5d82a2a7ec8209ff492c07cf37b21" +dependencies = [ + "deranged", + "itoa", + "libc", + "num-conv", + "num_threads", + "powerfmt", + "serde", + "time-core", + "time-macros", +] + +[[package]] +name = "time-core" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ef927ca75afb808a4d64dd374f00a2adf8d0fcff8e7b184af886c3c87ec4a3f3" + +[[package]] +name = "time-macros" +version = "0.2.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2834e6017e3e5e4b9834939793b282bc03b37a3336245fa820e35e233e2a85de" +dependencies = [ + "num-conv", + "time-core", +] + [[package]] name = "tinystr" version = "0.7.6" @@ -2152,6 +2252,33 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c06d3da6113f116aaee68e4d601191614c9053067f9ab7f6edbcb161237daa54" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e8189decb5ac0fa7bc8b96b7cb9b2701d60d48805aca84a238004d665fcc4008" +dependencies = [ + "nu-ansi-term", + "sharded-slab", + "smallvec", + "thread_local", + "time", + "tracing-core", + "tracing-log", ] [[package]] @@ -2276,6 +2403,12 @@ dependencies = [ "getrandom", ] +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "vcpkg" version = "0.2.15" @@ -2319,6 +2452,22 @@ dependencies = [ "rustls-pki-types", ] +[[package]] +name = "winapi" +version = "0.3.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5c839a674fcd7a98952e593242ea400abe93992746761e38641405d28b00f419" +dependencies = [ + "winapi-i686-pc-windows-gnu", + "winapi-x86_64-pc-windows-gnu", +] + +[[package]] +name = "winapi-i686-pc-windows-gnu" +version = "0.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6" + [[package]] name = "winapi-util" version = "0.1.9" @@ -2328,6 +2477,12 @@ dependencies = [ "windows-sys 0.59.0", ] +[[package]] +name = "winapi-x86_64-pc-windows-gnu" +version = "0.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "712e227841d057c1ee1cd2fb22fa7e5a5461ae8e48fa2ca79ec42cfc1931183f" + [[package]] name = "windows-sys" version = "0.52.0" diff --git a/Cargo.toml b/Cargo.toml index ee989634..f2cb06c3 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -62,12 +62,14 @@ proc-macro2 = "1.0.86" serde = { version = "1.0.215", features = ["derive"] } serde_json = "1.0.132" struct-field-names-as-array = "0.3.0" +time = "0.3.37" thiserror = "2.0.5" tokio = { version = "1.41.1" } tokio-util = "0.7.12" # For https://github.com/ebkalderon/tower-lsp/pull/428 tower-lsp = { git = "https://github.com/lionel-/tower-lsp", branch = "bugfix/patches" } tracing = { version = "0.1.40", default-features = false, features = ["std"] } +tracing-subscriber = "0.3.19" tree-sitter = "0.23.0" tree-sitter-r = { git = "https://github.com/r-lib/tree-sitter-r", rev = "a0d3e3307489c3ca54da8c7b5b4e0c5f5fd6953a" } triomphe = "0.1.14" diff --git a/crates/lsp/Cargo.toml b/crates/lsp/Cargo.toml index 8eab38e0..863cfa72 100644 --- a/crates/lsp/Cargo.toml +++ b/crates/lsp/Cargo.toml @@ -30,9 +30,11 @@ memchr.workspace = true serde.workspace = true serde_json.workspace = true struct-field-names-as-array.workspace = true +time = { workspace = true } tokio = { workspace = true, features = ["full"] } tower-lsp.workspace = true tracing.workspace = true +tracing-subscriber = { workspace = true, features = ["ansi", "local-time"] } tree-sitter.workspace = true tree-sitter-r.workspace = true triomphe.workspace = true diff --git a/crates/lsp/src/handlers_state.rs b/crates/lsp/src/handlers_state.rs index 486bd478..0c17f182 100644 --- a/crates/lsp/src/handlers_state.rs +++ b/crates/lsp/src/handlers_state.rs @@ -33,6 +33,7 @@ use crate::config::DocumentConfig; use crate::config::VscDiagnosticsConfig; use crate::config::VscDocumentConfig; use crate::documents::Document; +use crate::logging; use crate::main_loop::AuxiliaryEventSender; use crate::main_loop::LspState; use crate::state::workspace_uris; @@ -62,7 +63,13 @@ pub(crate) fn initialize( params: InitializeParams, lsp_state: &mut LspState, state: &mut WorldState, + auxiliary_event_tx: &AuxiliaryEventSender, ) -> anyhow::Result { + // TODO: Get default log level from `params.initialization_options` + // and `AIR_LOG` env var. + let log_level = logging::LogLevel::Trace; + logging::init_logging(auxiliary_event_tx.clone(), log_level, ¶ms.client_info); + // Defaults to UTF-16 let mut position_encoding = None; @@ -157,7 +164,6 @@ pub(crate) fn did_change( pub(crate) fn did_close( params: DidCloseTextDocumentParams, state: &mut WorldState, - auxiliary_event_tx: &AuxiliaryEventSender, ) -> anyhow::Result<()> { let uri = params.text_document.uri; @@ -169,7 +175,7 @@ pub(crate) fn did_close( .remove(&uri) .ok_or(anyhow!("Failed to remove document for URI: {uri}"))?; - auxiliary_event_tx.log_info(format!("did_close(): closed document with URI: '{uri}'.")); + log::info!("did_close(): closed document with URI: '{uri}'."); Ok(()) } diff --git a/crates/lsp/src/lib.rs b/crates/lsp/src/lib.rs index 5336aa9a..b8a362db 100644 --- a/crates/lsp/src/lib.rs +++ b/crates/lsp/src/lib.rs @@ -11,6 +11,7 @@ pub mod handlers; pub mod handlers_ext; pub mod handlers_format; pub mod handlers_state; +pub mod logging; pub mod main_loop; pub mod rust_analyzer; pub mod state; diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs new file mode 100644 index 00000000..df080b0f --- /dev/null +++ b/crates/lsp/src/logging.rs @@ -0,0 +1,181 @@ +// --- source +// authors = ["Charlie Marsh"] +// license = "MIT" +// origin = "https://github.com/astral-sh/ruff/blob/03fb2e5ac1481e498f84474800b42a966e9843e1/crates/ruff_server/src/trace.rs" +// --- + +//! The logging system for `air lsp`. +//! +//! Logs are controlled by the `air.server.log` setting in VS Code, +//! passed through `InitializeParams` in the arbitrary `initializationOptions` field. +//! +//! Logs are also controlled by the `AIR_LOG` environment variable. This is preferred +//! over the extension setting, but it is unlikely to see them both be used together. +//! This can be used by other LSP clients if there is no easy way to set `initializationOptions`. +//! +//! By default, we fallback to `"info"`. +//! +//! For VS Code and Zed, which are known to support `window/logMessage` well, logging will +//! emit a `window/logMessage` message. Otherwise, logging will write to `stderr`, +//! which should appear in the logs for most LSP clients. +use core::str; +use lsp_types::ClientInfo; +use serde::Deserialize; +use std::io::{Error as IoError, ErrorKind, Write}; +use tower_lsp::lsp_types; +use tower_lsp::lsp_types::MessageType; +use tracing::level_filters::LevelFilter; +use tracing_subscriber::fmt::time::LocalTime; +use tracing_subscriber::{ + fmt::{writer::BoxMakeWriter, MakeWriter}, + layer::SubscriberExt, + Layer, +}; + +use crate::main_loop::AuxiliaryEventSender; + +// TODO: +// - Add `air.server.log` as a VS Code extension option that sets the log level, +// and pass it through the arbitrary `initializationOptions` field of `InitializeParams`. +// - Add `AIR_LOG` environment variable that sets the log level as well, and prefer this +// over the extension option as its the "harder" thing to set. + +// A log writer that uses LSPs logMessage method. +struct LogWriter<'a> { + auxiliary_event_tx: &'a AuxiliaryEventSender, +} + +impl<'a> LogWriter<'a> { + fn new(auxiliary_event_tx: &'a AuxiliaryEventSender) -> Self { + Self { auxiliary_event_tx } + } +} + +impl Write for LogWriter<'_> { + // We use `MessageType::LOG` to prevent the middleware from adding its own + // timestamp and log level labels. We add that ourselves through tracing. + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let message = str::from_utf8(buf).map_err(|e| IoError::new(ErrorKind::InvalidData, e))?; + + self.auxiliary_event_tx + .send(crate::main_loop::AuxiliaryEvent::Log( + MessageType::LOG, + message.to_string(), + )) + .map_err(|e| IoError::new(ErrorKind::Other, e))?; + + Ok(buf.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } +} + +struct LogWriterMaker { + auxiliary_event_tx: AuxiliaryEventSender, +} + +impl LogWriterMaker { + fn new(auxiliary_event_tx: AuxiliaryEventSender) -> Self { + Self { auxiliary_event_tx } + } +} + +impl<'a> MakeWriter<'a> for LogWriterMaker { + type Writer = LogWriter<'a>; + + fn make_writer(&'a self) -> Self::Writer { + // We expect `make_writer_for()` to be called instead, but provide this just in case + LogWriter::new(&self.auxiliary_event_tx) + } +} + +pub(crate) fn init_logging( + auxiliary_event_tx: AuxiliaryEventSender, + log_level: LogLevel, + client_info: &Option, +) { + let writer = if client_info.as_ref().is_some_and(|client_info| { + client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code") + }) { + BoxMakeWriter::new(LogWriterMaker::new(auxiliary_event_tx)) + } else { + BoxMakeWriter::new(std::io::stderr) + }; + + let layer = tracing_subscriber::fmt::layer() + // Disable ANSI escapes, those are not supported in Code + .with_ansi(false) + // Display source code file paths + .with_file(true) + // Display source code line numbers + .with_line_number(true) + // Don't display the thread ID or thread name + .with_thread_ids(false) + .with_thread_names(false) + // Don't display the event's target (module path). + // Mostly redundant with file paths. + .with_target(false) + // Display local time rather than UTC + .with_timer(LocalTime::rfc_3339()) + // Display the log level + .with_level(true) + .with_writer(writer) + .with_filter(LogLevelFilter { filter: log_level }); + + let subscriber = tracing_subscriber::Registry::default().with(layer); + + tracing::subscriber::set_global_default(subscriber) + .expect("Should be able to set global default subscriber"); +} + +#[derive(Clone, Copy, Debug, Deserialize, Default, PartialEq, Eq, PartialOrd, Ord)] +#[serde(rename_all = "lowercase")] +pub(crate) enum LogLevel { + Error, + Warn, + #[default] + Info, + Debug, + Trace, +} + +impl LogLevel { + fn tracing_level(self) -> tracing::Level { + match self { + Self::Error => tracing::Level::ERROR, + Self::Warn => tracing::Level::WARN, + Self::Info => tracing::Level::INFO, + Self::Debug => tracing::Level::DEBUG, + Self::Trace => tracing::Level::TRACE, + } + } +} + +/// Filters out logs which have a log level lower than the level set by the client. +struct LogLevelFilter { + filter: LogLevel, +} + +impl tracing_subscriber::layer::Filter for LogLevelFilter { + fn enabled( + &self, + meta: &tracing::Metadata<'_>, + _: &tracing_subscriber::layer::Context<'_, S>, + ) -> bool { + // This is a potential reason to use `air_` as the crate prefix, + // it would make it easy to set the `tracing_level()` for only air related crates + let filter = if meta.target().starts_with("air") || meta.target().starts_with("lsp") { + self.filter.tracing_level() + } else { + tracing::Level::INFO + }; + + meta.level() <= &filter + } + + fn max_level_hint(&self) -> Option { + Some(LevelFilter::from_level(self.filter.tracing_level())) + } +} diff --git a/crates/lsp/src/main_loop.rs b/crates/lsp/src/main_loop.rs index 23b5af79..0a64e34b 100644 --- a/crates/lsp/src/main_loop.rs +++ b/crates/lsp/src/main_loop.rs @@ -85,42 +85,6 @@ impl AuxiliaryEventSender { self.inner.send(message) } - pub(crate) fn log_info(&self, message: String) { - self.log(MessageType::INFO, message); - } - pub(crate) fn log_warn(&self, message: String) { - self.log(MessageType::WARNING, message); - } - pub(crate) fn log_error(&self, message: String) { - self.log(MessageType::ERROR, message); - } - - /// Send an `AuxiliaryEvent::Log` message in a non-blocking way - fn log(&self, level: lsp_types::MessageType, message: String) { - // We're not connected to an LSP client when running unit tests - if cfg!(test) { - return; - } - - // Check that channel is still alive in case the LSP was closed. - // If closed, fallthrough. - if self - .send(AuxiliaryEvent::Log(level, message.clone())) - .is_ok() - { - return; - } - - // Log to the kernel as fallback - log::warn!("LSP channel is closed, redirecting messages to Jupyter kernel"); - - match level { - MessageType::ERROR => log::error!("{message}"), - MessageType::WARNING => log::warn!("{message}"), - _ => log::info!("{message}"), - }; - } - /// Spawn a blocking task /// /// This runs tasks that do semantic analysis on a separate thread pool to avoid @@ -246,7 +210,6 @@ impl GlobalState { // Transmission channel for the main loop events. Shared with the // tower-lsp backend and the Jupyter kernel. let (events_tx, events_rx) = tokio_unbounded_channel::(); - let (auxiliary_state, auxiliary_event_tx) = AuxiliaryState::new(client.clone()); Self { @@ -300,7 +263,7 @@ impl GlobalState { loop { let event = self.next_event().await; match self.handle_event(event).await { - Err(err) => self.log_error(format!("Failure while handling event:\n{err:?}")), + Err(err) => tracing::info!("Failure while handling event:\n{err:?}"), Ok(LoopControl::Shutdown) => break, _ => {} } @@ -360,7 +323,7 @@ impl GlobalState { // Currently ignored }, LspNotification::DidCloseTextDocument(params) => { - handlers_state::did_close(params, &mut self.world, &self.auxiliary_event_tx)?; + handlers_state::did_close(params, &mut self.world)?; }, } }, @@ -368,7 +331,7 @@ impl GlobalState { LspMessage::Request(request, tx) => { match request { LspRequest::Initialize(params) => { - respond(tx, handlers_state::initialize(params, &mut self.lsp_state, &mut self.world), LspResponse::Initialize)?; + respond(tx, handlers_state::initialize(params, &mut self.lsp_state, &mut self.world, &self.auxiliary_event_tx), LspResponse::Initialize)?; }, LspRequest::Shutdown => { out = LoopControl::Shutdown; @@ -393,7 +356,7 @@ impl GlobalState { // TODO Make this threshold configurable by the client if loop_tick.elapsed() > std::time::Duration::from_millis(50) { - self.log_info(format!("Handler took {}ms", loop_tick.elapsed().as_millis())); + tracing::info!("Handler took {}ms", loop_tick.elapsed().as_millis()); } Ok(out) @@ -422,16 +385,6 @@ impl GlobalState { respond(response_tx, handler(), into_lsp_response).and(Ok(None)) }); } - - fn log_info(&self, message: String) { - self.auxiliary_event_tx.log_info(message); - } - fn log_warn(&self, message: String) { - self.auxiliary_event_tx.log_warn(message); - } - fn log_error(&self, message: String) { - self.auxiliary_event_tx.log_error(message); - } } /// Respond to a request from the LSP @@ -529,8 +482,8 @@ impl AuxiliaryState { Ok(Ok(Some(event))) => return event, // Otherwise relay any errors and loop back into select - Err(err) => self.log_error(format!("A task panicked:\n{err:?}")).await, - Ok(Err(err)) => self.log_error(format!("A task failed:\n{err:?}")).await, + Err(err) => self.log(MessageType::ERROR, format!("A task panicked:\n{err:?}")).await, + Ok(Err(err)) => self.log(MessageType::ERROR, format!("A task failed:\n{err:?}")).await, _ => (), }, } @@ -540,7 +493,4 @@ impl AuxiliaryState { async fn log(&self, level: MessageType, message: String) { self.client.log_message(level, message).await } - async fn log_error(&self, message: String) { - self.client.log_message(MessageType::ERROR, message).await - } } diff --git a/crates/lsp/src/tower_lsp.rs b/crates/lsp/src/tower_lsp.rs index d0b0a717..cc45da3c 100644 --- a/crates/lsp/src/tower_lsp.rs +++ b/crates/lsp/src/tower_lsp.rs @@ -89,7 +89,7 @@ struct Backend { impl Backend { async fn request(&self, request: LspRequest) -> anyhow::Result { - self.log_info(format!("Incoming: {request:#?}")); + tracing::info!("Incoming:\n{request:#?}"); let (response_tx, mut response_rx) = tokio_unbounded_channel::>(); @@ -102,12 +102,12 @@ impl Backend { // Wait for response from main loop let out = response_rx.recv().await.unwrap()?; - self.log_info(format!("Outgoing {out:#?}")); + tracing::info!("Outgoing\n{out:#?}"); Ok(out) } fn notify(&self, notif: LspNotification) { - self.log_info(format!("Incoming: {notif:#?}")); + tracing::info!("Incoming:\n{notif:#?}"); // Relay notification to main loop self.events_tx @@ -121,10 +121,6 @@ impl Backend { LspResponse::AirViewFile ) } - - fn log_info(&self, message: String) { - self.auxiliary_event_tx.log_info(message); - } } #[tower_lsp::async_trait] @@ -194,7 +190,7 @@ where let server = tower_lsp::Server::new(read, write, socket); server.serve(service).await; - log::trace!("LSP exiting gracefully.",); + log::trace!("LSP exiting gracefully."); } fn new_lsp() -> (LspService, ClientSocket) { From c4b669c869079ff109ca39c3af4f1c2c80812d74 Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Wed, 11 Dec 2024 11:43:33 -0500 Subject: [PATCH 02/15] Put logging on its own thread This completely isolates it, and also allows us to maintain all logging related logic in `logging.rs` --- crates/lsp/src/handlers_state.rs | 17 ++++-- crates/lsp/src/logging.rs | 90 +++++++++++++++++++++----------- crates/lsp/src/main_loop.rs | 79 +++++++++++++--------------- crates/lsp/src/tower_lsp.rs | 14 +---- 4 files changed, 110 insertions(+), 90 deletions(-) diff --git a/crates/lsp/src/handlers_state.rs b/crates/lsp/src/handlers_state.rs index 0c17f182..fe8c0d0b 100644 --- a/crates/lsp/src/handlers_state.rs +++ b/crates/lsp/src/handlers_state.rs @@ -34,7 +34,7 @@ use crate::config::VscDiagnosticsConfig; use crate::config::VscDocumentConfig; use crate::documents::Document; use crate::logging; -use crate::main_loop::AuxiliaryEventSender; +use crate::logging::LogMessageSender; use crate::main_loop::LspState; use crate::state::workspace_uris; use crate::state::WorldState; @@ -63,12 +63,23 @@ pub(crate) fn initialize( params: InitializeParams, lsp_state: &mut LspState, state: &mut WorldState, - auxiliary_event_tx: &AuxiliaryEventSender, + log_tx: LogMessageSender, ) -> anyhow::Result { + let client_info = params.client_info.as_ref(); + // TODO: Get default log level from `params.initialization_options` // and `AIR_LOG` env var. let log_level = logging::LogLevel::Trace; - logging::init_logging(auxiliary_event_tx.clone(), log_level, ¶ms.client_info); + + let log_tx = if client_info.is_some_and(|client_info| { + client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code") + }) { + Some(log_tx) + } else { + None + }; + + logging::init_logging(log_tx, log_level); // Defaults to UTF-16 let mut position_encoding = None; diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index df080b0f..939a21b7 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -19,11 +19,11 @@ //! emit a `window/logMessage` message. Otherwise, logging will write to `stderr`, //! which should appear in the logs for most LSP clients. use core::str; -use lsp_types::ClientInfo; use serde::Deserialize; use std::io::{Error as IoError, ErrorKind, Write}; -use tower_lsp::lsp_types; +use tokio::sync::mpsc::unbounded_channel; use tower_lsp::lsp_types::MessageType; +use tower_lsp::Client; use tracing::level_filters::LevelFilter; use tracing_subscriber::fmt::time::LocalTime; use tracing_subscriber::{ @@ -32,36 +32,72 @@ use tracing_subscriber::{ Layer, }; -use crate::main_loop::AuxiliaryEventSender; - // TODO: // - Add `air.server.log` as a VS Code extension option that sets the log level, // and pass it through the arbitrary `initializationOptions` field of `InitializeParams`. // - Add `AIR_LOG` environment variable that sets the log level as well, and prefer this // over the extension option as its the "harder" thing to set. +pub(crate) struct LogMessage { + contents: String, +} + +pub(crate) type LogMessageSender = tokio::sync::mpsc::UnboundedSender; +pub(crate) type LogMessageReceiver = tokio::sync::mpsc::UnboundedReceiver; + +pub(crate) struct LogState { + client: Client, + log_rx: LogMessageReceiver, +} + +// Needed for spawning the loop +unsafe impl Sync for LogState {} + +impl LogState { + pub(crate) fn new(client: Client) -> (Self, LogMessageSender) { + let (log_tx, log_rx) = unbounded_channel::(); + let state = Self { client, log_rx }; + (state, log_tx) + } + + /// Start the log loop + /// + /// Takes ownership of log state and start the low-latency log loop. + /// + /// We use `MessageType::LOG` to prevent the middleware from adding its own + /// timestamp and log level labels. We add that ourselves through tracing. + pub(crate) async fn start(mut self) { + while let Some(message) = self.log_rx.recv().await { + self.client + .log_message(MessageType::LOG, message.contents) + .await + } + + // Channel has been closed. + // All senders have been dropped or `close()` was called. + } +} + // A log writer that uses LSPs logMessage method. struct LogWriter<'a> { - auxiliary_event_tx: &'a AuxiliaryEventSender, + log_tx: &'a LogMessageSender, } impl<'a> LogWriter<'a> { - fn new(auxiliary_event_tx: &'a AuxiliaryEventSender) -> Self { - Self { auxiliary_event_tx } + fn new(log_tx: &'a LogMessageSender) -> Self { + Self { log_tx } } } impl Write for LogWriter<'_> { - // We use `MessageType::LOG` to prevent the middleware from adding its own - // timestamp and log level labels. We add that ourselves through tracing. fn write(&mut self, buf: &[u8]) -> std::io::Result { - let message = str::from_utf8(buf).map_err(|e| IoError::new(ErrorKind::InvalidData, e))?; + let contents = str::from_utf8(buf).map_err(|e| IoError::new(ErrorKind::InvalidData, e))?; + let contents = contents.to_string(); - self.auxiliary_event_tx - .send(crate::main_loop::AuxiliaryEvent::Log( - MessageType::LOG, - message.to_string(), - )) + // Forward the log message to the latency sensitive log thread, + // which is in charge of forwarding to the client in an async manner. + self.log_tx + .send(LogMessage { contents }) .map_err(|e| IoError::new(ErrorKind::Other, e))?; Ok(buf.len()) @@ -73,12 +109,12 @@ impl Write for LogWriter<'_> { } struct LogWriterMaker { - auxiliary_event_tx: AuxiliaryEventSender, + log_tx: LogMessageSender, } impl LogWriterMaker { - fn new(auxiliary_event_tx: AuxiliaryEventSender) -> Self { - Self { auxiliary_event_tx } + fn new(log_tx: LogMessageSender) -> Self { + Self { log_tx } } } @@ -86,22 +122,14 @@ impl<'a> MakeWriter<'a> for LogWriterMaker { type Writer = LogWriter<'a>; fn make_writer(&'a self) -> Self::Writer { - // We expect `make_writer_for()` to be called instead, but provide this just in case - LogWriter::new(&self.auxiliary_event_tx) + LogWriter::new(&self.log_tx) } } -pub(crate) fn init_logging( - auxiliary_event_tx: AuxiliaryEventSender, - log_level: LogLevel, - client_info: &Option, -) { - let writer = if client_info.as_ref().is_some_and(|client_info| { - client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code") - }) { - BoxMakeWriter::new(LogWriterMaker::new(auxiliary_event_tx)) - } else { - BoxMakeWriter::new(std::io::stderr) +pub(crate) fn init_logging(log_tx: Option, log_level: LogLevel) { + let writer = match log_tx { + Some(log_tx) => BoxMakeWriter::new(LogWriterMaker::new(log_tx)), + None => BoxMakeWriter::new(std::io::stderr), }; let layer = tracing_subscriber::fmt::layer() diff --git a/crates/lsp/src/main_loop.rs b/crates/lsp/src/main_loop.rs index 0a64e34b..bfb666c1 100644 --- a/crates/lsp/src/main_loop.rs +++ b/crates/lsp/src/main_loop.rs @@ -15,9 +15,7 @@ use biome_lsp_converters::WideEncoding; use futures::StreamExt; use tokio::sync::mpsc::unbounded_channel as tokio_unbounded_channel; use tokio::task::JoinHandle; -use tower_lsp::lsp_types; use tower_lsp::lsp_types::Diagnostic; -use tower_lsp::lsp_types::MessageType; use tower_lsp::Client; use url::Url; @@ -26,6 +24,8 @@ use crate::handlers_ext; use crate::handlers_format; use crate::handlers_state; use crate::handlers_state::ConsoleInputs; +use crate::logging::LogMessageSender; +use crate::logging::LogState; use crate::state::WorldState; use crate::tower_lsp::LspMessage; use crate::tower_lsp::LspNotification; @@ -62,7 +62,6 @@ pub(crate) enum KernelNotification { #[derive(Debug)] pub(crate) enum AuxiliaryEvent { - Log(lsp_types::MessageType, String), PublishDiagnostics(Url, Vec, Option), SpawnedTask(JoinHandle>>), } @@ -90,8 +89,7 @@ impl AuxiliaryEventSender { /// This runs tasks that do semantic analysis on a separate thread pool to avoid /// blocking the main loop. /// - /// Can optionally return an event for the auxiliary loop (i.e. a log message or - /// diagnostics publication). + /// Can optionally return an event for the auxiliary loop (i.e. diagnostics publication). pub(crate) fn spawn_blocking_task(&self, handler: Handler) where Handler: FnOnce() -> anyhow::Result>, @@ -128,22 +126,23 @@ pub(crate) struct GlobalState { /// LSP client shared with tower-lsp and the log loop client: Client, - /// Event channels for the main loop. The tower-lsp methods forward + /// Event receiver channel for the main loop. The tower-lsp methods forward /// notifications and requests here via `Event::Lsp`. We also receive /// messages from the kernel via `Event::Kernel`, and from ourselves via /// `Event::Task`. - events_tx: TokioUnboundedSender, events_rx: TokioUnboundedReceiver, - /// State of the internal auxiliary loop. - /// Fully managed by the `GlobalState`. - /// Initialized as `Some()`, and converted to `None` on `start()`. + /// Auxiliary state that gets moved to the auxiliary thread, + /// and our channel for communicating with that thread. + /// Used for sending latency sensitive events like tasks and diagnostics. auxiliary_state: Option, - - /// Event channel for sending to the auxiliary loop. - /// Used for sending latency sensitive events like logs, tasks, and - /// diagnostics. auxiliary_event_tx: AuxiliaryEventSender, + + /// Log state that gets moved to the log thread, + /// and a channel for communicating with that thread which we + /// pass on to `init_logging()` during `initialize()`. + log_state: Option, + log_tx: Option, } /// Unlike `WorldState`, `ParserState` cannot be cloned and is only accessed by @@ -206,31 +205,26 @@ impl GlobalState { /// /// * `client`: The tower-lsp client shared with the tower-lsp backend /// and auxiliary loop. - pub(crate) fn new(client: Client) -> Self { + pub(crate) fn new(client: Client) -> (Self, TokioUnboundedSender) { // Transmission channel for the main loop events. Shared with the // tower-lsp backend and the Jupyter kernel. let (events_tx, events_rx) = tokio_unbounded_channel::(); + + let (log_state, log_tx) = LogState::new(client.clone()); let (auxiliary_state, auxiliary_event_tx) = AuxiliaryState::new(client.clone()); - Self { + let state = Self { world: WorldState::default(), lsp_state: LspState::default(), client, + events_rx, auxiliary_state: Some(auxiliary_state), auxiliary_event_tx, - events_tx, - events_rx, - } - } - - /// Get `Event` transmission channel - pub(crate) fn events_tx(&self) -> TokioUnboundedSender { - self.events_tx.clone() - } + log_state: Some(log_state), + log_tx: Some(log_tx), + }; - /// Get `AuxiliaryEvent` transmission channel - pub(crate) fn auxiliary_event_tx(&self) -> AuxiliaryEventSender { - self.auxiliary_event_tx.clone() + (state, events_tx) } /// Start the main and auxiliary loops @@ -251,12 +245,16 @@ impl GlobalState { /// This takes ownership of all global state and handles one by one LSP /// requests, notifications, and other internal events. async fn main_loop(mut self) { - // Spawn latency-sensitive auxiliary loop. Must be first to initialise - // global transmission channel. + // Spawn latency-sensitive auxiliary and log threads. let mut set = tokio::task::JoinSet::<()>::new(); - // Move the `auxiliary_state` owned by the global state to its own thread. - // Unwrap: `start()` should only ever be called once. + // Take ownership over `log_state` and start the log thread. + // Unwrap: `start()` should only be called once. + let log_state = self.log_state.take().unwrap(); + set.spawn(async move { log_state.start().await }); + + // Take ownership over `auxiliary_state` and start the auxiliary thread. + // Unwrap: `start()` should only be called once. let auxiliary_state = self.auxiliary_state.take().unwrap(); set.spawn(async move { auxiliary_state.start().await }); @@ -269,10 +267,8 @@ impl GlobalState { } } - log::trace!("Main loop closed. Shutting down auxiliary loop."); + tracing::trace!("Main loop closed. Shutting down auxiliary and log loop."); set.shutdown().await; - - log::trace!("Main loop exited."); } async fn next_event(&mut self) -> Event { @@ -331,7 +327,9 @@ impl GlobalState { LspMessage::Request(request, tx) => { match request { LspRequest::Initialize(params) => { - respond(tx, handlers_state::initialize(params, &mut self.lsp_state, &mut self.world, &self.auxiliary_event_tx), LspResponse::Initialize)?; + // Unwrap: `Initialize` method should only be called once. + let log_tx = self.log_tx.take().unwrap(); + respond(tx, handlers_state::initialize(params, &mut self.lsp_state, &mut self.world, log_tx), LspResponse::Initialize)?; }, LspRequest::Shutdown => { out = LoopControl::Shutdown; @@ -461,7 +459,6 @@ impl AuxiliaryState { async fn start(mut self) -> ! { loop { match self.next_event().await { - AuxiliaryEvent::Log(level, message) => self.log(level, message).await, AuxiliaryEvent::SpawnedTask(handle) => self.tasks.push(Box::pin(handle)), AuxiliaryEvent::PublishDiagnostics(uri, diagnostics, version) => { self.client @@ -482,15 +479,11 @@ impl AuxiliaryState { Ok(Ok(Some(event))) => return event, // Otherwise relay any errors and loop back into select - Err(err) => self.log(MessageType::ERROR, format!("A task panicked:\n{err:?}")).await, - Ok(Err(err)) => self.log(MessageType::ERROR, format!("A task failed:\n{err:?}")).await, + Err(err) => tracing::error!("A task panicked:\n{err:?}"), + Ok(Err(err)) => tracing::error!("A task failed:\n{err:?}"), _ => (), }, } } } - - async fn log(&self, level: MessageType, message: String) { - self.client.log_message(level, message).await - } } diff --git a/crates/lsp/src/tower_lsp.rs b/crates/lsp/src/tower_lsp.rs index cc45da3c..f5f91af2 100644 --- a/crates/lsp/src/tower_lsp.rs +++ b/crates/lsp/src/tower_lsp.rs @@ -17,7 +17,6 @@ use tower_lsp::LspService; use tower_lsp::{jsonrpc, ClientSocket}; use crate::handlers_ext::ViewFileParams; -use crate::main_loop::AuxiliaryEventSender; use crate::main_loop::Event; use crate::main_loop::GlobalState; use crate::main_loop::TokioUnboundedSender; @@ -78,10 +77,6 @@ struct Backend { /// Channel for communication with the main loop. events_tx: TokioUnboundedSender, - /// Channel for communication with the auxiliary loop. - /// Used for latency sensitive logging. - auxiliary_event_tx: AuxiliaryEventSender, - /// Handle to main loop. Drop it to cancel the loop, all associated tasks, /// and drop all owned state. _main_loop: tokio::task::JoinSet<()>, @@ -184,27 +179,20 @@ where I: AsyncRead + Unpin, O: AsyncWrite, { - log::trace!("Starting LSP"); - let (service, socket) = new_lsp(); let server = tower_lsp::Server::new(read, write, socket); server.serve(service).await; - - log::trace!("LSP exiting gracefully."); } fn new_lsp() -> (LspService, ClientSocket) { let init = |client: Client| { - let state = GlobalState::new(client); - let events_tx = state.events_tx(); - let auxiliary_event_tx = state.auxiliary_event_tx(); + let (state, events_tx) = GlobalState::new(client); // Start main loop and hold onto the handle that keeps it alive let main_loop = state.start(); Backend { events_tx, - auxiliary_event_tx, _main_loop: main_loop, } }; From 05a4df31a4a7046dd1e37017dbf9f3caa9efc06b Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Wed, 11 Dec 2024 12:10:32 -0500 Subject: [PATCH 03/15] Tweak existing log usage --- crates/lsp/src/handlers_state.rs | 2 -- crates/lsp/src/main_loop.rs | 4 ++-- crates/lsp/src/tower_lsp.rs | 6 +++--- 3 files changed, 5 insertions(+), 7 deletions(-) diff --git a/crates/lsp/src/handlers_state.rs b/crates/lsp/src/handlers_state.rs index fe8c0d0b..a84da7eb 100644 --- a/crates/lsp/src/handlers_state.rs +++ b/crates/lsp/src/handlers_state.rs @@ -186,8 +186,6 @@ pub(crate) fn did_close( .remove(&uri) .ok_or(anyhow!("Failed to remove document for URI: {uri}"))?; - log::info!("did_close(): closed document with URI: '{uri}'."); - Ok(()) } diff --git a/crates/lsp/src/main_loop.rs b/crates/lsp/src/main_loop.rs index bfb666c1..ddc998d9 100644 --- a/crates/lsp/src/main_loop.rs +++ b/crates/lsp/src/main_loop.rs @@ -261,7 +261,7 @@ impl GlobalState { loop { let event = self.next_event().await; match self.handle_event(event).await { - Err(err) => tracing::info!("Failure while handling event:\n{err:?}"), + Err(err) => tracing::error!("Failure while handling event:\n{err:?}"), Ok(LoopControl::Shutdown) => break, _ => {} } @@ -354,7 +354,7 @@ impl GlobalState { // TODO Make this threshold configurable by the client if loop_tick.elapsed() > std::time::Duration::from_millis(50) { - tracing::info!("Handler took {}ms", loop_tick.elapsed().as_millis()); + tracing::trace!("Handler took {}ms", loop_tick.elapsed().as_millis()); } Ok(out) diff --git a/crates/lsp/src/tower_lsp.rs b/crates/lsp/src/tower_lsp.rs index f5f91af2..d85427ae 100644 --- a/crates/lsp/src/tower_lsp.rs +++ b/crates/lsp/src/tower_lsp.rs @@ -84,7 +84,7 @@ struct Backend { impl Backend { async fn request(&self, request: LspRequest) -> anyhow::Result { - tracing::info!("Incoming:\n{request:#?}"); + tracing::trace!("Incoming:\n{request:#?}"); let (response_tx, mut response_rx) = tokio_unbounded_channel::>(); @@ -97,12 +97,12 @@ impl Backend { // Wait for response from main loop let out = response_rx.recv().await.unwrap()?; - tracing::info!("Outgoing\n{out:#?}"); + tracing::trace!("Outgoing\n{out:#?}"); Ok(out) } fn notify(&self, notif: LspNotification) { - tracing::info!("Incoming:\n{notif:#?}"); + tracing::trace!("Incoming:\n{notif:#?}"); // Relay notification to main loop self.events_tx From 61881fc362101616621e578261a210d53b918926 Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Wed, 11 Dec 2024 12:41:44 -0500 Subject: [PATCH 04/15] Avoid logging during tests --- crates/lsp/src/handlers_state.rs | 12 +---------- crates/lsp/src/logging.rs | 33 +++++++++++++++++++++++++------ crates/lsp_test/src/lsp_client.rs | 14 +++++++++++++ 3 files changed, 42 insertions(+), 17 deletions(-) diff --git a/crates/lsp/src/handlers_state.rs b/crates/lsp/src/handlers_state.rs index a84da7eb..b772febe 100644 --- a/crates/lsp/src/handlers_state.rs +++ b/crates/lsp/src/handlers_state.rs @@ -65,21 +65,11 @@ pub(crate) fn initialize( state: &mut WorldState, log_tx: LogMessageSender, ) -> anyhow::Result { - let client_info = params.client_info.as_ref(); - // TODO: Get default log level from `params.initialization_options` // and `AIR_LOG` env var. let log_level = logging::LogLevel::Trace; - let log_tx = if client_info.is_some_and(|client_info| { - client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code") - }) { - Some(log_tx) - } else { - None - }; - - logging::init_logging(log_tx, log_level); + logging::init_logging(log_tx, log_level, params.client_info.as_ref()); // Defaults to UTF-16 let mut position_encoding = None; diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index 939a21b7..197569b6 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -22,6 +22,7 @@ use core::str; use serde::Deserialize; use std::io::{Error as IoError, ErrorKind, Write}; use tokio::sync::mpsc::unbounded_channel; +use tower_lsp::lsp_types::ClientInfo; use tower_lsp::lsp_types::MessageType; use tower_lsp::Client; use tracing::level_filters::LevelFilter; @@ -126,10 +127,17 @@ impl<'a> MakeWriter<'a> for LogWriterMaker { } } -pub(crate) fn init_logging(log_tx: Option, log_level: LogLevel) { - let writer = match log_tx { - Some(log_tx) => BoxMakeWriter::new(LogWriterMaker::new(log_tx)), - None => BoxMakeWriter::new(std::io::stderr), +pub(crate) fn init_logging( + log_tx: LogMessageSender, + log_level: LogLevel, + client_info: Option<&ClientInfo>, +) { + let writer = if client_info.is_some_and(|client_info| { + client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code") + }) { + BoxMakeWriter::new(LogWriterMaker::new(log_tx)) + } else { + BoxMakeWriter::new(std::io::stderr) }; let layer = tracing_subscriber::fmt::layer() @@ -154,8 +162,21 @@ pub(crate) fn init_logging(log_tx: Option, log_level: LogLevel let subscriber = tracing_subscriber::Registry::default().with(layer); - tracing::subscriber::set_global_default(subscriber) - .expect("Should be able to set global default subscriber"); + if !is_test_client(client_info) { + tracing::subscriber::set_global_default(subscriber) + .expect("Should be able to set the global subscriber."); + } +} + +/// We never log during tests as tests run in parallel within a single process, +/// but you can only have 1 global subscriber per process. +/// +/// If you are debugging a single test, you can override this to emit messages to stderr. +/// +/// Note that if you override this and run multiple tests in parallel, then the call +/// to `set_global_default()` will error causing a panic. +fn is_test_client(client_info: Option<&ClientInfo>) -> bool { + client_info.map_or(false, |client_info| client_info.name == "AirTestClient") } #[derive(Clone, Copy, Debug, Deserialize, Default, PartialEq, Eq, PartialOrd, Ord)] diff --git a/crates/lsp_test/src/lsp_client.rs b/crates/lsp_test/src/lsp_client.rs index c19047d6..4d086590 100644 --- a/crates/lsp_test/src/lsp_client.rs +++ b/crates/lsp_test/src/lsp_client.rs @@ -11,6 +11,7 @@ use std::future::Future; use tokio::io::{AsyncRead, AsyncWrite}; use tokio::io::{ReadHalf, SimplexStream, WriteHalf}; use tokio_util::codec::{FramedRead, FramedWrite}; +use tower_lsp::lsp_types::ClientInfo; use tower_lsp::{jsonrpc, lsp_types}; use crate::tower_lsp::codec::LanguageServerCodec; @@ -87,9 +88,22 @@ impl TestClient { pub async fn initialize(&mut self) -> i64 { let params: Option = std::mem::take(&mut self.init_params); let params = params.unwrap_or_default(); + let params = Self::with_client_info(params); self.request::(params).await } + // Regardless of how we got the params, ensure the client name is set to + // `AirTestClient` so we can recognize it when we set up global logging. + fn with_client_info( + mut init_params: lsp_types::InitializeParams, + ) -> lsp_types::InitializeParams { + init_params.client_info = Some(ClientInfo { + name: String::from("AirTestClient"), + version: None, + }); + init_params + } + pub fn with_initialize_params(&mut self, init_params: lsp_types::InitializeParams) { self.init_params = Some(init_params); } From 59db48d8b1e69b49d4088a5a64b8b4f8912a209c Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Wed, 11 Dec 2024 12:56:38 -0500 Subject: [PATCH 05/15] Fully switch to tracing over log Right now we don't even have the "compatibility" log layer turned on --- Cargo.lock | 1 - Cargo.toml | 1 - crates/lsp/Cargo.toml | 1 - crates/lsp/src/config.rs | 2 +- crates/lsp/src/encoding.rs | 4 ++-- crates/lsp/src/main_loop.rs | 2 +- 6 files changed, 4 insertions(+), 7 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 3679a2b8..d4dab04f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1293,7 +1293,6 @@ dependencies = [ "insta", "itertools", "line_ending", - "log", "lsp_test", "memchr", "serde", diff --git a/Cargo.toml b/Cargo.toml index f2cb06c3..d0e044ed 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -55,7 +55,6 @@ ignore = "0.4.23" insta = "1.40.0" itertools = "0.13.0" line-index = "0.1.2" -log = "0.4.22" memchr = "2.7.4" path-absolutize = "3.1.1" proc-macro2 = "1.0.86" diff --git a/crates/lsp/Cargo.toml b/crates/lsp/Cargo.toml index 863cfa72..f1e0f792 100644 --- a/crates/lsp/Cargo.toml +++ b/crates/lsp/Cargo.toml @@ -25,7 +25,6 @@ dissimilar.workspace = true futures.workspace = true itertools.workspace = true line_ending.workspace = true -log.workspace = true memchr.workspace = true serde.workspace = true serde_json.workspace = true diff --git a/crates/lsp/src/config.rs b/crates/lsp/src/config.rs index b0633475..3c2fa069 100644 --- a/crates/lsp/src/config.rs +++ b/crates/lsp/src/config.rs @@ -95,7 +95,7 @@ impl From for DocumentConfig { if var == "tabSize" { x.tab_size } else { - log::warn!("Unknown indent alias {var}, using default"); + tracing::warn!("Unknown indent alias {var}, using default"); 2 } } diff --git a/crates/lsp/src/encoding.rs b/crates/lsp/src/encoding.rs index 488b55cd..be8062a6 100644 --- a/crates/lsp/src/encoding.rs +++ b/crates/lsp/src/encoding.rs @@ -34,7 +34,7 @@ fn convert_character_from_utf16_to_utf8(x: &str, character: usize) -> usize { } } - log::error!("Failed to locate UTF-16 offset of {character}. Line: '{x}'."); + tracing::error!("Failed to locate UTF-16 offset of {character}. Line: '{x}'."); 0 } @@ -52,7 +52,7 @@ fn convert_character_from_utf8_to_utf16(x: &str, character: usize) -> usize { Some(x) => x.encode_utf16().count(), None => { let n = x.len(); - log::error!( + tracing::error!( "Tried to take UTF-8 character {character}, but only {n} characters exist. Line: '{x}'." ); 0 diff --git a/crates/lsp/src/main_loop.rs b/crates/lsp/src/main_loop.rs index ddc998d9..4f07eb21 100644 --- a/crates/lsp/src/main_loop.rs +++ b/crates/lsp/src/main_loop.rs @@ -100,7 +100,7 @@ impl AuxiliaryEventSender { // Send the join handle to the auxiliary loop so it can log any errors // or panics if let Err(err) = self.send(AuxiliaryEvent::SpawnedTask(handle)) { - log::warn!("Failed to send task to auxiliary loop due to {err}"); + tracing::warn!("Failed to send task to auxiliary loop due to {err}"); } } } From c0755b3ccc8753230485ceecf0050e600236ad7e Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Wed, 11 Dec 2024 12:56:57 -0500 Subject: [PATCH 06/15] Send an initial log message with the level --- crates/lsp/src/logging.rs | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index 197569b6..bf0441ac 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -20,6 +20,7 @@ //! which should appear in the logs for most LSP clients. use core::str; use serde::Deserialize; +use std::fmt::Display; use std::io::{Error as IoError, ErrorKind, Write}; use tokio::sync::mpsc::unbounded_channel; use tower_lsp::lsp_types::ClientInfo; @@ -166,6 +167,8 @@ pub(crate) fn init_logging( tracing::subscriber::set_global_default(subscriber) .expect("Should be able to set the global subscriber."); } + + tracing::info!("Logging initialized with level: {log_level}"); } /// We never log during tests as tests run in parallel within a single process, @@ -202,6 +205,18 @@ impl LogLevel { } } +impl Display for LogLevel { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self { + Self::Error => f.write_str("Error"), + Self::Warn => f.write_str("Warn"), + Self::Info => f.write_str("Info"), + Self::Debug => f.write_str("Debug"), + Self::Trace => f.write_str("Trace"), + } + } +} + /// Filters out logs which have a log level lower than the level set by the client. struct LogLevelFilter { filter: LogLevel, From f6e203e500ebcaf4c67edb15af45a9651444f72d Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Wed, 11 Dec 2024 13:08:59 -0500 Subject: [PATCH 07/15] Check `AIR_LOG` envvar on startup --- crates/lsp/src/handlers_state.rs | 2 +- crates/lsp/src/logging.rs | 26 +++++++++++++++++++++++--- 2 files changed, 24 insertions(+), 4 deletions(-) diff --git a/crates/lsp/src/handlers_state.rs b/crates/lsp/src/handlers_state.rs index b772febe..24bf54b4 100644 --- a/crates/lsp/src/handlers_state.rs +++ b/crates/lsp/src/handlers_state.rs @@ -67,7 +67,7 @@ pub(crate) fn initialize( ) -> anyhow::Result { // TODO: Get default log level from `params.initialization_options` // and `AIR_LOG` env var. - let log_level = logging::LogLevel::Trace; + let log_level = None; logging::init_logging(log_tx, log_level, params.client_info.as_ref()); diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index bf0441ac..ae747eee 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -37,8 +37,8 @@ use tracing_subscriber::{ // TODO: // - Add `air.server.log` as a VS Code extension option that sets the log level, // and pass it through the arbitrary `initializationOptions` field of `InitializeParams`. -// - Add `AIR_LOG` environment variable that sets the log level as well, and prefer this -// over the extension option as its the "harder" thing to set. + +const LOG_ENV_KEY: &str = "AIR_LOG"; pub(crate) struct LogMessage { contents: String, @@ -130,9 +130,11 @@ impl<'a> MakeWriter<'a> for LogWriterMaker { pub(crate) fn init_logging( log_tx: LogMessageSender, - log_level: LogLevel, + log_level: Option, client_info: Option<&ClientInfo>, ) { + let log_level = resolve_log_level(log_level); + let writer = if client_info.is_some_and(|client_info| { client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code") }) { @@ -182,6 +184,24 @@ fn is_test_client(client_info: Option<&ClientInfo>) -> bool { client_info.map_or(false, |client_info| client_info.name == "AirTestClient") } +fn resolve_log_level(log_level: Option) -> LogLevel { + // Check log environment variable, this overrides any Client options + if let Some(log_level) = std::env::var(LOG_ENV_KEY) + .ok() + .and_then(|level| serde_json::from_value(serde_json::Value::String(level)).ok()) + { + return log_level; + } + + // Client specified log level through initialization parameters + if let Some(log_level) = log_level { + return log_level; + } + + // Fallback + LogLevel::default() +} + #[derive(Clone, Copy, Debug, Deserialize, Default, PartialEq, Eq, PartialOrd, Ord)] #[serde(rename_all = "lowercase")] pub(crate) enum LogLevel { From 8d952c7d3cb52298b63b5df89f3be5ebdadfa64f Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Wed, 11 Dec 2024 13:57:27 -0500 Subject: [PATCH 08/15] Tweak expected option name --- crates/lsp/src/logging.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index ae747eee..ba434784 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -6,7 +6,7 @@ //! The logging system for `air lsp`. //! -//! Logs are controlled by the `air.server.log` setting in VS Code, +//! Logs are controlled by the `air.logLevel` setting in VS Code, //! passed through `InitializeParams` in the arbitrary `initializationOptions` field. //! //! Logs are also controlled by the `AIR_LOG` environment variable. This is preferred @@ -35,7 +35,7 @@ use tracing_subscriber::{ }; // TODO: -// - Add `air.server.log` as a VS Code extension option that sets the log level, +// - Add `air.logLevel` as a VS Code extension option that sets the log level, // and pass it through the arbitrary `initializationOptions` field of `InitializeParams`. const LOG_ENV_KEY: &str = "AIR_LOG"; From e2a785803d8bc0edd8d64e1f1f19a5da1541ea2f Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Wed, 11 Dec 2024 14:12:20 -0500 Subject: [PATCH 09/15] Tweak comment --- crates/lsp/src/handlers_state.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/crates/lsp/src/handlers_state.rs b/crates/lsp/src/handlers_state.rs index 24bf54b4..22bc0755 100644 --- a/crates/lsp/src/handlers_state.rs +++ b/crates/lsp/src/handlers_state.rs @@ -65,8 +65,7 @@ pub(crate) fn initialize( state: &mut WorldState, log_tx: LogMessageSender, ) -> anyhow::Result { - // TODO: Get default log level from `params.initialization_options` - // and `AIR_LOG` env var. + // TODO: Get user specified log level from `params.initialization_options` let log_level = None; logging::init_logging(log_tx, log_level, params.client_info.as_ref()); From 05c3dc3052252b39ac8558b2f0788b971b6f330c Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Thu, 12 Dec 2024 13:08:00 -0500 Subject: [PATCH 10/15] Do log during testing, but "captured" by default - `just test` is silent - `just test-verbose` is noisy and sequential - CI is noisy and sequential and `trace` level --- .github/workflows/test-linux.yml | 6 +++++- .github/workflows/test-mac.yml | 6 +++++- .github/workflows/test-windows.yml | 6 +++++- crates/lsp/src/logging.rs | 27 +++++++++++++++++++-------- justfile | 13 +++++++++---- 5 files changed, 43 insertions(+), 15 deletions(-) diff --git a/.github/workflows/test-linux.yml b/.github/workflows/test-linux.yml index 8c97b869..9a8e0fcd 100644 --- a/.github/workflows/test-linux.yml +++ b/.github/workflows/test-linux.yml @@ -51,4 +51,8 @@ jobs: run: cargo build - name: Run unit tests - run: cargo test + env: + AIR_LOG: trace + # `--nocapture` to see our own `tracing` logs + # `--test-threads 1` to ensure `tracing` logs aren't interleaved + run: cargo test -- --nocapture --test-threads 1 diff --git a/.github/workflows/test-mac.yml b/.github/workflows/test-mac.yml index 2259a18a..e59db708 100644 --- a/.github/workflows/test-mac.yml +++ b/.github/workflows/test-mac.yml @@ -29,4 +29,8 @@ jobs: run: cargo build - name: Run unit tests - run: cargo test + env: + AIR_LOG: trace + # `--nocapture` to see our own `tracing` logs + # `--test-threads 1` to ensure `tracing` logs aren't interleaved + run: cargo test -- --nocapture --test-threads 1 diff --git a/.github/workflows/test-windows.yml b/.github/workflows/test-windows.yml index 24b16010..a1b2edfb 100644 --- a/.github/workflows/test-windows.yml +++ b/.github/workflows/test-windows.yml @@ -29,4 +29,8 @@ jobs: run: cargo build - name: Run unit tests - run: cargo test + env: + AIR_LOG: trace + # `--nocapture` to see our own `tracing` logs + # `--test-threads 1` to ensure `tracing` logs aren't interleaved + run: cargo test -- --nocapture --test-threads 1 diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index ba434784..2c4bbf6f 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -28,6 +28,7 @@ use tower_lsp::lsp_types::MessageType; use tower_lsp::Client; use tracing::level_filters::LevelFilter; use tracing_subscriber::fmt::time::LocalTime; +use tracing_subscriber::fmt::TestWriter; use tracing_subscriber::{ fmt::{writer::BoxMakeWriter, MakeWriter}, layer::SubscriberExt, @@ -138,8 +139,13 @@ pub(crate) fn init_logging( let writer = if client_info.is_some_and(|client_info| { client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code") }) { + // These IDEs are known to support `window/logMessage` well BoxMakeWriter::new(LogWriterMaker::new(log_tx)) + } else if is_test_client(client_info) { + // Ensures a standard `cargo test` captures output unless `-- --nocapture` is used + BoxMakeWriter::new(TestWriter::default()) } else { + // Fallback for other editors / IDEs BoxMakeWriter::new(std::io::stderr) }; @@ -165,21 +171,26 @@ pub(crate) fn init_logging( let subscriber = tracing_subscriber::Registry::default().with(layer); - if !is_test_client(client_info) { + if is_test_client(client_info) { + // During parallel testing, `set_global_default()` gets called multiple times + // per process. That causes it to error, but we ignore this. + tracing::subscriber::set_global_default(subscriber).ok(); + } else { tracing::subscriber::set_global_default(subscriber) - .expect("Should be able to set the global subscriber."); + .expect("Should be able to set the global subscriber exactly once."); } tracing::info!("Logging initialized with level: {log_level}"); } -/// We never log during tests as tests run in parallel within a single process, -/// but you can only have 1 global subscriber per process. +/// We use a special `TestWriter` during tests to be compatible with `cargo test`'s +/// typical output capturing behavior. /// -/// If you are debugging a single test, you can override this to emit messages to stderr. +/// Important notes: +/// - `cargo test` swallows all logs unless you use `-- --nocapture`. +/// - Tests run in parallel, so logs can be interleaved unless you run `--test-threads 1`. /// -/// Note that if you override this and run multiple tests in parallel, then the call -/// to `set_global_default()` will error causing a panic. +/// We use `cargo test -- --nocapture --test-threads 1` on CI because of all of this. fn is_test_client(client_info: Option<&ClientInfo>) -> bool { client_info.map_or(false, |client_info| client_info.name == "AirTestClient") } @@ -253,7 +264,7 @@ impl tracing_subscriber::layer::Filter for LogLevelFilter { let filter = if meta.target().starts_with("air") || meta.target().starts_with("lsp") { self.filter.tracing_level() } else { - tracing::Level::INFO + tracing::Level::WARN }; meta.level() <= &filter diff --git a/justfile b/justfile index 0ae38573..818c4c0b 100644 --- a/justfile +++ b/justfile @@ -6,13 +6,18 @@ gen-formatter: gen-grammar: cargo run -p xtask_codegen -- grammar r -# Run the parser and formatter tests +# Run the tests test: - cargo test -p air_r_parser - cargo test -p air_r_formatter + cargo test + +# Run the tests in verbose mode +# `--nocapture` to see our own `tracing` logs +# `--test-threads 1` to ensure `tracing` logs aren't interleaved +test-verbose: + cargo test -- --nocapture --test-threads 1 # Run the quick formatter test -quick: +test-quick: cargo test --package air_r_formatter --test quick_test -- quick_test --exact --show-output --ignored # Creates a new crate From a775e7752bf4923b724872ba6216fe07c3f9113f Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Thu, 12 Dec 2024 14:39:06 -0500 Subject: [PATCH 11/15] Add intermediate `Trace*` structs with custom `Debug` implementations --- Cargo.lock | 29 ++++++++++++ Cargo.toml | 1 + crates/lsp/Cargo.toml | 1 + crates/lsp/src/tower_lsp.rs | 88 +++++++++++++++++++++++++++++++++---- 4 files changed, 111 insertions(+), 8 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index d4dab04f..2457a47d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1298,6 +1298,7 @@ dependencies = [ "serde", "serde_json", "struct-field-names-as-array", + "strum", "tests_macros", "time", "tokio", @@ -1685,6 +1686,12 @@ dependencies = [ "untrusted", ] +[[package]] +name = "rustversion" +version = "1.0.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0e819f2bc632f285be6d7cd36e25940d45b2391dd6d9b939e79de557f7014248" + [[package]] name = "ryu" version = "1.0.18" @@ -1911,6 +1918,28 @@ dependencies = [ "syn 2.0.90", ] +[[package]] +name = "strum" +version = "0.26.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8fec0f0aef304996cf250b31b5a10dee7980c85da9d759361292b8bca5a18f06" +dependencies = [ + "strum_macros", +] + +[[package]] +name = "strum_macros" +version = "0.26.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4c6bee85a5a24955dc440386795aa378cd9cf82acd5f764469152d2270e581be" +dependencies = [ + "heck", + "proc-macro2", + "quote", + "rustversion", + "syn 2.0.90", +] + [[package]] name = "subtle" version = "2.6.1" diff --git a/Cargo.toml b/Cargo.toml index d0e044ed..ffce32ec 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -61,6 +61,7 @@ proc-macro2 = "1.0.86" serde = { version = "1.0.215", features = ["derive"] } serde_json = "1.0.132" struct-field-names-as-array = "0.3.0" +strum = "0.26" time = "0.3.37" thiserror = "2.0.5" tokio = { version = "1.41.1" } diff --git a/crates/lsp/Cargo.toml b/crates/lsp/Cargo.toml index f1e0f792..2d630413 100644 --- a/crates/lsp/Cargo.toml +++ b/crates/lsp/Cargo.toml @@ -29,6 +29,7 @@ memchr.workspace = true serde.workspace = true serde_json.workspace = true struct-field-names-as-array.workspace = true +strum = { workspace = true, features = ["derive"] } time = { workspace = true } tokio = { workspace = true, features = ["full"] } tower-lsp.workspace = true diff --git a/crates/lsp/src/tower_lsp.rs b/crates/lsp/src/tower_lsp.rs index d85427ae..47db9ad5 100644 --- a/crates/lsp/src/tower_lsp.rs +++ b/crates/lsp/src/tower_lsp.rs @@ -7,6 +7,8 @@ #![allow(deprecated)] +use strum::IntoStaticStr; + use tokio::io::{AsyncRead, AsyncWrite}; use tokio::sync::mpsc::unbounded_channel as tokio_unbounded_channel; use tower_lsp::jsonrpc::Result; @@ -42,7 +44,7 @@ pub(crate) enum LspMessage { ), } -#[derive(Debug)] +#[derive(Debug, IntoStaticStr)] pub(crate) enum LspNotification { Initialized(InitializedParams), DidChangeWorkspaceFolders(DidChangeWorkspaceFoldersParams), @@ -55,7 +57,7 @@ pub(crate) enum LspNotification { } #[allow(clippy::large_enum_variant)] -#[derive(Debug)] +#[derive(Debug, IntoStaticStr)] pub(crate) enum LspRequest { Initialize(InitializeParams), DocumentFormatting(DocumentFormattingParams), @@ -64,7 +66,7 @@ pub(crate) enum LspRequest { } #[allow(clippy::large_enum_variant)] -#[derive(Debug)] +#[derive(Debug, IntoStaticStr)] pub(crate) enum LspResponse { Initialize(InitializeResult), DocumentFormatting(Option>), @@ -72,6 +74,76 @@ pub(crate) enum LspResponse { AirViewFile(String), } +impl std::fmt::Display for LspNotification { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str(self.into()) + } +} +impl std::fmt::Display for LspRequest { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str(self.into()) + } +} +impl std::fmt::Display for LspResponse { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + f.write_str(self.into()) + } +} + +impl LspNotification { + fn trace(&self) -> TraceLspNotification { + TraceLspNotification { inner: self } + } +} +impl LspRequest { + fn trace(&self) -> TraceLspRequest { + TraceLspRequest { inner: self } + } +} +impl LspResponse { + fn trace(&self) -> TraceLspResponse { + TraceLspResponse { inner: self } + } +} + +struct TraceLspNotification<'a> { + inner: &'a LspNotification, +} +struct TraceLspRequest<'a> { + inner: &'a LspRequest, +} +struct TraceLspResponse<'a> { + inner: &'a LspResponse, +} + +impl std::fmt::Debug for TraceLspNotification<'_> { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self.inner { + LspNotification::DidOpenTextDocument(params) => { + // Ignore the document itself in trace logs + f.debug_tuple(self.inner.into()) + .field(¶ms.text_document.uri) + .field(¶ms.text_document.version) + .field(¶ms.text_document.language_id) + .finish() + } + _ => std::fmt::Debug::fmt(self.inner, f), + } + } +} + +impl std::fmt::Debug for TraceLspRequest<'_> { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + std::fmt::Debug::fmt(self.inner, f) + } +} + +impl std::fmt::Debug for TraceLspResponse<'_> { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + std::fmt::Debug::fmt(self.inner, f) + } +} + #[derive(Debug)] struct Backend { /// Channel for communication with the main loop. @@ -84,7 +156,7 @@ struct Backend { impl Backend { async fn request(&self, request: LspRequest) -> anyhow::Result { - tracing::trace!("Incoming:\n{request:#?}"); + tracing::trace!("Incoming:\n{request:#?}", request = request.trace()); let (response_tx, mut response_rx) = tokio_unbounded_channel::>(); @@ -95,14 +167,14 @@ impl Backend { .unwrap(); // Wait for response from main loop - let out = response_rx.recv().await.unwrap()?; + let response = response_rx.recv().await.unwrap()?; - tracing::trace!("Outgoing\n{out:#?}"); - Ok(out) + tracing::trace!("Outgoing:\n{response:#?}", response = response.trace()); + Ok(response) } fn notify(&self, notif: LspNotification) { - tracing::trace!("Incoming:\n{notif:#?}"); + tracing::trace!("Incoming:\n{notif:#?}", notif = notif.trace()); // Relay notification to main loop self.events_tx From 2e474a4699dc4483648a686bc38c13587f0b7119 Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Thu, 12 Dec 2024 16:36:48 -0500 Subject: [PATCH 12/15] Use `Targets` backed filtering --- .github/workflows/test-linux.yml | 2 +- .github/workflows/test-mac.yml | 2 +- .github/workflows/test-windows.yml | 2 +- crates/lsp/src/handlers_state.rs | 12 ++- crates/lsp/src/logging.rs | 130 +++++++++++++++++-------- crates/lsp_test/src/tower_lsp/codec.rs | 6 +- 6 files changed, 104 insertions(+), 50 deletions(-) diff --git a/.github/workflows/test-linux.yml b/.github/workflows/test-linux.yml index 9a8e0fcd..2e084756 100644 --- a/.github/workflows/test-linux.yml +++ b/.github/workflows/test-linux.yml @@ -52,7 +52,7 @@ jobs: - name: Run unit tests env: - AIR_LOG: trace + AIR_LOG_LEVEL: trace # `--nocapture` to see our own `tracing` logs # `--test-threads 1` to ensure `tracing` logs aren't interleaved run: cargo test -- --nocapture --test-threads 1 diff --git a/.github/workflows/test-mac.yml b/.github/workflows/test-mac.yml index e59db708..dbe44a94 100644 --- a/.github/workflows/test-mac.yml +++ b/.github/workflows/test-mac.yml @@ -30,7 +30,7 @@ jobs: - name: Run unit tests env: - AIR_LOG: trace + AIR_LOG_LEVEL: trace # `--nocapture` to see our own `tracing` logs # `--test-threads 1` to ensure `tracing` logs aren't interleaved run: cargo test -- --nocapture --test-threads 1 diff --git a/.github/workflows/test-windows.yml b/.github/workflows/test-windows.yml index a1b2edfb..fa95a5b2 100644 --- a/.github/workflows/test-windows.yml +++ b/.github/workflows/test-windows.yml @@ -30,7 +30,7 @@ jobs: - name: Run unit tests env: - AIR_LOG: trace + AIR_LOG_LEVEL: trace # `--nocapture` to see our own `tracing` logs # `--test-threads 1` to ensure `tracing` logs aren't interleaved run: cargo test -- --nocapture --test-threads 1 diff --git a/crates/lsp/src/handlers_state.rs b/crates/lsp/src/handlers_state.rs index 22bc0755..211eb1b2 100644 --- a/crates/lsp/src/handlers_state.rs +++ b/crates/lsp/src/handlers_state.rs @@ -65,10 +65,16 @@ pub(crate) fn initialize( state: &mut WorldState, log_tx: LogMessageSender, ) -> anyhow::Result { - // TODO: Get user specified log level from `params.initialization_options` + // TODO: Get user specified options from `params.initialization_options` let log_level = None; - - logging::init_logging(log_tx, log_level, params.client_info.as_ref()); + let dependency_log_levels = None; + + logging::init_logging( + log_tx, + log_level, + dependency_log_levels, + params.client_info.as_ref(), + ); // Defaults to UTF-16 let mut position_encoding = None; diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index 2c4bbf6f..6a6c491e 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -6,14 +6,37 @@ //! The logging system for `air lsp`. //! -//! Logs are controlled by the `air.logLevel` setting in VS Code, -//! passed through `InitializeParams` in the arbitrary `initializationOptions` field. +//! ## Air crate logs //! -//! Logs are also controlled by the `AIR_LOG` environment variable. This is preferred -//! over the extension setting, but it is unlikely to see them both be used together. -//! This can be used by other LSP clients if there is no easy way to set `initializationOptions`. +//! For air crates, a single log level is supplied as one of: error, warn, info, debug, +//! or trace, which is applied to all air crates that log. //! -//! By default, we fallback to `"info"`. +//! Resolution strategy: +//! +//! - The environment variable `AIR_LOG_LEVEL` is consulted. +//! +//! - The LSP `InitializeParams.initializationOptions.logLevel` option is consulted. This +//! can be set in VS Code / Positron using `air.logLevel`, or in Zed by supplying +//! `initialization_options`. +//! +//! - If neither are supplied, we fallback to `"info"`. +//! +//! ## Dependency crate logs +//! +//! For dependency crates, either a single log level can be supplied, or comma separated +//! `target=level` pairs can be supplied, like `tower_lsp=debug,tokio=info`. +//! +//! Resolution strategy: +//! +//! - The environment variable `AIR_DEPENDENCY_LOG_LEVELS` is consulted. +//! +//! - The LSP `InitializeParams.initializationOptions.dependencyLogLevels` option is +//! consulted. This can be set in VS Code / Positron using `air.dependencyLogLevel`, or +//! in Zed by supplying `initialization_options`. +//! +//! - If neither are supplied, we fallback to no logging for dependency crates. +//! +//! ## IDE support //! //! For VS Code and Zed, which are known to support `window/logMessage` well, logging will //! emit a `window/logMessage` message. Otherwise, logging will write to `stderr`, @@ -22,11 +45,12 @@ use core::str; use serde::Deserialize; use std::fmt::Display; use std::io::{Error as IoError, ErrorKind, Write}; +use std::str::FromStr; use tokio::sync::mpsc::unbounded_channel; use tower_lsp::lsp_types::ClientInfo; use tower_lsp::lsp_types::MessageType; use tower_lsp::Client; -use tracing::level_filters::LevelFilter; +use tracing_subscriber::filter; use tracing_subscriber::fmt::time::LocalTime; use tracing_subscriber::fmt::TestWriter; use tracing_subscriber::{ @@ -36,10 +60,12 @@ use tracing_subscriber::{ }; // TODO: -// - Add `air.logLevel` as a VS Code extension option that sets the log level, -// and pass it through the arbitrary `initializationOptions` field of `InitializeParams`. +// - Add `air.logLevel` and `air.dependencyLogLevels` as VS Code extension options that set +// the log levels, and pass them through the arbitrary `initializationOptions` field of +// `InitializeParams`. -const LOG_ENV_KEY: &str = "AIR_LOG"; +const AIR_LOG_LEVEL: &str = "AIR_LOG_LEVEL"; +const AIR_DEPENDENCY_LOG_LEVELS: &str = "AIR_DEPENDENCY_LOG_LEVELS"; pub(crate) struct LogMessage { contents: String, @@ -132,9 +158,11 @@ impl<'a> MakeWriter<'a> for LogWriterMaker { pub(crate) fn init_logging( log_tx: LogMessageSender, log_level: Option, + dependency_log_levels: Option, client_info: Option<&ClientInfo>, ) { let log_level = resolve_log_level(log_level); + let dependency_log_levels = resolve_dependency_log_levels(dependency_log_levels); let writer = if client_info.is_some_and(|client_info| { client_info.name.starts_with("Zed") || client_info.name.starts_with("Visual Studio Code") @@ -167,7 +195,7 @@ pub(crate) fn init_logging( // Display the log level .with_level(true) .with_writer(writer) - .with_filter(LogLevelFilter { filter: log_level }); + .with_filter(log_filter(log_level, dependency_log_levels)); let subscriber = tracing_subscriber::Registry::default().with(layer); @@ -195,9 +223,41 @@ fn is_test_client(client_info: Option<&ClientInfo>) -> bool { client_info.map_or(false, |client_info| client_info.name == "AirTestClient") } +// TODO: Is there a way to generate this at compile time? +const TARGETS: &[&str] = &[ + "air_r_factory", + "air_r_formatter", + "air_r_parser", + "air_r_syntax", + "fs", + "line_ending", + "lsp", +]; + +fn log_filter(log_level: LogLevel, dependency_log_levels: Option) -> filter::Targets { + // Initialize `filter` from dependency log levels. + // If nothing is supplied, dependency logs are completely off. + let mut filter = match dependency_log_levels { + Some(dependency_log_levels) => match filter::Targets::from_str(&dependency_log_levels) { + Ok(level) => level, + Err(_) => filter::Targets::new(), + }, + None => filter::Targets::new(), + }; + + let log_level = log_level.tracing_level(); + + // Apply the air log level to each air crate that logs + for target in TARGETS { + filter = filter.with_target(*target, log_level); + } + + filter +} + fn resolve_log_level(log_level: Option) -> LogLevel { // Check log environment variable, this overrides any Client options - if let Some(log_level) = std::env::var(LOG_ENV_KEY) + if let Some(log_level) = std::env::var(AIR_LOG_LEVEL) .ok() .and_then(|level| serde_json::from_value(serde_json::Value::String(level)).ok()) { @@ -209,8 +269,23 @@ fn resolve_log_level(log_level: Option) -> LogLevel { return log_level; } - // Fallback - LogLevel::default() + // Default to info logs for air crates + LogLevel::Info +} + +fn resolve_dependency_log_levels(dependency_log_levels: Option) -> Option { + // Check dependency log environment variable, this overrides any Client options + if let Ok(dependency_log_levels) = std::env::var(AIR_DEPENDENCY_LOG_LEVELS) { + return Some(dependency_log_levels); + } + + // Client specified log level through initialization parameters + if dependency_log_levels.is_some() { + return dependency_log_levels; + } + + // Default to no logs for dependency crates + None } #[derive(Clone, Copy, Debug, Deserialize, Default, PartialEq, Eq, PartialOrd, Ord)] @@ -247,30 +322,3 @@ impl Display for LogLevel { } } } - -/// Filters out logs which have a log level lower than the level set by the client. -struct LogLevelFilter { - filter: LogLevel, -} - -impl tracing_subscriber::layer::Filter for LogLevelFilter { - fn enabled( - &self, - meta: &tracing::Metadata<'_>, - _: &tracing_subscriber::layer::Context<'_, S>, - ) -> bool { - // This is a potential reason to use `air_` as the crate prefix, - // it would make it easy to set the `tracing_level()` for only air related crates - let filter = if meta.target().starts_with("air") || meta.target().starts_with("lsp") { - self.filter.tracing_level() - } else { - tracing::Level::WARN - }; - - meta.level() <= &filter - } - - fn max_level_hint(&self) -> Option { - Some(LevelFilter::from_level(self.filter.tracing_level())) - } -} diff --git a/crates/lsp_test/src/tower_lsp/codec.rs b/crates/lsp_test/src/tower_lsp/codec.rs index 5c1068c2..38f2af83 100644 --- a/crates/lsp_test/src/tower_lsp/codec.rs +++ b/crates/lsp_test/src/tower_lsp/codec.rs @@ -17,7 +17,7 @@ use bytes::buf::BufMut; use bytes::{Buf, BytesMut}; use memchr::memmem; use serde::{de::DeserializeOwned, Serialize}; -use tracing::{trace, warn}; +use tracing::warn; use tokio_util::codec::{Decoder, Encoder}; @@ -120,7 +120,7 @@ impl Encoder for LanguageServerCodec { fn encode(&mut self, item: T, dst: &mut BytesMut) -> Result<(), Self::Error> { let msg = serde_json::to_string(&item)?; - trace!("-> {}", msg); + // trace!("-> {}", msg); // Reserve just enough space to hold the `Content-Length: ` and `\r\n\r\n` constants, // the length of the message, and the message body. @@ -160,7 +160,7 @@ impl Decoder for LanguageServerCodec { let result = if message.is_empty() { Ok(None) } else { - trace!("<- {}", message); + // trace!("<- {}", message); match serde_json::from_str(message) { Ok(parsed) => Ok(Some(parsed)), Err(err) => Err(err.into()), From 6e1cdc4241ce59682ad595b383342a61ec12c3da Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Fri, 13 Dec 2024 12:52:02 -0500 Subject: [PATCH 13/15] Always write the request/notify name at `info!()` level --- crates/lsp/src/tower_lsp.rs | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/crates/lsp/src/tower_lsp.rs b/crates/lsp/src/tower_lsp.rs index 47db9ad5..5e824475 100644 --- a/crates/lsp/src/tower_lsp.rs +++ b/crates/lsp/src/tower_lsp.rs @@ -156,7 +156,8 @@ struct Backend { impl Backend { async fn request(&self, request: LspRequest) -> anyhow::Result { - tracing::trace!("Incoming:\n{request:#?}", request = request.trace()); + tracing::info!("Incoming: {request}"); + tracing::trace!("Incoming (debug):\n{request:#?}", request = request.trace()); let (response_tx, mut response_rx) = tokio_unbounded_channel::>(); @@ -169,12 +170,17 @@ impl Backend { // Wait for response from main loop let response = response_rx.recv().await.unwrap()?; - tracing::trace!("Outgoing:\n{response:#?}", response = response.trace()); + tracing::info!("Outgoing: {response}"); + tracing::trace!( + "Outgoing (debug):\n{response:#?}", + response = response.trace() + ); Ok(response) } fn notify(&self, notif: LspNotification) { - tracing::trace!("Incoming:\n{notif:#?}", notif = notif.trace()); + tracing::info!("Incoming: {notif}"); + tracing::trace!("Incoming (debug):\n{notif:#?}", notif = notif.trace()); // Relay notification to main loop self.events_tx From 1ddd672cd9921b505df1bfed06c962aee3a87735 Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Fri, 13 Dec 2024 12:52:17 -0500 Subject: [PATCH 14/15] Use `pretty()` after all because it is useful with spans --- crates/lsp/src/logging.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index 6a6c491e..de8412d5 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -178,6 +178,9 @@ pub(crate) fn init_logging( }; let layer = tracing_subscriber::fmt::layer() + // Spend the effort cleaning up the logs before writing them. + // Particularly useful for instrumented logs with spans. + .pretty() // Disable ANSI escapes, those are not supported in Code .with_ansi(false) // Display source code file paths From 3f0f72058866a26f6316dd2ad26939fea769ee8e Mon Sep 17 00:00:00 2001 From: Davis Vaughan Date: Fri, 13 Dec 2024 13:47:38 -0500 Subject: [PATCH 15/15] Write out `AIR_CRATE_NAMES` at build time --- Cargo.lock | 42 +++++++++++++++++++++++++++++++++++++++ Cargo.toml | 1 + crates/lsp/Cargo.toml | 9 ++++++--- crates/lsp/build.rs | 34 +++++++++++++++++++++++++++++++ crates/lsp/src/crates.rs | 3 +++ crates/lsp/src/lib.rs | 1 + crates/lsp/src/logging.rs | 15 +++----------- 7 files changed, 90 insertions(+), 15 deletions(-) create mode 100644 crates/lsp/build.rs create mode 100644 crates/lsp/src/crates.rs diff --git a/Cargo.lock b/Cargo.lock index 2457a47d..226e1976 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -498,6 +498,38 @@ version = "1.8.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9ac0150caa2ae65ca5bd83f25c7de183dea78d4d366469f148435e2acfbad0da" +[[package]] +name = "camino" +version = "1.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8b96ec4966b5813e2c0507c1f86115c8c5abaadc3980879c3424042a02fd1ad3" +dependencies = [ + "serde", +] + +[[package]] +name = "cargo-platform" +version = "0.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e35af189006b9c0f00a064685c727031e3ed2d8020f7ba284d78cc2671bd36ea" +dependencies = [ + "serde", +] + +[[package]] +name = "cargo_metadata" +version = "0.19.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8769706aad5d996120af43197bf46ef6ad0fda35216b4505f926a365a232d924" +dependencies = [ + "camino", + "cargo-platform", + "semver", + "serde", + "serde_json", + "thiserror 2.0.5", +] + [[package]] name = "case" version = "1.0.0" @@ -1285,6 +1317,7 @@ dependencies = [ "biome_parser", "biome_text_size", "bytes", + "cargo_metadata", "crossbeam", "dissimilar", "futures", @@ -1739,6 +1772,15 @@ version = "1.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "94143f37725109f92c262ed2cf5e59bce7498c01bcc1502d7b9afe439a4e9f49" +[[package]] +name = "semver" +version = "1.0.24" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3cb6eb87a131f756572d7fb904f6e7b68633f09cca868c5df1c4b8d1a694bbba" +dependencies = [ + "serde", +] + [[package]] name = "serde" version = "1.0.215" diff --git a/Cargo.toml b/Cargo.toml index ffce32ec..b6b56566 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -45,6 +45,7 @@ biome_string_case = { git = "https://github.com/biomejs/biome", rev = "2648fa420 biome_text_size = { git = "https://github.com/biomejs/biome", rev = "2648fa4201be4afd26f44eca1a4e77aac0a67272" } biome_unicode_table = { git = "https://github.com/biomejs/biome", rev = "2648fa4201be4afd26f44eca1a4e77aac0a67272" } bytes = "1.8.0" +cargo_metadata = "0.19.1" clap = { version = "4.5.20", features = ["derive"] } crossbeam = "0.8.4" dissimilar = "1.0.9" diff --git a/crates/lsp/Cargo.toml b/crates/lsp/Cargo.toml index 2d630413..5bf1e568 100644 --- a/crates/lsp/Cargo.toml +++ b/crates/lsp/Cargo.toml @@ -41,9 +41,6 @@ triomphe.workspace = true url.workspace = true uuid = { workspace = true, features = ["v4"] } -[lints] -workspace = true - [dev-dependencies] assert_matches.workspace = true bytes.workspace = true @@ -54,3 +51,9 @@ lsp_test.workspace = true memchr.workspace = true tests_macros.workspace = true tokio-util.workspace = true + +[build-dependencies] +cargo_metadata.workspace = true + +[lints] +workspace = true diff --git a/crates/lsp/build.rs b/crates/lsp/build.rs new file mode 100644 index 00000000..17cde13a --- /dev/null +++ b/crates/lsp/build.rs @@ -0,0 +1,34 @@ +use std::env; +use std::fs; +use std::path::Path; + +extern crate cargo_metadata; + +fn main() { + write_workspace_crate_names(); +} + +/// Write out a constant array of air crate names as `AIR_CRATE_NAMES` at build time +fn write_workspace_crate_names() { + let dir = env::var_os("OUT_DIR").unwrap(); + let path = Path::new(&dir).join("crates.rs"); + + // Equivalent to `cargo metadata --no-deps` + let mut cmd = cargo_metadata::MetadataCommand::new(); + cmd.no_deps(); + let metadata = cmd.exec().unwrap(); + + let packages: Vec = metadata + .workspace_packages() + .iter() + .map(|package| package.name.clone()) + .map(|package| String::from("\"") + package.as_str() + "\",") + .collect(); + + let packages = packages.join(" "); + + let contents = format!("pub(crate) const AIR_CRATE_NAMES: &[&str] = &[{packages}];"); + + fs::write(&path, contents).unwrap(); + println!("cargo::rerun-if-changed=build.rs"); +} diff --git a/crates/lsp/src/crates.rs b/crates/lsp/src/crates.rs new file mode 100644 index 00000000..e79951a1 --- /dev/null +++ b/crates/lsp/src/crates.rs @@ -0,0 +1,3 @@ +// Generates `AIR_CRATE_NAMES`, a const array of the crate names in the air workspace, +// see `lsp/src/build.rs` +include!(concat!(env!("OUT_DIR"), "/crates.rs")); diff --git a/crates/lsp/src/lib.rs b/crates/lsp/src/lib.rs index b8a362db..30c20aac 100644 --- a/crates/lsp/src/lib.rs +++ b/crates/lsp/src/lib.rs @@ -4,6 +4,7 @@ pub use tower_lsp::start_lsp; pub mod config; +pub mod crates; pub mod documents; pub mod encoding; pub mod from_proto; diff --git a/crates/lsp/src/logging.rs b/crates/lsp/src/logging.rs index de8412d5..78db0373 100644 --- a/crates/lsp/src/logging.rs +++ b/crates/lsp/src/logging.rs @@ -59,6 +59,8 @@ use tracing_subscriber::{ Layer, }; +use crate::crates; + // TODO: // - Add `air.logLevel` and `air.dependencyLogLevels` as VS Code extension options that set // the log levels, and pass them through the arbitrary `initializationOptions` field of @@ -226,17 +228,6 @@ fn is_test_client(client_info: Option<&ClientInfo>) -> bool { client_info.map_or(false, |client_info| client_info.name == "AirTestClient") } -// TODO: Is there a way to generate this at compile time? -const TARGETS: &[&str] = &[ - "air_r_factory", - "air_r_formatter", - "air_r_parser", - "air_r_syntax", - "fs", - "line_ending", - "lsp", -]; - fn log_filter(log_level: LogLevel, dependency_log_levels: Option) -> filter::Targets { // Initialize `filter` from dependency log levels. // If nothing is supplied, dependency logs are completely off. @@ -251,7 +242,7 @@ fn log_filter(log_level: LogLevel, dependency_log_levels: Option) -> fil let log_level = log_level.tracing_level(); // Apply the air log level to each air crate that logs - for target in TARGETS { + for target in crates::AIR_CRATE_NAMES { filter = filter.with_target(*target, log_level); }